出现log.info报红的解决方案

网友投稿 1673 2022-09-26

出现log.info报红的解决方案

出现log.info报红的解决方案

目录出现log.info报红1.装lombok插件2.导包3.配置log4j.properties4.报错的解决方案项目问题:log.info()导致CPU飙升首先使用top命令查看进程运行情况结论

出现log.info报红

1.装lombok插件

File——>Settings——>plugins——>search plugins   搜索lombok    安装,重启Intellij

2.导包

无论使用Maven还是从本地导包,切记,要导入lombok与slf4j-log4j两个包。前者依赖后者。

Maven导包如图所示:

3.配置log4j.properties

本文意在说明log.info报红的原因,所以这里不做叙述,您可以另行查找。

4jsCRNwo.报错的解决方案

程序包org.slf4j不存在:此错误可能是未导入slf4j-log4j包导致。lombok.javac.apt.LombokProcessor could not be initialized:出现此错误请升级  lombok  jar包版本其他错误:请到Setting——>Build、Execution、Deployment——>Compiler——>Annotation Processors勾选Enable annotation processing。

项目问题:log.info()导致CPU飙升

项目问题:log.info()导致CPU飙升

最近公司有个需求是对接E签宝的,也就是CA认证,大致的情况就是我们拿着文件去E签宝做CA认定,简单的理解就是拿着合同去E签宝盖章。

因为是对接三方的吗,所以在调E签宝服务的时候我就用log.info()把请求参数给打印了出来,方便看组装的参加,排查问题,参数中就包含我们的合同文件流,所以整个参数是一个大对象。在做压测的时候发现CPU很快就飙升到100%,并且耗时很久。但是我把打印日志的log.info()去掉之后,CPU和耗时马上就降下来了。下面开始排查这个问题:

首先使用top命令查看进程运行情况

# top

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

7020 root 20 0 2538892 164144 11856 S 90.3 8.7 61:23.54 java

11022 root 20 0 2560528 241340 11920 S 0.3 12.8 311:23.23 java

26805 root 20 0 32612 4036 2472 S 0.3 0.2 24:50.95 AliYunDunUpdate

26838 root 10 -10 134120 14524 5924 S 0.3 0.8 343:05.22 AliYunDun

1 root 20 0 43280 3300 2108 S 0.0 0.2 2:16.82 systemd

2 root 20 0 0 0 0 S 0.0 0.0 0:01.78 kthreadd

3 root 20 0 0 0 0 S 0.0 0.0 1:30.68 ksoftirqd/0

5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H

7 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/0

8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh

9 root 20 0 0 0 0 S 0.0 0.0 65:15.85 rcu_sched

10 root rt 0 0 0 0 S 0.0 0.0 2:14.65 watchdog/0

12 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kdevtmpfs

13 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 netns

14 root 20 0 0 0 0 S 0.0 0.0 0:00.00 khungtaskd

15 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 writeback

16 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kintegrityd

查询到7020这个进程有异常,在继续查看具体异常线程。

# top -Hp 7020

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

23328 root 20 0 2538892 164144 11856 S 90.0 8.7 0:00.00 java

找到了当前异常进程下的异常线程后使用jstack查看详细情况

# jstack -l 6377 > error.log

将线程ID打印成16进制形式

# printf "%x\n" 23328

5b20

然后从jstack里查询该线程信息

# grep '18e9' error.log --color

"http-bio-6379-exec-200" #8869954 daemon prio=5 os_prio=0 tid=0x00007f74a81f6800 nid=0x5b20 waiting for monitor entry [0x00007f742457f000]

最后从jstack文件定位到堆栈信息

"http-bio-7020-exec-200" #8869954 daemon prio=5 os_prio=0 tid=0x00007f74a81f6800 nid=0x5b20 waiting for monitor entrJsCRNwoy [0x00007f742457f000]   java.lang.Thread.State: BLOCKED (on object monitor)    at org.apache.log4j.Category.callAppenders(Category.java:204)    - waiting to lock <0x00000000800371d0> (a org.apache.log4j.spi.RootLogger)    at org.apache.log4j.Category.forcedLog(Category.java:391)    at org.apache.log4j.Category.log(Category.java:856)    at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:368)

结论

在log4j 中,logger.info等日志记录方法是同步的(使用了synchronized),大量的日志导致线程阻塞在callAppenders()这个方法,也就是这个地方导致压测阻塞,响应耗时比较久的问题。

public void callAppenders(LoggingEvent event) {

int writes = 0;

for(Category c = this; c != null; c = c.parent) {

synchronized(c) {

if (c.aai != null) {

writes += c.aai.appendLoopOnAppenders(event);

}

if (!c.additive) {

break;

http:// }

}

}

if (writes == 0) {

this.repository.emitNoAppenderWarning(this);

}

}

版权声明:本文内容由网络用户投稿,版权归原作者所有,本站不拥有其著作权,亦不承担相应法律责任。如果您发现本站中有涉嫌抄袭或描述失实的内容,请联系我们jiasou666@gmail.com 处理,核实后本网站将在24小时内删除侵权内容。

上一篇:智能化运维场景分析
下一篇:企业该如何进行高效IT运维管理?
相关文章

 发表评论

暂时没有评论,来抢沙发吧~