log4j引起的性能问题

一、一次服务异常

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对请求造成的影响，是锦上添花的；但是另一方面，如果日志打印不合理，一个业务中由很多次日志打印，那这部分等待锁的时间叠加起来也是客观的了。

解决问题的方法：

  1. 根本原因还在于服务中确实存在处理很慢的请求，需要优化这一部分请求；
  2. 日志打印要合理，不要多打，也不要不打；在成熟的接口上，关闭日志输出，利于提高效率
  3. 生产日志级别调高，一般只打印info及以上的日志；
  4. 采用性能更高的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会造成服务性能下降的原因所在。

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 204,053评论 6赞 478
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 85,527评论 2赞 381
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 150,779评论 0赞 337
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 54,685评论 1赞 276
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 63,699评论 5赞 366
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 48,609评论 1赞 281
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 37,989评论 3赞 396
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 36,654评论 0赞 258
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 40,890评论 1赞 298
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,634评论 2赞 321
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,716评论 1赞 330
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,394评论 4赞 319
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 38,976评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,950评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,191评论 1赞 260
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 44,849评论 2赞 349
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,458评论 2赞 342