一次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倍）！