log4j引起的性能问题

作者: 理查德成 | 来源:发表于2018-12-03 15:24 被阅读146次

log4j引起的性能问题
从源码分析log4j引起的性能问题
django queryset __in 引起的性能问题
SpringBoot--实战开发-整合Logback(五)
logge日志-logback
运行在生产系统中的企业级 JavaScript 应用的性能问题分
Logback
错误使用索引引起的性能问题
logback介绍和配置详解
浅谈日志处理logback

一、一次服务异常

web的问题

近期生产环境出现某web项目访问慢，有时甚至拒绝服务的现象；经查日志，发现web的日志中，频繁出现调用依赖的服务时，连接超时的问题；初步怀疑被依赖的服务请求处理过慢，但是有时一些明显不存在性能问题的请求，处理也很慢。

服务的问题

在我司的系统架构中，服务之间的远程通信采用采用Thrift实现；被依赖服务的日志中，频繁出现Connection reset by peer连接重置的问题。这个问题，是服务端企图从已经关闭的连接中读取或者写数据导致的，这就印证了web端的问题，确实是服务器响应太慢，导致web端因超时在响应前断开了连接，从而服务端出现连接重置的问题。

高并发下的log4j性能瓶颈

既然不存在性能问题的请求响应速度变慢了，那一定是请求处理过程中的某些外部因素，导致了速度变慢；比如数据库异常了；当让排查这个问题时并没有按照这个思路，而是在生产出问题时，直接查看了服务的线程堆栈信息(jstack)，发现大量线程的堆栈类似如下：

"pool-1-thread-190" prio=10 tid=0x00002b853809d800 nid=0xc01 waiting for monitor entry [0x00002b84b85d5000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    - waiting to lock <0x00000007880579e8> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.info(Category.java:666)
    at com.jlpay.commons.rpc.thrift.server.Dispatcher.invoke(Dispatcher.java:38)
    at com.jlpay.commons.rpc.thrift.server.RpcAdapterImpl.Invoke(RpcAdapterImpl.java:32)
    at com.jlpay.commons.rpc.thrift.server.RpcAdapter$Processor$Invoke.getResult(RpcAdapter.java:175)
    at com.jlpay.commons.rpc.thrift.server.RpcAdapter$Processor$Invoke.getResult(RpcAdapter.java:160)
    at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
    at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
    at org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer.invoke(AbstractNonblockingServer.java:518)
    at org.apache.thrift.server.Invocation.run(Invocation.java:18)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:724)

大量线程阻塞，等待某个锁，但是这个锁被以下线程持有：

"pool-1-thread-102" prio=10 tid=0x00002b8538053800 nid=0xba9 runnable [0x00002b84b2f71000]
   java.lang.Thread.State: RUNNABLE
    at java.text.DateFormat.format(DateFormat.java:336)
    at org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:443)
    at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)
    at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
    - locked <0x0000000788057650> (a org.apache.log4j.ConsoleAppender)
    at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
    at org.apache.log4j.Category.callAppenders(Category.java:206)
    - locked <0x00000007880579e8> (a org.apache.log4j.spi.RootLogger)

这样，大量线程在等待获取锁写日志，请求响应变慢了，一切都说得通了。

问题总结

那么，上面的线程堆栈信息真的有问题吗？

如果单单是堆栈信息里存在线程等待锁而阻塞，没有web服务以及其依赖服务日志中的请求超时以及连接重置问题，这样的堆栈信息是完全没有任何问题的。
在服务中因访问共享资源而使用同步代码很常见，一些特定的业务，以及资源的稀缺性决定了我们代码中的多线程必须使用同步操作。临界区（访问共享资源的代码片段）同一时刻只能由一个线程进入，那么其他线程必然是在临界区外等待的，此时的java线程堆栈信息就如以上，由一个线程获得锁，其他线程在等待。

高并发下
但是为什么这种问题不是特别频繁呢，其实还与并发量有关，高并发下，大量写日志请求，这个问题就会暴露出来。而且写日志操作相对来说还是比较慢的，高并发下会导致请求的平均处理时间高于正常情况下的处理时间；但是处理时间也不会大幅度增加到引起客户端请求超时的地步。因为相比与纯粹的cpu处理操作，写日志是一个慢操作，但是也不是肉眼能见的慢，写完日志的线程最终会释放锁，其他线程获得锁。

如果服务可同时处理的请求很多，线程数量很多，那写日志的等待时间确实是客观的。但是一般的服务，如web容器tomcat之类，分发请求线程池大小配置都是合理的，不会出现巨多线程同时存活；因此，log4j对请求造成的影响，是锦上添花的；但是另一方面，如果日志打印不合理，一个业务中由很多次日志打印，那这部分等待锁的时间叠加起来也是客观的了。

解决问题的方法：

根本原因还在于服务中确实存在处理很慢的请求，需要优化这一部分请求；
日志打印要合理，不要多打，也不要不打；在成熟的接口上，关闭日志输出，利于提高效率
生产日志级别调高，一般只打印info及以上的日志；
采用性能更高的log4j2或者logback替换log4j。

二、log4j的性能瓶颈

通过以上线程堆栈信息：

