记一次性能分析及调优记一次性能分析及调优背景在不同QPS要求下，项目组服务端所需要的资源数，目前缺少一个准确的判断，

记一次性能分析及调优

背景

在不同QPS要求下，项目组服务端所需要的资源数，目前缺少一个准确的判断，故需要一份压测报告以供参考，避免造成资源浪费或是对稳定性造成影响。

另一方面，也需要预先对日后的高性能要求做好准备，无论是进行性能调优或是采用限流降级熔断之类的措施，以保障服务稳定。

工具准备

Arthas

Arthas是Alibaba开源的一款Java诊断工具。它可以帮助开发者在线诊断生产环境中的Java应用程序，它提供了一些强大的功能，如JVM监控，线程监控，类加载监控等。

Arthas的主要特点包括：

在线诊断生产问题，无需重启JVM。
动态跟踪Java代码，实时监控方法执行情况。
查看JVM和类加载器的实时状态。
对线程进行监控和诊断，分析线程状态，堆栈信息等。
支持REPL交互式命令行界面，提供命令自动完成、历史记录等功能。
支持多种命令，如监控、线程、堆栈、内存、GC等。

Arthas是对Java生产环境进行故障诊断、性能监控、业务数据统计等工作的非常有效的工具。以下为常见用法

curl -O https://arthas.aliyun.com/arthas-boot.jar 

java -jar arthas-boot.jar

用法详见：arthas.aliyun.com/doc/

Jmeter

目前市面上有诸如ab,wrk等各类压测软件，这里选用Jmeter主要是因为其支持参数化，可以使用CSV等数据文件来驱动测试，方便模拟大数量用户的并发请求，尽可能贴近线上环境。

以下为本次压测的相关参数，即800线程压测5分钟：

<stringProp name="ThreadGroup.num_threads">800</stringProp> 
<stringProp name="ThreadGroup.ramp_time">5</stringProp>
<boolProp name="ThreadGroup.scheduler">true</boolProp> 
<stringProp name="ThreadGroup.duration">300</stringProp> 
<stringProp name="ThreadGroup.delay">1</stringProp>

压测方式

压测过程需要尽可能排除系统波动导致的结果失真，否则将对优化思路产生干扰。一般几百QPS的上下波动不可当作优化措施是否生效的判断依据，还需结合平均耗时或是其他系统指标综合判断。

本次压测采用预热+3次3分钟压测取其平均值。

预热主要是排除 JIT C1/C2编译器优化的影响，一般开启压测后1、2分钟优化工作即可完成，可通过Arthas的Dashboard观察C1/C2线程占用情况，若不占用CPU则可认为预热完成。

调优过程

指标量化

为评估性能优化的效果，我们需要对系统的性能指标进行量化，并且要分别测试出优化前、后的性能指标，用前后指标的变化来对比呈现效果。

性能的量化指标有很多，比如 CPU 使用率、应用程序的吞吐量、客户端请求的延迟等，都可以评估性能。

主：应用程序的维度，我们可以用吞吐量和请求延迟来评估应用程序的性能。
辅：系统资源的维度，我们可以用 CPU 使用率来评估系统的 CPU 使用情况。

好的应用程序是性能优化的最终目的和结果，系统优化总是为应用程序服务的。所以，必须要使用应用程序的指标，来评估性能优化的整体效果。

系统资源的使用情况是影响应用程序性能的根源。所以，需要用系统资源的指标，来观察和分析瓶颈的来源。

这里建议优先以吞吐量和请求延迟来评估优化措施，系统的资源指标有很多，彼此之间的联系往往不容易全部厘清，可能在优化一个指标时，引发其他指标的异常。如果过早去纠结某一具体的系统资源指标，如上下文切换数，可能会影响你的判断，无端浪费时间

性能基准

为控制变量，本次性能优化基于下述机器资源：

服务器CPU规格	TiDB规格	TiKV规格
8C*6	6C/36G/288G * 6	6C/60G/600G *3

在初始压测结果中，3台6核 Tidb Server在8500左右QPS时到达瓶颈，在优化服务端性能时，需要控制数据库规格不变，避免过早对性能指标造成影响，故需要准备好足够的余量，即TIDB节点数X2。

以下为上述资源所压测到的QPS基准值：

summary + 175888 in 00:00:30 = 5862.9/s Avg:   136 Min:     9 Max:   539 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 1277990 in 00:03:29 = 6126.4/s Avg:   126 Min:     7 Max:  1157 Err:     0 (0.00%)
summary + 172500 in 00:00:30 = 5750.0/s Avg:   134 Min:     9 Max:   633 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 1450490 in 00:03:59 = 6079.1/s Avg:   127 Min:     7 Max:  1157 Err:     0 (0.00%)
summary + 176597 in 00:00:30 = 5885.2/s Avg:   134 Min:     8 Max:   466 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 1627087 in 00:04:29 = 6057.4/s Avg:   128 Min:     7 Max:  1157 Err:     0 (0.00%)
summary + 175133 in 00:00:30 = 5839.1/s Avg:   135 Min:     9 Max:   616 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 1802220 in 00:04:59 = 6035.5/s Avg:   129 Min:     7 Max:  1157 Err:     0 (0.00%)
summary +  16519 in 00:00:03 = 5759.8/s Avg:   135 Min:     7 Max:   546 Err:     0 (0.00%) Active: 0 Started: 800 Finished: 800
summary = 1818739 in 00:05:01 = 6032.9/s Avg:   129 Min:     7 Max:  1157 Err:     0 (0.00%)

