log4j2日志戳引发的优化

背景：针对生产环境中日志打印量多、并且长度大等现象，从而在使用同步打印时会导致增加交易的耗时以及系统的吞吐量上不去的情况，最终选择使用目前流行的log4j2的异步打印。

我们抛出一个问题为什么异步就不能传递日志戳？

在解决问题之前我们先说一下为什么选用log4j2是因为异步快？为什么异步打印快？底层运用了什么原理？

首先为什么log4j2的异步打印要优于logback以及log4j，最重要的原因是因为底层运用了一个叫disruptor的框架，该框架是由LMAX公司提供。LMAX Disruptor

那么为什么disruptor快呢？

1. 该框架底层运用无锁的环形队列，实际上就是一个数组。（利用cas原理实现无锁机制，减少了因为锁导致的上下文切换的开销）

2. 采用cpu高速缓存来减少读取磁盘内存的耗时。（通过缓存行填充手段及实现高速缓存，也避免了伪共享的问题）

 

 

而logback以及log4j等日志框架底层采用的java代码实现的ArrayBlockingQueue来实现的异步消息消费。

了解完底层原理之后，回过头来看看异步日志戳为什么会传递不下去？在log4j2官网找到了Log4j – Log4j 2 线程上下文 (apache.org)相关的介绍。

这里可以看到默认情况下是ThreadLocal，大家都知道threadlocal只能用于当前线程上下文之间传递参数，但是由于我们是通过队列异步消费，所以当我们传递日志戳时无法继续往下传递，接着我们去看下源码

看到这里当inheritableMap变量false的话直接返回threadlocal，这也就印证了为什么异步线程日志戳为什么不能传递了。

那么inheritableMap又是什么？该类下面也有一行赋值的代码，篇幅问题我只拿取需要的部分。

public static final String INHERITABLE_MAP = "isThreadContextMapInheritable";
    static void init() {
        inheritableMap = PropertiesUtil.getProperties().getBooleanProperty(INHERITABLE_MAP);
    }

看代码意思是会通过系统配置属性里面拿到一个叫isThreadContextMapInheritable 的变量来赋值。看到这里大家应该也能想到，如果改属性为true 那么也就是可以使用InheritableThreadLocal使子线程可以传递父线程相关的内容。当然官网也做了相关的使用介绍。

接着我们在Log4j – Extending Log4j 2 (apache.org)里找到了自定义上下文的入口。

这里给大家补充另外一个更高级的上下文传递工具TransmittableThreadLocal自行可以百度了解下。

于是我经过上面的一通操作之后，终于看到了光明。我们借着光明，经行了一轮压测。结果如下

可见性能相对之前提升四倍，但是通过jmc检测工具看到有好多线程阻塞在AsyncLoggerDisruptor.enqueueLogMessageWhenQueueFull这里。

 于是我们看下源码，发现这里用到了锁机制。

继续分析源码为什么要加锁以及前面的if是意思，上源码。

 继续官网找属性值定义

也就是当缓冲区满之后，通过限制输入端对排队的继续访问，从而避免过多占用cpu影响主线程。看到这里终于明白了为什么线程会阻塞。

由于篇幅的问题，我们暂时介绍到这里，链接见官网给出的其他优化点Log4j – Performance