记一次通过优化日志解决高并发服务性能瓶颈问题

蔚落 2023-07-16 12:56 31阅读 0赞

## 事故发现 ##

服务在生产环境中，由于同一时间段请求量过大，导致服务响应速度急剧下降。甚至会出现拒绝服务的问题，第一时间想到是机器性能问题，无法满足并发如此大的场景，需要进行扩容或者服务限流。经过扩容之后平稳了一个多月之后，又一次大量请求打进来的时候出现了此问题。这时才意识到开始从各个角度去排查问题。

## 事故排查过程 ##

一个系统的`吞吐量`（承压能力）与request对CPU的消耗、外部接口、IO等等紧密关联。单个reqeust 对CPU消耗越高，外部系统接口、IO影响速度越慢，系统吞吐能力越低，反之越高。所以对于性能方面影响，需要排查的原因比较广。

首先通过`top`排查机器情况，并未发现太多问题。然后又结合业务代码、第三方接口请求和数据库请求进行排查，依旧没能找到突破点。

此时通过观察日志发现，日志的打印间隔竟然有高达2秒的，而且比例还不少，这明显是不正常的。

log4j采用`buffer`进行输出，怀疑是否log4j中`buffer`容量配置问题。于是增加`buffer`大小，进行压力测试，`buffer`增加到了8M，发现并没有什么实际的效果，于是开始怀疑同步性能低。

为了验证是否同步性能问题导致的，故将该服务的日志改为异步日志，发现`qps`得到了数十倍的增长，采用异步之后，问题已经觉得基本解决了。但是回过头来想，同步日志到底是什么问题导致性能会如此低下呢？还有就是其他的使用同步日志的服务，为什么没有出现这个问题？

## 同步日志性能探究 ##

对于服务线程响应变慢，我想到了用`jstack`直接去观察服务的线程堆栈信息，发现大量线程的堆栈类似如下：

"pool-1-thread-190" prio=10 tid=0x00002b853809d800 nid=0xc01 waiting for monitor entry [0x00002b84b85d5000]
       java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
        - waiting to lock <0x00000007880579e8> (a org.apache.log4j.spi.RootLogger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.info(Category.java:666)
        at com.jlpay.commons.rpc.thrift.server.Dispatcher.invoke(Dispatcher.java:38)
        at com.jlpay.commons.rpc.thrift.server.RpcAdapterImpl.Invoke(RpcAdapterImpl.java:32)
        at com.jlpay.commons.rpc.thrift.server.RpcAdapter$Processor$Invoke.getResult(RpcAdapter.java:175)
        at com.jlpay.commons.rpc.thrift.server.RpcAdapter$Processor$Invoke.getResult(RpcAdapter.java:160)
        at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
        at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
        at org.apache.thrift.server.AbstractNonblockingServer$FrameBuffer.invoke(AbstractNonblockingServer.java:518)
        at org.apache.thrift.server.Invocation.run(Invocation.java:18)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:724)

大量线程阻塞，等待某个锁，但是这个锁被以下线程持有：

"pool-1-thread-102" prio=10 tid=0x00002b8538053800 nid=0xba9 runnable [0x00002b84b2f71000]
       java.lang.Thread.State: RUNNABLE
        at java.text.DateFormat.format(DateFormat.java:336)
        at org.apache.log4j.helpers.PatternParser$DatePatternConverter.convert(PatternParser.java:443)
        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.WriterAppender.append(WriterAppender.java:162)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        - locked <0x0000000788057650> (a org.apache.log4j.ConsoleAppender)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
        at org.apache.log4j.Category.callAppenders(Category.java:206)
        - locked <0x00000007880579e8> (a org.apache.log4j.spi.RootLogger)

恍然大悟，同步日志的速度慢是因为`大量线程阻塞等待获取锁`，再写日志。

简单看了下`logger`输出日志的过程源码，发现有很多逻辑都在`加锁`的场景下处理的。高并发下，大量写日志请求，这个问题就会暴露出来。

而且写日志操作相对来说还是比较慢的，高并发下会导致请求的平均处理时间高于正常情况下的处理时间；但是处理时间也不会大幅度增加到引起客户端请求超时的地步。因为相比与纯粹的cpu处理操作，写日志是一个慢操作，但是也不是肉眼能见的慢，写完日志的线程最终会释放锁，其他线程获得锁。

