日志打印會嚴重影響到性能

以前編程不喜歡對每個功能、重要的方法進行日志的格式化輸出，即使要輸出，也沒按照規范進行輸出。前段時間，隨着我們平

台用戶量不斷增加，出現些問題。當用戶遇到問題，就給我們客服打電話。然后客服毫無疑問就來找我們。當我們接收到這樣問題的時候，

我們首先要定位是什么原因造成的。當時就是因為自己方法中輸出的日志很少，而且不規范，所以根本找不到具體原因，雖然最后問題解

決了，但是花費很多不必要的時間。

 

那么我們怎樣使用好日志這一利器呢？

 

1.寫好日志：

 

我們先來看一下糟糕的日志打印：

 

 

@ResponseBody
    @RequestMapping(value = "unbind.do", method = RequestMethod.POST)
    public Object unbind(String bankId, String memberId) {

        if (StringUtils.isBlank(bankId) || StringUtils.isBlank(memberId)) {
            return new Result(false, "解綁參數不合法！");
        }
        try {
            authPayTwoService.unbind(bankId, memberId);
        } catch (AppException e) {
            LOG.info("認證支付2.0(unbind)失敗：{}",e);
            return new Result(false, e.getMessage());
        } catch (Exception e) {
            LOG.info("認證支付2.0(unbind)]失敗：{}",  e);
            return new Result(false, "解綁銀行卡失敗，請重試");
        }
        return new Result(true, "解綁銀行卡成功！");
    }

 

 

上面代碼是嚴格不符合規范的，每個公司都有自己的打印要求。首先日志的打印必須是以logger.error、logger.warn或logger.info

的方式打印出來。日志打印格式應包含[系統來源] 錯誤描述 [關鍵信息]，日志信息要能打印出能看懂的信息，有前因和后果。方法的入參和

出參也要考慮打印出來。

好的日志格式打印：

 

 

@ResponseBody
    @RequestMapping(value = "unbind.do", method = RequestMethod.POST)
    public Object unbind(String bankId, String memberId) {
        LOG.info("[解綁銀行卡--認證支付2.0][params:bankId=" + bankId + ",memberId="
                + memberId + "]");
        if (StringUtils.isBlank(bankId) || StringUtils.isBlank(memberId)) {
            return new Result(false, "解綁參數不合法！");
        }
        try {
            authPayTwoService.unbind(bankId, memberId);
        } catch (AppException e) {
            LOG.error("[解綁銀行卡--認證支付2.0(unbind)-mas][error：{}",e);
            return new Result(false, e.getMessage());
        } catch (Exception e) {
            LOG.error("[解綁銀行卡--認證支付2.0(unbind)][error：{}",e);
            return new Result(false, "解綁銀行卡失敗，請重試");
        }
        return new Result(true, "解綁銀行卡成功！");
    }

 

 

從上面的代碼可以很輕松的定位方法、傳入的參數及異常是調用接口拋出的異常還是系統級的異常。

 

2.良好的日志輸出格式

 

最近測試同事采用兩百並發對項目進行測試。

格式優化前：

經過測試查看每秒的並發量平均只有110多如下圖：

 

通過查看jvm 虛擬機發現很多日志線程出現BLOCKED，如下：

 

"http-saoma%2F192.168.6.162-8097-132" daemon prio=10 tid=0x00002aaab88e4800 nid=0x2c8e runnable [0x0000000045274000]
   java.lang.Thread.State: BLOCKED
    at java.lang.Throwable.getStackTraceElement(Native Method)
    at java.lang.Throwable.getOurStackTrace(Throwable.java:591)
    - locked <0x00000007691390d0> (a java.lang.Throwable)
    at java.lang.Throwable.getStackTrace(Throwable.java:582)
    at sun.reflect.GeneratedMethodAccessor29.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.apache.log4j.spi.LocationInfo.<init>(LocationInfo.java:139)
    at org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:253)
    at org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:500)
    at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:65)
    at org.apache.log4j.PatternLayout.format(PatternLayout.java:506)
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
    at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
    - locked <0x0000000780fb1e00> (a org.apache.log4j.DailyRollingFileAppender)
    at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
    at org.apache.log4j.Category.callAppenders(Category.java:206)
    - locked <0x00000007800020a0> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:497)

我們定位org.apache.log4j.spi.LocationInfo類的代碼如下：

 

 

String s;
     // Protect against multiple access to sw.
     synchronized(sw) {
t.printStackTrace(pw);
s = sw.toString();
sw.getBuffer().setLength(0);
     }
     //System.out.println("s is ["+s+"].");
     int ibegin, iend;

     // Given the current structure of the package, the line
     // containing "org.apache.log4j.Category." should be printed just
     // before the caller.

     // This method of searching may not be fastest but it's safer
     // than counting the stack depth which is not guaranteed to be
     // constant across JVM implementations.
     ibegin = s.lastIndexOf(fqnOfCallingClass);

 

從上面可以看出在該方法中用了synchronized鎖，然后又通過打印堆棧來獲取行號。那么肯定會影響到性能的，我們通過看

此時log4j.properties日志文件配置的輸出格式為：

 %d %-5p %c:%L [%t] - %m%n

 

很明顯就是%l輸出行號的問題，那么我們把%l去掉結果會不會好很多呢？

把log4j.properties文件中輸出格式改為：

 %d %-5p %c [%t] - %m%n

輸出格式優化后：

 再看每秒的並發量如下圖：

 

從圖中我們可以看出並發量提高了40多，同時jvm線程日志中java.lang.Thread.State: BLOCKED也沒有了。看來程序的性能和日志的輸