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

更新时间：2022年06月20日 11:03:49 作者：welfna

这篇文章主要介绍了出现log.info报红的解决方案，具有很好的参考价值，希望对大家有所帮助。如有错误或未考虑完全的地方，望不吝赐教

出现log.info报红

1.装lombok插件

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

如果您已经安装lombok插件，您也可选择重装lombok插件，但作者并不推荐，只作为下策使用。

2.导包

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

Maven导包如图所示：

3.配置log4j.properties

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

4.报错的解决方案

程序包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 entry [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;
                }
            }
        }
        if (writes == 0) {
            this.repository.emitNoAppenderWarning(this);
        }
    }

以上为个人经验，希望能给大家一个参考，也希望大家多多支持脚本之家。

您可能感兴趣的文章:

Spring Boot 3中一套可以直接用于生产环境的Log4J2日志配置详解
Log4J2是Apache Log4j的升级版，参考了logback的一些优秀的设计，并且修复了一些问题，因此带来了一些重大的提升，这篇文章主要介绍了Spring Boot 3中一套可以直接用于生产环境的Log4J2日志配置,需要的朋友可以参考下
2023-12-12
SpringBoot多环境配置及配置文件分类实例详解
这篇文章主要介绍了SpringBoot多环境配置及配置文件分类,本文通过实例代码给大家介绍的非常详细，对大家的学习或工作具有一定的参考借鉴价值，需要的朋友可以参考下
2022-10-10
Spring核心IoC容器的依赖注入接口和层级包命名规范
这篇文章主要介绍了Spring核心IoC容器的依赖注入接口和层级包命名规范,IOC又名控制反转,把对象创建和对象之间的调用过程,交给Spring进行管理,目的是为了降低耦合度,需要的朋友可以参考下
2023-05-05
java多线程-读写锁原理
本文主要介绍java多线程的知识，这里整理了相关资料及简单示例代码，有兴趣的小伙伴可以参考下
2016-09-09
java解析XML详解
这篇文章主要介绍了XML解析四种方式代码示例详解,文中通过示例代码介绍的非常详细，对大家的学习或者工作具有一定的参考学习价值,需要的朋友可以参考下
2021-07-07
深入理解java异常处理机制及应用
本篇文章主要介绍了java异常处理机制及应用，异常处理机制是Java语言的一大特色。从异常处理的机制、异常处理的方法、异常处理的原则等方面介绍Java语言的异常处理技术,有兴趣的可以了解一下。
2016-12-12
Nacos框架与原理之Nacos的参数
这篇文章主要介绍了Nacos框架与原理之Nacos的参数，Nacos 中的参数有很多，如：命名空间、分组名、服务名、保护阈值、服务路由类型、临时实例等，但下面文章我们要讲解的是参数，参数是什么呢，下面一起进去文章学习详细内容吧
2022-05-05
Java8接口默认静态方法及重复注解原理解析
这篇文章主要介绍了Java8接口默认静态方法及重复注解原理解析,文中通过示例代码介绍的非常详细，对大家的学习或者工作具有一定的参考学习价值,需要的朋友可以参考下
2020-04-04
http调用controller方法时openfeign执行流程
这篇文章主要为大家介绍了http调用controller方法时openfeign执行流程，有需要的朋友可以借鉴参考下，希望能够有所帮助，祝大家多多进步，早日升职加薪
2023-07-07
MyBatis实现CRUD的示例代码
本文主要介绍了MyBatis实现CRUD的示例代码,文中通过示例代码介绍的非常详细,对大家的学习或者工作具有一定的参考学习价值,需要的朋友们下面随着小编来一起学习学习吧
2024-12-12