初始压测结果

以下为各服务器规格下的压测结果：

服务器CPU规格	TiDB规格	TiKV规格	接口类型	并发数	总请求数	QPS	平均耗时	错误率	瓶颈
4C*3	6C/36G/288G * 3	6C/60G/600G *3	DBUpdate1,Redis2	800	279260	1518.5/s	489	0.00%	服务器CPU100%
4C*9	6C/36G/288G * 3	6C/60G/600G *3	DBUpdate1,Redis2	800	822924	4484.8/s	155	0.00%	服务器CPU100%
8C*6	6C/36G/288G * 3	6C/60G/600G *3	DBUpdate1,Redis2	800	1202942	6628.5/s	64	0.00%	服务器CPU100%
8C*9	6C/36G/288G * 3	6C/60G/600G *3	DBUpdate1,Redis2	800	1148784	8721.1/s	87	0.00%	服务器CPU100%
8C*12	6C/36G/288G * 3	6C/60G/600G *3	DBUpdate1,Redis2	800	2568560	8517.8/s	88	0.00%	TIDB CPU100%
8C*12	6C/36G/288G * 6	6C/60G/600G *3	DBUpdate1,Redis2	800	3659819	12132.7/s	61	0.00%	服务器CPU100%

从上述压测结果我们可以看出，随着服务器CPU数量增长，QPS基本呈线性增长，而Tidb在8500左右QPS时则到达CPU瓶颈。

显而易见，CPU使用率会是我们本次调优的重点。

服务端CPU优化

Discard LogEvent

如前文所述，服务端的CPU瓶颈是肉眼可见的，这里首先要做的是定位到是哪一线程的占用了多数CPU。在此可以直接采用Arthas的Dashboard或是Thread指令进行观测：

在这个面板中，有两个地方是需要关注的：

Log4j2-TF-5-AsyncLoggerConfig-4 线程占用较多CPU。
以http-nio-8888-exec-*开头的Tomcat业务线程存在阻塞的情况。

压测期间产生了大量的日志，该线程一直处于Runnable状态。

通过thread 42 打印出线程堆栈可知，Log4j2-TF-5-AsyncLoggerConfig-4 为异步日志消费线程，其不断从Ringbuffer中取出日志，并通过TCP连接投递到远程GrayLog进行处理。

而业务线程阻塞问题，可通过thread -b 捞出处于阻塞状态的线程堆栈，分析其阻塞原因：

可以看到，业务线程是在日志入队时阻塞，Log4j2默认采用SynchronizeEnqueueWhenQueueFull=true，即在Ringbuffer满时上锁，等待Ringbuffer消费出下一个可用空间。

如果将SynchronizeEnqueueWhenQueueFull设为false又会如何呢？调整该参数后进行压测：

summary = 655076 in 00:02:57 = 3704.6/s Avg:   208 Min:     7 Max:  3878 Err:     0 (0.00%)
summary +  49673 in 00:00:30 = 1655.9/s Avg:   477 Min:     9 Max:  2101 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 704749 in 00:03:27 = 3407.5/s Avg:   227 Min:     7 Max:  3878 Err:     0 (0.00%)
summary +  47597 in 00:00:30 = 1586.3/s Avg:   501 Min:    10 Max:  2039 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 752346 in 00:03:57 = 3176.7/s Avg:   245 Min:     7 Max:  3878 Err:     0 (0.00%)
summary +  45585 in 00:00:30 = 1519.5/s Avg:   526 Min:    35 Max:  2389 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 797931 in 00:04:27 = 2990.4/s Avg:   261 Min:     7 Max:  3878 Err:     0 (0.00%)
summary +  44367 in 00:00:30 = 1478.5/s Avg:   540 Min:    56 Max:  2586 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 842298 in 00:04:57 = 2837.6/s Avg:   276 Min:     7 Max:  3878 Err:     0 (0.00%)
summary +   7410 in 00:00:05 = 1542.1/s Avg:   533 Min:    81 Max:  2592 Err:     0 (0.00%) Active: 0 Started: 800 Finished: 800
summary = 849708 in 00:05:02 = 2816.9/s Avg:   278 Min:     7 Max:  3878 Err:     0 (0.00%)

可以看到QPS和平均请求耗时大幅下降，分析日志事件入队源码：

   public long next(int n)
    {
       ...//省略

        if (wrapPoint > cachedGatingSequence || cachedGatingSequence > nextValue)
        {
            cursor.setVolatile(nextValue);  // StoreLoad fence

            long minSequence;
            while (wrapPoint > (minSequence = Util.getMinimumSequence(gatingSequences, nextValue)))
            {
                LockSupport.parkNanos(1L); // TODO: Use waitStrategy to spin?
            }

            this.cachedValue = minSequence;
        }

        this.nextValue = nextSequence;

        return nextSequence;
    }

不加锁情况下，在等待nextSequene时，会 park 在 Disruptor 的 produce 方法上，轮询等待消费出下一个可以生产的环形 buffer c槽，这种做法会白白消耗大量CPU，故不宜采用。

