log4j導致的性能問題

問題背景

　　雙十一零點時，有一個服務A（后文該服務都用A來代替）的tp99由平常的50ms左右突然彪到60000ms，導致調用端積累了幾十W的數據，同時，也影響到了同一個docker上的其他服務。那為什么會出現這種問題呢，且看下面排查過程。

問題分析

　　1、將一台docker上其他服務都進行下線，同時將其他docker上的A服務進行下線，也就是說調用方只能調用到該docker上的A服務。這個時候發現除了A服務性能比較差，其他服務基本恢復正常。

　　2、將A服務的每一步認為耗時的地方都加上日志打印，包括內部方法調用的地方。這時候發現一個奇怪，在方法methodA()的內部耗時打印日志是10ms，在this.methodA()調用的地方耗時打印日志是1000ms；而且查看依賴的兩個外部服務的性能都比較正常，所以加上日志打印后也看不出來到底是什么地方耗時。

　　3、再次梳理代碼，能考慮到的地方都考慮到了，依然沒有任何解決方案。

　　4、早上8點時，經一個同事的指點，是否是日志打印太多導致了該問題，因為log4j在多線程情況下，會競爭Logger的鎖。下載線程快照文件后（執行jstatck -l pid），文件部分內容如下圖所示，看了一下，差不多大概有200個線程都是blocked狀態，都在等待這把鎖：

　　5、將A服務內所有打印日志的地方都注釋掉，然后重啟，此時性能恢復。

　　6、查看監控得知，當時A服務由平時200/m的調用量突然彪到了5000/m的調用量。且A服務內部有很多不合理的日志打印，所以導致了這次線上問題。

　　那回到最開始，為什么會影響docker上的其他服務呢。因為A服務和其他服務共用了一個線程池（200個），當大量A請求過來，且很多線程都阻塞的情況下，導致了其他服務沒有線程可用，所以影響了到其他服務。那這時的解決方案就是在設計初期要做線程隔離的規划（關於高並發系統的各種隔離策略可以參見http://jinnianshilongnian.iteye.com/blog/2324025）

Log4j分析

　　我們來看一下log4j的內部實現，查看如下源代碼。可以簡單理解為當寫入同一個日志文件時（如調用log.info(xxx)，會寫入info.log文件），為了保證寫入文件的順序不錯亂，會對該資源加鎖。

    public void callAppenders(LoggingEvent event) {
        int writes = 0;

        for(Category c = this; c != null; c = c.parent) {
            synchronized(c) {
                if(c.aai != null) {
                    writes += c.aai.appendLoopOnAppenders(event);
                }

                if(!c.additive) {
                    break;
                }
            }
        }

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

    }

 

Log4j配置分析

　　待補充

總結

　　1、日志打印要有針對性，不該打的日志不打，該打的日志一定要打，且要有一定的打印規范。

　　2、線上日志級別調到最高，一般開啟的info級別

　　3、如果碰到如下情況，如 LOG.info("params = {}", JSON.toJSONString(user));如下打印需求，可以修改為如下打印方式，因為你不加的話，其實JSON序列化也執行了，所以為了不必要的性能損耗，前面可以加上判斷。

　　　　if(LOG.isInfoEnable) {

　　　　　　LOG.info("params = {}", JSON.toJSONString(user));

　　　　}

 　　4、可以采用logback、log4j2來替換log4j。