一次logback多线程调优的经历

背景

  在一次项目的性能调优中，发现出现竞争瓶颈，导致在资源未使用满的情况下，TPS已经无法提升。祭起JMC（JAVA MISSON CONTROL）飞行记录器大法后，发现线程集中等待在logback写日志的地方，如下图所示：

  由于项目组多线程写如同一个文件日志，导致存在IO竞争，一般解决这种问题有三种选择方式
：

• 异步日志，但是会存在断电或者日志队列溢出丢失的可能
• 远程日志，日志放入外部消息队列，保证持久化，但需额外部署日志存储队列
• 多线程日志，按线程（或线程取模）记录日志，减少竞争，日志也能保证持久化

  项目组权衡再三，决定采用第三种分线程日志的方式解决。

误入SiftingAppender大坑

  项目组使用logback作为日志组件，loback是否有自动分线程写日志的功能呢？网上搜索logack multiThread 的第一篇文章就是教你如何使用SiftingAppender来分线程记录日志如下：
https://dzone.com/articles/si...
  SiftingAppender是logback根据mdc中的变量动态创建appender的代理，只要我们将一个线程号作为日志名分发器discriminator注入到SiftingAppender中，它就可以动态的为我们创建不同的appender，达到分线程的目的，配置方式举例如下：

• 配置discriminator

public class ThreadDiscriminator extends ContextBasedDiscriminator {
    String KEY ="threadName";
    /**
     * Return the name of the current context name as found in the logging event.
     */
    public String getDiscriminatingValue(ILoggingEvent event) {
        return event.getThreadName();
    }
    
    public String getDefaultValue() {
        return KEY;
    }
    
    public String getKey() {
        return KEY;
    }
    
    public void setKey(String key) {
        this.KEY = key;
    }
}

• 配置logback appender

    <!-- 分线程输出源 -->
    <appender name="frameworkthread" class="ch.qos.logback.classic.sift.SiftingAppender">
        <discriminator class="ThreadDiscriminator">
            <key>threadName</key>
        </discriminator>
        <sift>
            <appender name="FILE-${threadName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <encoder>
                    <Encoding>UTF-8</Encoding>
                    <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}[%c][%thread][%X{tradeNo}][%p]-%m%n</pattern>
                </encoder>
                <rollingPolicy
                    class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">        
                    <fileNamePattern>D:/test/threadlogs/${threadName}-%d{yyyy-MM-dd}.%i.log
                    </fileNamePattern>
                    <maxFileSize>100MB</maxFileSize>
                    <maxHistory>60</maxHistory>
                    <totalSizeCap>20GB</totalSizeCap>
                </rollingPolicy>
            </appender>
        </sift>
    </appender> 

  配置后查看输出结果也完全正确，网上的方法非常靠谱，真是piece of cake！但是接下来的性能测试让我再次懵逼：性能没有任何提升！反而更加糟糕了！这是怎么一回事呢？继续jmc查看线程状态：

  这次写文件outputStream的IO等待竟然提升到了AppenderBase.doAppender方法级别！查看AppenderBase.doAppender实现，这个方法是Synchronized！这个父类的方法是SiftingAppender的入口方法，这意味着在获取/创建线程自己真正的Appender和写入日志之前都必须排队阻塞在这个方法上！阻塞的级别提升了，当然性能更糟糕了！

优化logback：增加无需同步的SiftAppender

  logback Appender有两个最基础的抽象类，一个是同步AppenderBase，一个是不同步的UnsynchronizedAppenderBase，这两个类功能一样，只是doAppender方法的同步策略不一样（Synchronize VS ThreadLocal）。那么SiftingAppender为什么继承了AppenderBase而不是UnsynchronizedAppenderBase呢？分析原因应该是SiftingAppender作为Appender的代理集合，它即可能包含了继承自UnsynchronizedAppenderBase的OutputStreamAppender（FileAppender的基类，自行实现底层同步，doAppend方法未同步），也可能包含了继承AppenderBase的SocketAppender类（doAppend方法同步），为防止出现线程安全问题，它直接在自身的doAppend方法上进行了同步。
  在项目组实际使用时，项目组只需要分线程写文件日志，这意味这它使用的最终FileAppender应该是线程安全，完全独立的。故我们尝试在logback新增继承于UnsynchronizedAppenderBase的ParrelSiftingAppender步骤如下：

• logback core中增加继承UnsynchronizedAppenderBase的UnsynchronizedSiftingAppenderBase
• logback classic中增加继承UnsynchronizedSiftingAppenderBase的ParrelSiftingAppender
• logback classic中SiftAction注册增加ParrelSiftingAppender的工厂注册

  修改完成后测试发现果然性能提升了5倍左右，CPU资源利用率接近饱和，应该基本达到效果了，JMC分析应该是没有竞争了把，但是发现新的竞争方法出现了：

Appender<E> appender = appenderTracker.getOrCreate(discriminatingValue, timestamp);

最终改进：使用ConcurrentHashMap替换LinkedHashMap

  原来在SiftingAppender内部使用了LinkedHashMap作为LRU Cache来管理Appender，会定期移除。由于LinkedHashMap不是线程安全的，故在getOrCreate方法上增加了Synchronized同步操作，造成竞争等待。
  结合业务场景，这里完全可以使用ConcurrentHashMap作为Appender的缓存，ConcurrentHashMap读写锁分离，并且key值分区上锁，在多读少写的情况下，有很高的并发性能。并且真正生成的日志Appender也并不多（100个左右），定时清理完全也不会出现内存溢出问题。
  开始动手修改appenderTracker步骤如下：

• logback core中增加AbstractConcurrentMapComponentTracker
• logback core中增加ConcurrentMapAppenderTracker继承

AbstractConcurrentMapComponentTracker

• 修改UnsynchronizedSiftingAppenderBase使用ConcurrentMapAppenderTracker进行Appender管理

  最终性能测试结果：在资源相同的情况下，优化后比使用LinkedHashMap性能提高一倍。至此，整个logback多线程调优结束，通过充分优化同步竞争的方式，最终使得分线程记录日志的性能比最原始的多线程写同一文件提高了10倍（SiftAppender去锁提高到5倍，Map替换提高2倍）！