我们此时的目标是希望日志线程不阻塞业务线程，毕竟日志更多是作为一种辅助工具，若是影响到正常业务线程的运行，就得不偿失了。那么还有另一种方式：在Ringbuffer满时丢弃Info以下级别的日志，即采用丢弃策略：

    DISCARD {
        @Override
        public void logMessage(final AsyncLogger asyncLogger, final String fqcn, final Level level,
                final Marker marker, final Message message, final Throwable thrown) {
            // do nothing: drop the event
        }

        @Override
        public void logMessage(final AsyncLoggerConfig asyncLoggerConfig, final LogEvent event) {
            // do nothing: drop the event
        }

        @Override
        public void logMessage(final AsyncAppender asyncAppender, final LogEvent coreEvent) {
            // do nothing: drop the event
        }
    };

在加入参数-Dlog4j2.asyncQueueFullPolicy=Discard后重新压测：

summary = 692352 in 00:01:27 = 7968.1/s Avg:    94 Min:     7 Max:  1125 Err:     0 (0.00%)
summary + 243997 in 00:00:30 = 8133.2/s Avg:    96 Min:     8 Max:   481 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 936349 in 00:01:57 = 8010.5/s Avg:    95 Min:     7 Max:  1125 Err:     0 (0.00%)
summary + 240267 in 00:00:30 = 8008.9/s Avg:    96 Min:     8 Max:   413 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 1176616 in 00:02:27 = 8010.2/s Avg:    95 Min:     7 Max:  1125 Err:     0 (0.00%)
summary + 241268 in 00:00:30 = 8042.3/s Avg:    96 Min:     8 Max:   427 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 1417884 in 00:02:57 = 8015.6/s Avg:    95 Min:     7 Max:  1125 Err:     0 (0.00%)
summary + 244484 in 00:00:30 = 8149.2/s Avg:    98 Min:     8 Max:   697 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 1662368 in 00:03:27 = 8035.0/s Avg:    96 Min:     7 Max:  1125 Err:     0 (0.00%)

QPS从6032.9/s提升到了8035.0/s，平均耗时从129下降到了96。

此时观察Arthas的Dashboard：

可以看见业务线程再无Blocked。

该项举措与其说是优化，不如说是服务降级策略，本质上是在高峰期时通过牺牲掉低级别的GrayLog日志，换取业务线程的平稳执行。

当然，其实还有更优的解决方式，比如先将日志落盘，再启用代理来投递到远程GlayLog进行解析，这种做法有三个方面的优势：一是相当于是通过本地文件起到了一个削峰填谷的作用；二是可以动态的调整日志消费的CPU使用；三则是将日志消费与业务线程隔离开来，避免互相影响。

但考虑到改造的时间成本，此次暂且搁置。

异步打印日志

目前项目组日志存在3种Appender，分别是控制台，每日日志文件以及前文提到的投递到GlayLog的GelfAppender。其中，GelfAppender为异步打印，其余为同步打印，即混合异步

<Loggers>
    <AsyncLogger name="org.xxx" level="INFO" includeLocation="true">
        <AppenderRef ref="GelfAppender"/>
    </AsyncLogger>
    <Root level="INFO" includeLocation="true">
        <AppenderRef ref="Console"/>
        <AppenderRef ref="RollingFileAppender"/>
    </Root>

</Loggers>

关于同步、异步的性能对比，官方给出了一个测试报告：

We also compared throughput of asynchronous loggers to the synchronous loggers and asynchronous appenders available in other logging packages, specifically log4j-1.2.17 and logback-1.0.10, with similar results. For asynchronous appenders, total logging throughput of all threads together remains roughly constant when adding more threads. Asynchronous loggers make more effective use of the multiple cores available on the machine in multi-threaded scenarios.

我们还将异步记录器的吞吐量与其他日志记录包（特别是 log4j-1.2.17 和 logback-1.0.10）中可用的同步记录器和异步附加器进行了比较，结果相似。对于异步appenders，当添加更多线程时，所有线程的总日志记录吞吐量大致保持不变。在多线程场景中，异步appender可以更有效地利用机器上可用的多个内核。

按照官方的说法，全异步打印性能优于混合异步的形式，故尝试做出调整：

<Loggers>
    <AsyncRoot level="INFO" >
        <AppenderRef ref="Console"/>
        <AppenderRef ref="GelfAppender"/>
        <AppenderRef ref="RollingFileAppender"/>
    </AsyncRoot>
</Loggers>

调整后重新压测：

summary = 1633882 in 00:03:12 = 8528.1/s Avg:    79 Min:     7 Max:   375 Err:     0 (0.00%)
summary + 262118 in 00:00:30 = 8737.0/s Avg:    79 Min:     8 Max:   376 Err:     0 (0.00%) Active: 700 Started: 700 Finished: 0
summary = 1896000 in 00:03:42 = 8556.4/s Avg:    79 Min:     7 Max:   376 Err:     0 (0.00%)
summary + 261114 in 00:00:30 = 8704.1/s Avg:    79 Min:     7 Max:   319 Err:     0 (0.00%) Active: 700 Started: 700 Finished: 0
summary = 2157114 in 00:04:12 = 8574.0/s Avg:    79 Min:     7 Max:   376 Err:     0 (0.00%)
summary + 264894 in 00:00:30 = 8829.2/s Avg:    78 Min:     7 Max:   334 Err:     0 (0.00%) Active: 700 Started: 700 Finished: 0
summary = 2422008 in 00:04:42 = 8601.2/s Avg:    79 Min:     7 Max:   376 Err:     0 (0.00%)
summary + 175690 in 00:00:20 = 8875.0/s Avg:    78 Min:     7 Max:   383 Err:     0 (0.00%) Active: 0 Started: 700 Finished: 700
summary = 2597698 in 00:05:01 = 8619.2/s Avg:    79 Min:     7 Max:   383 Err:     0 (0.00%)