## 思考 ##

还存在一个问题，为什么其他的同步日志服务，在业务量和请求量相似的情况下，没有暴露出该问题呢？对比了一下对应的日志配置，发现主要在`打印格式`上的区别：

//出问题服务：
    %d{ yyyy/MM/dd HH:mm:ss.SSS}[traceId: %X{ trace_id}] %t [%p] %C{ 1} (%F:%M:%L) %msg%n
    
    //未出问题的服务
    [%d{ yy-MM-dd.HH:mm:ss.SSS}] [%thread]  [%-5p %-22c{ 0} -] %m%n

专门看了下log4j官网的信息（[http://logging.apache.org/log4j/2.x/performance.html\#asyncLoggingWithLocation][http_logging.apache.org_log4j_2.x_performance.html_asyncLoggingWithLocation]）

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMzNDA0Mzk1_size_16_color_FFFFFF_t_70]  
大概也就是说日志格式使用这些参数的使用会导致性能的急剧下降  
`C or $class, %F or %file, %l or %location, %L or %line, %M or %method`  
大概下降30-100倍左右，这才找到真正的原因，原来同步和异步的性能影响是一部分，本身日志格式的配置也是存在问题的。

## 较为影响性能的日志输出参数 ##

%C     - 调用者的类名(速度慢,不推荐使用);
    %F     - 调用者的文件名(速度极慢,不推荐使用)
    %l     - 调用者的函数名、文件名、行号(速度极其极其慢,不推荐使用)
    %L     - 调用者的行号(速度极慢,不推荐使用)
    %M     - 调用者的函数名(速度极慢,不推荐使用)

发现这几个性能比较低下的参数，做的都是`定位类`的工作，都是`LocationInfo`类下的成员。  
LocationInfo.java

public class LocationInfo implements java.io.Serializable { 
    
      /** Caller's line number. */
      transient String lineNumber;
      /** Caller's file name. */
      transient String fileName;
      /** Caller's fully qualified class name. */
      transient String className;
      /** Caller's method name. */
      transient String methodName;
      /** All available caller information, in the format <code>fully.qualified.classname.of.caller.methodName(Filename.java:line)</code> */
      public String fullInfo;
    
    
    //...
    }

再通过`LogEvent.getLocationInformation()`的源码发现，log4j为了拿到函数名称和行号信息，利用了异常机制，首先抛出一个异常，之后捕获异常并打印出异常信息的堆栈内容，再从堆栈内容中解析出行号。（ `jvm对异常的处理损耗是不可忽略的，这是性能慢的原因之一` ）

public class LogEvent implements java.io.Serializable { 
        
        public LocationInfo getLocationInformation() { 
        if(locationInfo == null) { 
          locationInfo = new LocationInfo(new Throwable(), fqnOfCategoryClass);
        }
        return locationInfo;
      }
    
    }

再看看`LocationInfo`对应的构造方法部分，需要通过`同步锁`去获取`异常栈`内的内容，可见这是操作是有多消耗性能：

public LocationInfo(Throwable t, String fqnOfCallingClass) { 
          
          //...
    
          synchronized(sw) { 
            t.printStackTrace(pw);
            s = sw.toString();
            sw.getBuffer().setLength(0);
         }
          //System.out.println("s is ["+s+"].");
          int ibegin, iend;
    
          
          ibegin = s.lastIndexOf(fqnOfCallingClass);
    
          //...

问题基本明了了。

## 再次压测 ##

将服务中日志格式中的`(%F:%M:%L)`剔除，再进行压测。`QPS`上升至2000+，果然不踩坑就很难注意到这中小配置，有这么大的性能影响，算是给自己上了一课。

[http_logging.apache.org_log4j_2.x_performance.html_asyncLoggingWithLocation]: http://logging.apache.org/log4j/2.x/performance.html#asyncLoggingWithLocation
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMzNDA0Mzk1_size_16_color_FFFFFF_t_70]: /images/20230528/9ebe745c6a834e16ae6138767217e086.png