log4j致使的性能問題

問題背景

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

問題分析

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

　　二、將A服務的每一步認爲耗時的地方都加上日誌打印，包括內部方法調用的地方。這時候發現一個奇怪，在方法methodA()的內部耗時打印日誌是10ms，在this.methodA()調用的地方耗時打印日誌是1000ms；並且查看依賴的兩個外部服務的性能都比較正常，因此加上日誌打印後也看不出來究竟是什麼地方耗時。

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

　　四、早上8點時，經一個同事的指點，是不是日誌打印太多致使了該問題，由於log4j在多線程狀況下，會競爭Logger的鎖。下載線程快照文件後（執行jstatck -l pid），文件部份內容以下圖所示，看了一下，差很少大概有200個線程都是blocked狀態，都在等待這把鎖：

　　五、將A服務內全部打印日誌的地方都註釋掉，而後重啓，此時性能恢復。

　　六、查看監控得知，當時A服務由平時200/m的調用量忽然彪到了5000/m的調用量。且A服務內部有不少不合理的日誌打印，因此致使了此次線上問題。

　　那回到最開始，爲何會影響docker上的其餘服務呢。由於A服務和其餘服務共用了一個線程池（200個），當大量A請求過來，且不少線程都阻塞的狀況下，致使了其餘服務沒有線程可用，因此影響了到其餘服務。那這時的解決方案就是在設計初期要作線程隔離的規劃（關於高併發系統的各類隔離策略能夠參見http://jinnianshilongnian.iteye.com/blog/2324025）

Log4j分析

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

 1     public void callAppenders(LoggingEvent event) {
 2         int writes = 0;
 3 
 4         for(Category c = this; c != null; c = c.parent) {
 5             synchronized(c) {
 6                 if(c.aai != null) {
 7                     writes += c.aai.appendLoopOnAppenders(event);
 8                 }
 9 
10                 if(!c.additive) {
11                     break;
12                 }
13             }
14         }
15 
16         if(writes == 0) {
17             this.repository.emitNoAppenderWarning(this);
18         }
19 
20     }

 

Log4j配置分析

　　待補充

總結

　　一、日誌打印要有針對性，不應打的日誌不打，該打的日誌必定要打，且要有必定的打印規範。

　　二、線上日誌級別調到最高，通常開啓的info級別

　　三、若是碰到以下狀況，如 LOG.info("params = {}", JSON.toJSONString(user));以下打印需求，能夠修改成以下打印方式，由於你不加的話，其實JSON序列化也執行了，因此爲了避免必要的性能損耗，前面能夠加上判斷。

　　　　if(LOG.isInfoEnable) {

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

　　　　}

 　　四、能夠採用logback、log4j2來替換log4j。