调整后QPS从8035.0/s提升到了8619.2/s，平均耗时从96降到79

Log4j2 也考虑到了监控 AsyncLogger 这种情况，所以将 AsyncLogger 的监控暴露成为一个 MBean（JMX Managed Bean）。若服务集成了 prometheus，可以通过将 Log4j2 RingBuffer 大小作为指标暴露到 prometheus 中。当然还有另一种简单点的方式可以动态观测到RingBuffer的变化，即使用Arthas的Mbean命令，以下为使用方式：

观察Ringbuffer的消费速度，基本在1分钟左右就打满了256K。之后便是走上文所述的降级策略。

我们可以通过适当扩大RingbufferSize，在面对请求高峰进行扩容前，可以尽可能保留多一些日志。但一般来说，在项目组在需求上线前，流量基本就可预估了，上线时会预留一定的容量，一旦发现CPU使用率到达70%、80%，就可以着手扩容了，故一般也不会走到Discard的情况。

非必要异常抛出

50%以上的CPU消耗

在经过上述两个优化后，我尝试通过Arthas 观测最忙碌的线程堆栈，即重复使用 thread -n 3 ，但效果并不理想，无法对全局进行评估。这种观测方式本质上是人为进行一种粗粒度的采样，是否有更为精细化的采样，并对采样结果进行统计、合并？那么就自然而然想到了火焰图。

翻阅Arthas的使用手册，其profiler 命令支持生成应用热点的火焰图。其通过不断的采样（默认对CPU进行采样），然后把收集到的采样结果生成火焰图。火焰图的每一个矩形代表一个函数，矩形的宽度代表函数在CPU上的执行时间，矩形的高度代表函数的调用栈深度。火焰图的x轴表示采样的时间（或者资源），y轴表示函数调用栈。

在压测开始时运行 profiler start，压测结束时运行 profiler stop --format html ,我们得到了下述CPU火焰图：

基准火焰图.png

观察火焰图发现，业务相关的逻辑，如Tomcat请求接收，请求处理，数据入库，并不占主要CPU时间，而

Function: org/apache/logging/log4j/util/StackLocatorUtil.calcLocation 方法竟占用了接近40%的CPU。该方法底层调用new Thorwable来获取到所谓的Location，即位置信息。

每一个Throwable在创建时，都会调用fillInStackTrace() 方法来将当前线程的栈帧信息保存一份到stackTrace字段中作为异常堆栈信息，然后Throwable提供了若干方法来操作其保存的堆栈信息。而fillInStackTrace() 这一爬栈操作是异常整个生命周期中十分耗时的一个环节，而getStackTrace() 则是将整个StackTraceElement数组拷贝一份，这更是雪上加霜。并且随着调用链的拉长，创建Throwable消耗则更加明显。

那么Log4j2为什么要获取到位置信息呢，翻阅官方文档：

默认情况下，异步日志记录器不会将location信息传递给I/O线程，如果你的layouts或custom过滤器需要location信息，你需要在所有相关日志记录器(包括根日志记录器)的配置中设置“includeLocation=true”

如果其中一个layouts配置了关于位置的信息，比如HTML locationInfo,或者表达式%C或%class、%F或%file、%l或%location、%L或%line、%M或%method，log4j2将会获取堆栈的快照（snapshot），并遍历堆栈跟踪以查找位置信息，因此会消耗较多的时间。

但实际上我们项目中的日志layout并不需要位置相关的信息，此处为了保险起见，使用了Arthas stack 指令，监控位置信息的返回方法，并无相关调用，故可以放心去掉 "includeLocation=true" 参数。

除了Log4j2的calcLocation方法，从火焰图中还发现了以下两处非必要的异常打印：

org/xxx/util/ReflectUtil.getAllPrimitiveFields & findField

该类为自定义的工具类，其在获取Field时采用try...catch 的方式判断是否存在该Field，修改前：

Class<?> currentClass = clazz;
while (currentClass != null) {
    try {
        return currentClass.getDeclaredField(fieldName);
    } catch (NoSuchFieldException e) {
        currentClass = currentClass.getSuperclass();
    }
}

修改后：

for (Field field : clazz.getDeclaredFields()) {
    if (field.getName().equals(fieldName)) {
        return field;
    }
}
Class<?> superclass = clazz.getSuperclass();
if (superclass != null) {
    return findField(superclass, fieldName);
}

biz/paluch/logging/gelf/intern/GelfMessage.getAdditionalFieldValue

该操作是Gelf格式日志转JSON时调用，在没有显式定义附加字段类型时，其内部同样也是采用try...catch 的方式判断字段类型

if (fieldType.equalsIgnoreCase(FIELD_TYPE_DISCOVER)) {
    try {
        try {
            // try adding the value as a long
            result = Long.parseLong(value);
        } catch (NumberFormatException ex) {
            // fallback on the double value
            result = Double.parseDouble(value);
        }
    } catch (NumberFormatException ex) {
        // fallback on the string value
        result = value;
    }
}

