log.info问题总结

最新推荐文章于 2024-06-04 15:19:02 发布

txxs

最新推荐文章于 2024-06-04 15:19:02 发布

阅读量6.1k

点赞数 2

本文链接：https://blog.csdn.net/maoyeqiu/article/details/119456270

版权

一、CPU飙升

1.1 异常日志

从开发人员给的描述里面看, 基本没啥可以具体怀疑的地方. 进一步观察该应用的各个指标, 只有 CPU 使用率比较异常, 其它没有啥异常的地方.

一般 CPU 高, 要从线程看起, 做了几个 thread dump, 大概推断出问题的所在, 进一步分析, 验证了这个推断.

从 thread dump 看到好几个线程都是在 blocked 状态, 它们都是在等 java.io.PrintStream 某个 instance 的一把锁, 这个锁正是 PrintStream 的 println 方法里面的.

为什么会调用这个 println 方法呢? 原来这些 thread 都遇到了一个 CommonException, 程序捕获这个 CommonException 之后, 就在 catch 块里面调用了 CommonException 的 printStacktrace() 方法; 然而这个方法对于没有指定要 print 到哪里去的情况, 默认是输出到 System.err, 这个 System.err 正是一个 PrintStream.

其实看到这里感觉也没啥问题, 很多人都是把 log 输出到 System.out, System.err 的. 这个应用里面, System.out, System.err 都是重定向到 log 文件的, 也就是和 log4j 一样, 都输出到了文件系统. 他们的文件都叫 stdout.log. 仔细查看输出的问题, 就会发现, 输出文件的效率真是太高了. 每秒2个文件, 每个6M:

随便打开一个文件来看, 里面基本全是出错的 stacktrace, 每个 stacktrace 大概只有10行, 6M 的 log 文件里面大概有3500个线程的 stacktrace. 这意味着每秒有大概7000次写入. 由于一个线程不可能连续写入这种 stacktrace, 所以每秒有7000次的锁获取/释放发生在 System.err, 也就是上面的 PrintStream 的同步锁上面. 由于这个锁是一个高频率使用, 并且必然会发生竞争的锁, 所以不可能有偏向锁, 自旋锁存在, 必然膨胀到最重量的锁.

那么这样问题就可以解释了:

30个线程不停的在出错, 不停的要写日志到 System.err 中, 这里有个锁, 它们要频繁的获取/释放, 它们从获取到释放的时间又超短, 仅仅写一个10行日志. 本来获取释放锁操作就是一个比较重量的操作, 这个重量就是指的 CPU 消耗比较高. 频繁短期的获取释放锁必然会导致 CPU 飙升.

1.2 正常日志

首先使用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]

“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);
        }

    }

1.3 日志死锁

https://www.iteye.com/blog/zl378837964-2373591

二、频繁的GC

线上服务突然告警，jvm疯狂触发老年代gc，登录后台查看gc并不能释放老年代空间，之前这个服务一直正常运行了几个月，第一时间下载jvm的dump文件，并对服务重启，防止内存不足影响线上业务。

使用MAT分析dump文件，先按照retained Heap排序，

发现ThreadLocal 和StringBuilder这两个类占用了大量内存，ThreadLocal也是引用的StringBuilder，点开StringBuilder发现内容是一些日志文件，初步确定是log文件导致的内存泄漏，先将线上的日志输出级别提高到error（我们系统支持动态调整日志输出级别）。

搜索Log4j2在什么地方使用了StringBuilder，排查发现org.apache.logging.log4j.message.ParameterizedMessage这个类中有一个复用StringBuilder的代码，线上使用log4j-api的版本是2.8

public String getFormattedMessage() {

        if (formattedMessage == null) {

            final StringBuilder buffer = getThreadLocalStringBuilder();

            formatTo(buffer);

            formattedMessage = buffer.toString();

        }

        return formattedMessage;

    }

    private static StringBuilder getThreadLocalStringBuilder() {

        StringBuilder buffer = threadLocalStringBuilder.get();

        if (buffer == null) {

            buffer = new StringBuilder(DEFAULT_STRING_BUILDER_SIZE);

            threadLocalStringBuilder.set(buffer);

        }

        buffer.setLength(0);

        return buffer;

    }

这段代码中Log4j2引用了一个ThreadLocal中的StringBuilder，这样复用StringBuilder可以大幅提高日志输出效率，但注意这段代码buffer.setLength(0),这个操作只会将StringBuilder的写入重置为从0开始写入，但不会回收StringBuilder已经占用的内存，类似于如果StringBuilder中原有值 “哈哈哈哈哈哈”，执行setLength(0)之后再写入"123"，那StringBuilder虽然存储的值是 “123”，但在Builder的数组中存储的其实是 “123哈哈哈”,只是覆盖了前三个位置，后面的三个位置仍然占用内存，释放不了。由于当前的ThreadLocal是tomcat的线程池里的线程，ThreadLocal就基本没啥可能会被释放，导致StringBuilder也不会被回收。这个StringBuilder的内存只会增加不会减少，由此导致内存泄漏。

后来查看log4j2-api的最新版本2.13.0

public static final int MAX_REUSABLE_MESSAGE_SIZE = size("log4j.maxReusableMsgSize", (128 * 2 + 2) * 2 + 2);

public String getFormattedMessage() {

        if (formattedMessage == null) {

            final StringBuilder buffer = getThreadLocalStringBuilder();

            formatTo(buffer);

            formattedMessage = buffer.toString();

            StringBuilders.trimToMaxSize(buffer, Constants.MAX_REUSABLE_MESSAGE_SIZE);

        }

        return formattedMessage;

    }

可以看到新版本中增加一个操作trimToMaxSize，代码如下：

/**

     * Ensures that the char[] array of the specified StringBuilder does not exceed the specified number of characters.

     * This method is useful to ensure that excessively long char[] arrays are not kept in memory forever.

     *

     * @param stringBuilder the StringBuilder to check

     * @param maxSize the maximum number of characters the StringBuilder is allowed to have

     * @since 2.9

     */

    public static void trimToMaxSize(final StringBuilder stringBuilder, final int maxSize) {

        if (stringBuilder != null && stringBuilder.capacity() > maxSize) {

            stringBuilder.setLength(maxSize);

            stringBuilder.trimToSize();

        }

    }

参考：

https://blog.csdn.net/jslcylcy/article/details/104371137

https://juejin.cn/post/6981424418413084703

https://zhuanlan.zhihu.com/p/71740544

https://blog.csdn.net/jiang18238032891/article/details/115832280

https://www.jianshu.com/p/fb124b45096a

txxs

关注

2
点赞
踩
3

收藏

觉得还不错? 一键收藏
2
评论
log.info问题总结

一、CPU飙升1.1 异常日志从开发人员给的描述里面看, 基本没啥可以具体怀疑的地方. 进一步观察该应用的各个指标, 只有 CPU 使用率比较异常, 其它没有啥异常的地方.一般 CPU 高, 要从线程看起, 做了几个 thread dump, 大概推断出问题的所在, 进一步分析, 验证了这个推断.从 thread dump 看到好几个线程都是在 blocked 状态, 它们都是在等 java.io.PrintStream 某个 instance 的一把锁, 这个锁正是 PrintStream 的 p
复制链接

扫一扫