小日志大问题——追踪Logger的错误使用导致的JAVA进程CPU占用过高问题

📢📢📢📣📣📣
哈喽！大家好，我是「奇点」，江湖人称 singularity。刚工作几年，想和大家一同进步🤝🤝
一位上进心十足的【Java ToB端大厂领域博主】！😜😜😜
喜欢java和python，平时比较懒，能用程序解决的坚决不手动解决😜😜😜

✨ 如果有对【java】感兴趣的【小可爱】，欢迎关注我

❤️❤️❤️感谢各位大可爱小可爱！❤️❤️❤️
————————————————

如果觉得本文对你有帮助，欢迎点赞，欢迎关注我，如果有补充欢迎评论交流，我将努力创作更多更好的文章。
————————————————
 

问题背景：

java工程和mysql混跑的一台服务器。最近的mysql的使用运算量比较大，然后就出现了查询运算卡死的情况。

最开始的排查方向放到了mysql上，结果始终找不到原因。

然后考虑是否是因为资源占用的问题，Top一看，java工程占用了150%以上的cpu，于是开始排查是什么原因导致的java这么大的cpu占用。

最后定位是日志过大导致的，日志级别从debug改成了info，减少日志量，优化前后cpu从最高150%多的占用降到了30%左右。

排查过程：

按照之前处理过的HttpClient buffer导致JAVA资源占用问题

https://blog.csdn.net/qq_29235677/article/details/133921735?spm=1001.2014.3001.5502

的步骤排查，但是发现进程的子线程堆栈并没有阻塞或卡死的情况，不是代码逻辑或异常导致的。

然后想看看日志方面有没有什么异常。

工程日志分为ALL、INFO、FATAL、ERROR，发现两方面问题：

1. 日志记的比较混乱，有些常规的INFO信息打到了FATAL里，影响问题排查；

2. ALL日志特别大，满200M打包压缩，1分钟就能打一个，偶尔1分钟能打两个。进去一看DEBUG的日志全写里边了。

处理：

我们是使用的org.apache.logging.log4j，获取到logger后就可以通过log.debug/log.info/log.warn/log.error/log.fatal等记日志了，具体的日志设置是在工程resources中的配置文件log4j2.xml下。

1. 首先规范代码中的log.使用，要清楚每条日志的level层级（即对于工程的意义，致命的错误用FATAL、一般的错误用ERROR、警告用WARN、业务信息用INFO、代码调试的用DEBUG）然后选用合适的方法log.debug或log.warn等。

2. 线上运行的服务，要设置好日志记录的级别，尤其是访问量或数据量比较大的情况。

下面贴一下具体的配置文件。分别设置了控制台日志、Info日志、error日志、fatal日志，并设置了循环机制，即超出一定大小后日志就打包压缩等。

原来标红的All日志和root那设置的都是debug，处理后都改成info了。

<?xml version="1.0" encoding="UTF-8"?>

<!--
    status : 这个用于设置log4j2自身内部的信息输出,可以不设置,当设置成trace时,会看到log4j2内部各种详细输出
    monitorInterval : Log4j能够自动检测修改配置文件和重新配置本身, 设置间隔秒数。此处表示每隔600秒重读一次配置文件
-->
<Configuration status="OFF" monitorInterval="600">

    <!--日志级别：TRACE < DEBUG < INFO < WARN < ERROR < FATAL-->
    <!--如果设置为WARN，则低于WARN的信息都不会输出-->
    <Properties>
        <!-- 配置日志文件输出目录,此处为项目根目录下的logs文件夹 -->
        <Property name="LOG_HOME">logs</Property>
        <property name="FILE_NAME">material_collection</property>
    </Properties>