故需要在log4j.xml中补充相关附加字段的类型：

<property name="AdditionalFieldTypes">
    service=String,env=String,level_str=String,logger=String,thread=String,service_game=String,server=String...
</property>

<Gelf name="GelfAppender" host="xxxm" port="xxx" version="1.1"
      extractStackTrace="true" filterStackTrace="true"
      mdcProfiling="false" includeFullMdc="true" originHost="%host{fqdn}"
      additionalFieldTypes="${AdditionalFieldTypes}">
    <Field name="level_str" pattern="%p"/>
    <Field name="logger" pattern="%c"/>
    <Field name="thread" pattern="%t"/>
    <Field name="service" literal="${sys:service}"/>
    <Field name="env" literal="${sys:graylog.env}"/>
</Gelf>

上述非必要异常加起来基本占了一半的CPU使用，全部优化之后重新压测：

summary = 1930398 in 00:02:25 = 13350.1/s Avg:    57 Min:     6 Max:  1096 Err:     0 (0.00%)
summary + 408251 in 00:00:30 = 13608.4/s Avg:    56 Min:     6 Max:  1072 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 2338649 in 00:02:55 = 13394.5/s Avg:    56 Min:     6 Max:  1096 Err:     0 (0.00%)
summary + 392472 in 00:00:30 = 13082.0/s Avg:    56 Min:     6 Max:  1105 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 2731121 in 00:03:25 = 13348.7/s Avg:    56 Min:     6 Max:  1105 Err:     0 (0.00%)
summary + 413004 in 00:00:30 = 13767.3/s Avg:    57 Min:     6 Max:   418 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 3144125 in 00:03:55 = 13402.2/s Avg:    57 Min:     6 Max:  1105 Err:     0 (0.00%)
summary + 359133 in 00:00:30 = 11971.1/s Avg:    57 Min:     7 Max:  1081 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 3503258 in 00:04:25 = 13239.9/s Avg:    57 Min:     6 Max:  1105 Err:     0 (0.00%)
summary + 389478 in 00:00:30 = 12982.6/s Avg:    58 Min:     6 Max:   307 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 3892736 in 00:04:55 = 13213.7/s Avg:    57 Min:     6 Max:  1105 Err:     0 (0.00%)
summary +  93173 in 00:00:07 = 13429.4/s Avg:    58 Min:     6 Max:   300 Err:     0 (0.00%) Active: 0 Started: 800 Finished: 800
summary = 3985909 in 00:05:02 = 13218.7/s Avg:    57 Min:     6 Max:  1105 Err:     0 (0.00%)
Tidying up ...    @ July 28, 2023 11:28:06 AM CST (1690514886939)

QPS从8619.2/s提升到了13218.7/s，平均耗时从79降低到57，性能有了显著提升。通过此优化也提醒我们在日常开发中，不可忽视异常对性能造成的影响，尤其是不要以抛出异常的方式来处理可预测的代码分支。

可避免的JSON操作

7%的CPU消耗

继续观察前文提到的火焰图：

可以发现，还有7%的CPU消耗在某个获取配置的函数上

该函数在用户每个请求的路径上解析相关配置，内部调用 JSON.parseArray() 以及 getString() ，但配置对象本身是可穷举的，可以采用缓存的方式，以空间换时间来提升性能。故使用了Caffine本地缓存进行了优化。

再次进行性能压测:

summary + 480169 in 00:00:30 = 16005.6/s Avg:    49 Min:     6 Max:   341 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 2587456 in 00:02:48 = 15413.4/s Avg:    49 Min:     6 Max:   341 Err:     0 (0.00%)
summary + 464617 in 00:00:30 = 15487.2/s Avg:    50 Min:     7 Max:   305 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 3052073 in 00:03:18 = 15424.6/s Avg:    49 Min:     6 Max:   341 Err:     0 (0.00%)
summary + 477794 in 00:00:30 = 15926.5/s Avg:    49 Min:     6 Max:   292 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 3529867 in 00:03:48 = 15490.6/s Avg:    49 Min:     6 Max:   341 Err:     0 (0.00%)
summary + 479163 in 00:00:30 = 15972.1/s Avg:    49 Min:     6 Max:  1091 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 4009030 in 00:04:18 = 15546.6/s Avg:    49 Min:     6 Max:  1091 Err:     0 (0.00%)
summary + 483348 in 00:00:30 = 16111.6/s Avg:    48 Min:     6 Max:   287 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 4492378 in 00:04:48 = 15605.5/s Avg:    49 Min:     6 Max:  1091 Err:     0 (0.00%)
summary + 218548 in 00:00:14 = 16087.4/s Avg:    49 Min:     6 Max:   306 Err:     0 (0.00%) Active: 0 Started: 800 Finished: 800
summary = 4710926 in 00:05:01 = 15827.2/s Avg:    49 Min:     6 Max:  1091 Err:     0 (0.00%)

QPS进一步从13218.7/s提升到15827.2/s，平均耗时从57下降到49。

通过这个优化也提醒我们，在用户请求路径上，要尽可能避免过重的操作，可能你认为的一个消耗“还行”的操作，经过数万用户放大，对系统也会造成不小影响。

上下文切换排查