"pool-1-thread-190" prio=10 tid=0x00002b853809d800 nid=0xc01 waiting for monitor entry [0x00002b84b85d5000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.apache.log4j.Category.callAppenders(Category.java:204)
    - waiting to lock <0x00000007880579e8> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)

可以很明显的看到，at org.apache.log4j.Category.callAppenders(Category.java:204)在类org.apache.log4j.Category的方法callAppenders调用中(204行)等待a org.apache.log4j.spi.RootLogger的锁；

翻看源码：

public void callAppenders(LoggingEvent event) {
        int writes = 0;
        for (Category c = this; c != null; c = c.parent) {
            // Protected against simultaneous call to addAppender, removeAppender,...
            synchronized (c) {
                if (c.aai != null) {
                    writes += c.aai.appendLoopOnAppenders(event);
                }
                if (!c.additive) {
                    break;
                }
            }
        }
        if (writes == 0) {
            repository.emitNoAppenderWarning(this);
        }
    }

这里有一个同步代码块。

org.apache.log4j.spi.RootLogger

堆栈信息中的org.apache.log4j.spi.RootLogger是什么？

在log4j中的架构中：

image.png

其中Logger是日志实例，Appender是日志输出目的地。日志输出到哪个目的地，是由日志实例名以及配置决定的：

日志实例：

Logger logger = Logger.getLogger("test.child");

配置：

log4j.rootLogger=DEBUG,Console

log4j.appender.Console=org.apache.log4j.ConsoleAppender
log4j.appender.Console.Target=System.out
log4j.appender.Console.Threshold=DEBUG
log4j.appender.Console.layout = org.apache.log4j.PatternLayout
log4j.appender.Console.layout.ConversionPattern=[%d{HH\:mm\:ss SS}][%t][%p][%X{logid}]%m%n

日志实例中，test.child就是实例名，通过.来继承，即名为test.child的实例继承自test，所有实例隐式继承自根实例；这里的继承，是指继承日志级别以及输出目的地。

配置中，log4j.rootLogger指定根实例的输出目的地，根实例就是独一无二的org.apache.log4j.spi.RootLogger; log4j.logger.instanceName指定名为instanceName的实例的输出目的地。

竞争父Logger的锁

在实现上，org.apache.log4j.Category是所有Logger的父类，其中一个属性：

/**
 * The parent of this category. All categories have at least one
 * ancestor which is the root category.
 */
volatile protected Category parent;

parent指定了日志实例的父级，回过头来看打印日志的源码：

/**
 * Call the appenders in the hierrachy starting at
 * <code>this</code>.  If no appenders could be found, emit a
 * warning.
 *
 * <p>This method calls all the appenders inherited from the
 * hierarchy circumventing any evaluation of whether to log or not
 * to log the particular log request.
 *
 * @param event the event to log.
 */
public void callAppenders(LoggingEvent event) {
    int writes = 0;

    for (Category c = this; c != null; c = c.parent) {
        // Protected against simultaneous call to addAppender, removeAppender,...
        synchronized (c) {
            if (c.aai != null) {
                writes += c.aai.appendLoopOnAppenders(event);
            }
            if (!c.additive) {
                break;
            }
        }
    }

    if (writes == 0) {
        repository.emitNoAppenderWarning(this);
    }
}

日志打印时，会从当前日志实例开始，调用实例继承链中的所有父实例的appender。

同步代码块首先同步的是当前日志实例的内部锁(synchronized机制)，继承链中自下而上，锁竞争越激烈，处于最顶层的根Logger(若配置了根)最为激烈，这就是log4j会造成服务性能下降的原因所在。

log4j引起的性能问题
一、一次服务异常 web的问题近期生产环境出现某web项目访问慢，有时甚至拒绝服务的现象；经查日志，发现web的...
从源码分析log4j引起的性能问题
坊间传闻，log4j对服务性能会造成不利影响，现从log4j的实现源码一探究竟。一、从调用开始打印日志时，接触...
django queryset __in 引起的性能问题
无图无真相，先上图，这是读django queryset文档的时候，文档上的一段note 当时读完这句，就是觉得说...
SpringBoot--实战开发-整合Logback(五)
一、Logback简介 Logback是java的日志开源组件，是log4j创始人写的，性能比log4j要好，...
logge日志-logback
一、logback简介 logback是log4j创始人写的，性能比log4j要好，目前主要分为3个模块 logb...
运行在生产系统中的企业级 JavaScript 应用的性能问题分
企业级 JavaScript 应用部署在生产系统并运行后，如果出现性能问题，则找出引起这些性能问题的根源，往往不像...
Logback
Logback是log4j创始人设计的另一个开源日志组件, 性能比log4j更好, 目前是SpringBoot的默...
错误使用索引引起的性能问题
索引真的不一定更快 1. 原查询代码，以及索引信息执行查询，花费了170s（这是多次测试后，最低的一次） 2. ...
logback介绍和配置详解
logback是java的日志开源组件，是log4j创始人写的，性能比log4j要好，目前主要分为3个模块 log...
浅谈日志处理logback
logback是由log4j创始人设计的另一款日志组件。比起log4j，logback表现出了更强的性能。logb...