在使用Vmstat观察系统整体运行指标时发现，上下文切换数量达到了10W+，此时忽略了一个问题，该宿主机上还有着其他容器，而大多数Linux工具所提供的系统资源指标在创建时间上要早于cgroups（通常会从proc文件系统获取），但例如/proc/meminfo, /proc/vmstat及其它位置是无法实现容器化，也就是其无法为cgroup所识别。其只能显示主机系统（物理或虚拟机）的整体内存容量，而现代Linux容器技术无法对其加以利用。

对于系统总的 CPU 使用率，需要读取 /proc/stat 文件，但是这个文件中的各项 CPU ticks 是反映整个节点的，并且这个 /proc/stat 文件也不包含在任意一个 Namespace 里。那么，对于 top 命令来说，它只能显示整个节点中各项 CPU 的使用率，不能显示单个容器的各项 CPU 的使用率。

也就是说，当我们在容器内运行原生top时，虽然可以看到容器中每个进程的 CPU 使用率，但是 top 中"%Cpu(s)"那一行中显示的数值，并不是这个容器的 CPU 整体使用率，而是容器宿主机的 CPU 使用率。

同理，当运行vmstat时，它显示的是宿主机的性能指标，而不是容器的。

那么要如何在容器内观测到进程本身的上下文切换呢？可以使用pidstat -wt 2（每两秒打印一次进程上下文切换指标）

02:37:16 PM   UID      TGID       TID   cswch/s nvcswch/s  Command
02:37:17 PM     0         -       157      0.00     47.00  |__java
02:37:17 PM     0         -       166      1.00      0.00  |__java
02:37:17 PM     0         -       174   3799.00      2.00  |__java
02:37:17 PM     0         -       176    275.00     12.00  |__java
02:37:17 PM     0         -       275   1884.00      7.00  |__java
02:37:17 PM     0         -       276   1919.00     10.00  |__java
02:37:17 PM     0         -       277   1717.00      6.00  |__java
02:37:17 PM     0         -      2501    271.00      8.00  |__java
02:37:17 PM     0         -      3324    274.00     10.00  |__java
02:37:17 PM     0         -      3828    276.00     13.00  |__java
02:37:17 PM     0         -      4325    267.00      1.00  |__java
02:37:17 PM     0         -      4328    247.00      7.00  |__java
02:37:17 PM     0         -      4330    267.00     52.00  |__java
02:37:17 PM     0         -      4338    269.00      3.00  |__java
02:37:17 PM     0         -      5151    261.00      3.00  |__java
02:37:17 PM     0         -      5217    236.00      2.00  |__java
02:37:17 PM     0         -      5228    257.00      9.00  |__java
02:37:17 PM     0         -      5260    258.00     10.00  |__java
02:37:17 PM     0         -      5266    290.00     95.00  |__java
02:37:17 PM     0         -      5267    274.00      4.00  |__java
02:37:17 PM     0         -      6663     42.00      0.00  |__java
02:37:17 PM     0         -      6664     29.00      0.00  |__java

此处只列出一部分，粗略估算，自愿上下文切换大概在5W左右。

cswch ，表示每秒自愿上下文切换（voluntary context switches）的次数，

nvcswch ，表示每秒非自愿上下文切换（non voluntary context switches）的次数。

所谓自愿上下文切换，是指进程无法获取所需资源，导致的上下文切换。比如说， I/O、内存等系统资源不足时，就会发生自愿上下文切换。而非自愿上下文切换，则是指进程由于时间片已到等原因，被系统强制调度，进而发生的上下文切换。比如说，大量进程都在争抢 CPU 时，就容易发生非自愿上下文切换。

但仅通过该表格很难去判断其是否存在无谓的上下文切换，是否可以像CPU火焰图一样绘制出上下文切换火焰图呢，答案是可以的。这里我采用了Perf+Flamegraph+perf-map-agent来配合绘制火焰图。

Linux中的Perf子系统是一个基于内核的子系统，为硬件和软件的性能分析和监控提供一个框架。它最初在v2.6.31版本中被并入Linux内核，并有一个用户空间工具（perf）与内核子系统接口。用户空间的perf工具可以对硬件事件（CPU中寄存器执行的上下文切换和指令），以及软件事件（通过软件计数器和跟踪点）进行记录、计数、和采样。另一方面，Arthas中的部分Profiler也需要借助Perf来完成系统调用采集。

使用Perf之前，需要提前调整参数 ‘echo -1 >/proc/sys/kernel/perf_event_paranoid’ 以开放权限，此项操作需要联系相关运维同学评估风险

但如果像是 Java 这种通过 JVM 来运行的应用程序，运行堆栈用的都是 JVM 内置的函数和堆栈管理。所以，从系统层面你只能看到 JVM 的函数堆栈，而不能直接得到 Java 应用程序的堆栈。perf_events 实际上已经支持了 JIT，但还需要一个 /tmp/perf-PID.map 文件，来进行符号翻译。开源项目 perf-map-agent 可以帮你生成这个符号表。此外，为了生成全部调用栈，你还需要开启 JDK 的选项 -XX:+PreserveFramePointer。

可以参考 Netflix 的技术博客 medium.com/netflix-tec… ，来查看详细的使用步骤。

而Flamegraph则是一个性能分析的可视化工具，可以以火焰图形式来展示性能分析数据。

以下给出使用方式：

yum -y install perf
yum -y install gcc-c++
yum -y install cmake
yum -y install make
git clone https://github.com/brendangregg/FlameGraph.git
git clone https://github.com/jvm-profiling-tools/perf-map-agent.git

cd perf-map-agent-master
cmake .
make

./bin/create-java-perf-map.sh 进程id     //生成符号表
perf record -e context-switches -F 99  -g -p 1 -- sleep 120 //采集120s导致上下文切换最多的函数或者指令
perf script | FlameGraph-master/stackcollapse-perf.pl | FlameGraph-master/flamegraph.pl > cs.svg

最终生成的上下文切换火焰图：

观察上述火焰图，主要可分为以下三大块

sun/nio/ch/EPollArrayWrapper:::epollWait：用于监视多个文件描述符，看是否有文件描述符就绪（例如读操作或写操作）。如果没有文件描述符就绪，调用 epollWait 的进程/线程将阻塞，直到有文件描述符就绪或者满足特定的超时条件。
**ip_finish_output：**ip_finish_output是Linux内核中的一个函数，用于处理网络数据包的发送。在数据包发送过程中，可能会涉及到硬件操作或者其他需要等待的操作，如等待网络接口的可用性，等待DMA操作完成等。这些操作可能需要一段时间才能完成。当调用ip_finish_output并且需要等待这些操作时，当前的进程可能会被挂起，操作系统会切换到其他可运行的进程，进行其他任务的处理。这就发生了一次上下文切换。
java/net/SocketInputStream:::socketRead0：当调用socketRead0时，如果没有数据可读，操作系统会将当前线程置于 "等待" 或 "阻塞" 状态，并将CPU的控制权交给其他的线程或进程，这就是所谓的上下文切换。

在做性能优化时，尽可能还是期望以最小的代价换取最大的性能提升，而当上下文切换主要发生在这三个地方，而不是一些例如锁争用等可优化的场景时，也就没有太大必要去深究是否存在优化空间了。

网络排查

网络协议栈中的统计信息，可以用 netstat 或者 ss ，来查看套接字、网络栈、网络接口以及路由表的信息。

接收队列（Recv-Q）和发送队列（Send-Q）通常应该是 0。当发现它们不是 0 时，说明有网络包的堆积发生。

当然还要注意，在不同套接字状态下，它们的含义不同。

当套接字处于连接状态（Established）时，Recv-Q 表示套接字缓冲还没有被应用程序取走的字节数（即接收队列长度）。而 Send-Q 表示还没有被远端主机确认的字节数（即发送队列长度）。

当套接字处于监听状态（Listening）时，Recv-Q 表示全连接队列的长度。而 Send-Q 表示全连接队列的最大长度。

通过watch "ss -tna | awk '{if ( $3 > 0) print$ 0}'" 指令，我们可以实时观察到发送队列的堆积情况：

State      Recv-Q Send-Q Local Address:Port               Peer Address:Port
LISTEN     0      128    xxxxxxxxxxx:xxxxx                     *:*
LISTEN     0      50           *:xxxx                     *:*
LISTEN     0      128          *:xxxx                     *:*
LISTEN     0      100    xxxxxxxxxxx:xxxxx                     *:*
LISTEN     0      10           *:xxxx                     *:*
ESTAB      0      11     xxxxxxxxxxx:xxxxx              xxxxxxxxxxx:xxxxx
ESTAB      0      11     xxxxxxxxxxx:xxxxx              xxxxxxxxxxx:xxxxx
ESTAB      0      11     xxxxxxxxxxx:xxxxx              xxxxxxxxxxx:xxxxx
ESTAB      0      11     xxxxxxxxxxx:xxxxx              xxxxxxxxxxx:xxxxx
ESTAB      0      21973  xxxxxxxxxxx:xxxxx              xxxxxxxxxxx:xxxxx

其中Send-Q列为21973的是GalyLog的日志接收端口，其接收速度赶不上发送的速度，造成了一定的堆积，这也基本符合上文所述。

数据层优化

前言

项目组数据库选用的是Tidb，服务端持久化框架为Mybatis，连接池选用Hikari，以下为线上环境配置：

"minimumIdle": 50,
"maximumPoolSize": 100,
"url": "jdbc:mysql://XXX?characterEncoding=utf8&autoReconnect=true&useSSL=true
&multiStatements=true&sessionVariables=wait_timeout=28800&sessionVariables=max_execution_time=300000",

关于Tidb的架构介绍可参考文档：docs.pingcap.com/zh/tidb/dev…

简单来说，Tidb可分为3部分：

TidbServer:SQL 层，对外暴露 MySQL 协议的连接 endpoint，负责接受客户端的连接，执行 SQL 解析和优化，最终生成分布式执行计划。TiDB Server 本身并不存储数据，只是解析 SQL，将实际的数据读取请求转发给底层的存储节点 TiKV（或 TiFlash）。
PD:整个 TiDB 集群的元信息管理模块，负责存储每个 TiKV 节点实时的数据分布情况和集群的整体拓扑结构，提供 TiDB Dashboard 管控界面，并为分布式事务分配事务 ID。
Tikv:负责存储数据，从外部看 TiKV 是一个分布式的提供事务的 Key-Value 存储引擎。存储数据的基本单位是 Region，每个 Region 负责存储一个 Key Range（从 StartKey 到 EndKey 的左闭右开区间）的数据，每个 TiKV 节点会负责多个 Region。

在初始压测中，Tidb Server首先到达了CPU瓶颈，其所需节点数是Tikv的两倍，直觉上存储引擎应该是负载更重的一方，带着这个疑点，着手对Tidb进行了分析

连接池参数优化

连接池.png

观察上面的火焰图，发现Update操作最终是走到了clientPrepareStatement方法，而该分支是在未开启预编译参数时走到，检查连接池的参数，果然未设置。回看Tidb的架构，TidbServer其职责之一就是执行SQL解析，开启useServerPrepStmts 参数，可以有效避免服务器重复解析的开销。

打开Cluster-TiDB-Summary->QPS By Instance监控面板

可以看到除了Query外，StmtPrepare,StmtExecute数量为0

注意，除useServerPrepStmts=true外，还需同时设置cachePrepStmts = true ，以避免客户端每次执行完后close 预处理语句，另外还需检查prepStmtCacheSqlLimit（即缓存预处理语句的最大长度）这个配置项是否设置得太小，在一些场景 SQL 的长度可能超过该配置，导致预处理 SQL 不能复用。

另外在火焰图中，我们又发现另一个疑点：

明明是Update操作，却附带执行了Query语句，翻看源码：

public boolean isReadOnly(boolean useSessionStatus) throws SQLException {
    if (useSessionStatus && !this.isClosed && versionMeetsMinimum(5, 6, 5) && !getUseLocalSessionState() && getReadOnlyPropagatesToServer()) {
        java.sql.Statement stmt = null;
        java.sql.ResultSet rs = null;

        try {
            try {
                stmt = getMetadataSafeStatement(this.sessionMaxRows);
                rs = stmt.executeQuery(versionMeetsMinimum(8, 0, 3) || (versionMeetsMinimum(5, 7, 20) && !versionMeetsMinimum(8, 0, 0))
                        ? "select @@session.transaction_read_only" : "select @@session.tx_read_only");
                if (rs.next()) {
                    return rs.getInt(1) != 0; // mysql has a habit of tri+ state booleans
                }
  ...省略
    return this.readOnly;
}

在Update操作时，会调用到上述方法查询数据库读写权限，此操作对我们来说是冗余的，翻看Tidb相关文档找到答案：

集成参数

通过监控可能会发现，虽然业务只向集群进行 insert 操作，却看到有很多多余的 select 语句。通常这是因为 JDBC 发送了一些查询设置类的 SQL 语句（例如 select @@session.transaction_read_only）。这些 SQL 对 TiDB 无用，推荐配置 useConfigs = maxPerformance 来避免额外开销。

useConfigs = maxPerformance 会包含一组配置，可查看 MySQL Connector/J 8.0 版本或 5.1 版本来确认当前 MySQL Connector/J 中 maxPerformance 包含的具体配置。

配置后查看监控，可以看到多余语句减少。

在加上预编译相关参数及useConfigs = maxPerformance后，我们进一步压测：

summary = 2587456 in 00:02:48 = 177413.4/s Avg:   369 Min:     6 Max:   341 Err:     0 (0.00%)summary + 483348 in 00:00:30 = 16111.6/s Avg:    48 Min:     6 Max:   287 Err:     0 (0.00%) Active: 800 Started: 800 Finished: 0
summary = 5392378 in 00:04:48 = 18605.5/s Avg:    36 Min:     6 Max:  1091 Err:     0 (0.00%)
summary + 218548 in 00:00:14 = 17087.4/s Avg:    36 Min:     6 Max:   306 Err:     0 (0.00%) Active: 0 Started: 800 Finished: 800
summary = 5577252 in 00:05:01 = 18499.0/s Avg:    36 Min:     6 Max:  1091 Err:     0 (0.00%)

QPS从15827.2提升到了18499.0/s，平均耗时从49降到了36，再次观察QPS By Instance面板中Query及StmtExecute命令的数量：

命令执行数量符合预期。另一方面，对比调整前后，Tidb的CPU使用率：

Tidb Cpu.png

基本每台TiDBServer的CPU使用率能降20%~30%左右，故尝试将TiDB资源数从6台缩容至3台，其压测结果基本相差无几。

总结

经过本次性能优化，服务端QPS从原先的6032.9/s提升到了18499.0/s，平均耗时从129下降到了36，性能提升200%+。所需TiDB Server资源数减半。

优化点汇总：

全异步日志+降级丢弃策略：提升40%
日志includeLocation、反射获取类型等制造的非必要异常：提升100%
过于频繁的JSON parse：提升20~30%
JDBC useServerPrepStmts=true&cachePrepStmts=true&useConfigs = maxPerformance：提升30~40%

[^]: 注：上述优化点的提升比例，是基于当时所处的环境下，通过QPS的提升量计算所得，如果将优化顺序进行调整，则提升比例将会有所不同。例如将全异步日志放在最后进行优化，其提升量将达到80%。

本次优化过程其实是走了一些弯路，而本报告则是按照我认为相对比较合理的一个排查思路来进行编写，重点还是在于分享性能压测及调优方面的一些思路、工具。

经过此次调优历程，个人觉得，在做性能优化时，有两点是较为关键的：一个是要建立整体系统性能的全局观，基础理论正是理解系统全局必备的核心内容；另一个则是要有足够的耐心，压测过程中，很多时候是会做一些无用功的，即便如此还是要不断地尝试，才能在某次观测中“撞”见有用的信息。

如有纰漏，还望指正。