前面了解了JVM提供的一些基础监控命令的用法，下面介绍一次线上项目出现QPS上不去的整个排查过程。

1 压测过程

压测的过程中是针对某一个接口，分布从3000线程，3500线程，4000线程进行压测，压测汇总结果如下：

线程数3000，总请求数180万，平均响应延时在559毫秒，最大响应时间在4472毫秒，99分为是814毫秒，qps为5280.931线程数3500，总请求数210万，平均响应延时在626毫秒，最大响应时间在4607毫秒，99分为是1006毫秒，qps为5466.6线程数4000，总请求数240万，平均响应延时在740毫秒，最大响应时间在5029毫秒，99分为是1113毫秒，qps为5320.776

压测机器和服务部署机器配置：

40核128G内存

从上面的压测过程来看，接口耗时严重，且线程数增加QPS增加不明显，同时查询的基本逻辑上很简单，因此压测的结果和预期不一致，需要进一步排查整体的性能瓶颈(导致服务卡顿的原因)。

2 排查分析过程

从上面来看，机器的CPU为40核，内存为128G。因此初步看应该不是这两个维度造成的性能上不去。分析过程整理：

1 压测过程中分析内存，CPU查看是否因这两个维度导致的(虽然是40核128G，但是需要看是否是内存设置的问题，或者是服务中有耗CPU的计算)2 查看网络问题，排查是否因为网络上的性能问题3 拉线程栈，排查锁竞争(死锁和死循环等线上服务应该是卡主，不会是以内有较高的流量)4 从锁竞争开始排查问题5 不断调优参数，分析测试结果

压测接口的整体逻辑：

1 拦截器中拦截接口进行权限校验2 走数据库中查询数据，如果数据查询正常，则将数据写入到缓存中，下次查询直接查询缓存，缓存命中后，则直接吐数据3 针对接口进行相应结果的字段筛减后包装结果突出

2.1 CPU问题排查

top的问题排查，基本上先看CPU具体使用情况和系统负载：

以上截图是整理文档时的截图非压测时的截图。

top - 20:27:20 up 465 days, 52 min, 1 user, load average: 0.29, 0.37, 0.51

以上为第一行的内容，表示的是当前命令执行时间，系统运行时间，登录用户数，系统最近5，10，15分钟的平均负载。

%Cpu0 : 0.3 us, 0.0 sy, 0.0 ni, 99.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st

第三行开始，表示每一个单核CPU的用户空间占用CPU的百分比，内核空间占用CPU的百分比，改变过优先级的进程占用CPU的百分比，空闲CPU百分比，IO等待占用CPU的百分比，硬中断（Hardware IRQ）占用CPU的百分比，软中断（Software Interrupts）占用CPU的百分比

在压测过程中，通过top命令排查CPU使用率不超过20%，负载很低。

2.2 网络问题排查

CPU的占用不高的情况下，查看一下是否因为网络带宽使用情况，网络的使用情况排查，使用命令：iftop。iftop可以用来监控网卡的实时流量（可以指定网段）、反向解析IP、显示端口信息等，详细的将会在后面的使用参数中说明

通过截图来看入站和出站流量，其中Tx表示出站流量，Rx表示入站流量。在压测时，网络流量在入站34M/s，出站在23M/s左右。由于压测机器和服务机器，线上依赖的存储机器之间都是万兆网络，网络远远没有达到上限

2.3 内存问题排查

CPU，网络占用不高的情况下，后续看了一下系统内存使用情况，线上机器是多服务混部的情况，使用命令：

本次内存等截图均为事后截图，当时压测内容的流程有限。总体内存使用并不高。需要看一下当前服务的启动参数配置

41864 jar -Djava.security.egd=file:/dev/urandom -Dserver.port=xxxx -Dspring.profiles.active=pro -Dlogging.path=xxxxxx -Xms8G -Xmx8G -XX:+UseG1GC -XX:MetaspaceSize=512M -XX:MaxMetaspaceSize=512M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+HeapDumpOnOutOfMemoryError -XX:+DisableExplicitGC -verbose:gc -Xloggc:xxxxx/gc.out.log -XX:ErrorFile=xxxxxx/hs_err_pid.log

参数说明：

java.security.egd： 随机数发生器-Xms 堆内存最小值-Xmx 堆内存最大值-XX：+UseG1GC 使用G1垃圾回收器-XX:+HeapDumpOnOutOfMemoryError 当放生OOM时，打印向堆栈信息-XX:+DisableExplicitGC 禁止代码中显示调用GC-verbose:gc 在控制台输出GC情况

查看GC情况

通过命令在压测过程中进行排查GC情况，GC查看命令为：

jstat -gc xxxx 1 30

表示每隔1s收集一下GC的情况，共计查询30次。针对压测时的情况分析，老年代暂用较低，新生代GC次数并不频繁。因此内存上的问题基本排除。

2.4 代码问题排查

基本上外网的依赖和环境因素都排除后，基本上是可以明确一定是服务上的问题了，因此先需要排查是否有锁竞争。拉取线上压测是抓取其中某一时刻的线程栈下来进行分析：

jstack xxx > test.log

将线程栈导出后，拉到本地进行分析。发现线程栈中的问题：

"http-nio-7016-exec-1922" #2017 daemon prio=5 os_prio=0 tid=0x00007f48003af000 nid=0x5200 waiting on condition [0x00007f463f4f3000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000003c2e47a10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103) at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:745)"http-nio-7016-exec-1921" #2016 daemon prio=5 os_prio=0 tid=0x00007f47fc3db800 nid=0x51ff waiting on condition [0x00007f463f5f4000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000003c2e47a10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103) at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:745)

线程栈中的部分内容中如上，可以看到有大量的 parking to wait for <0x00000003c2e47a10>。经过分析后发现，这个是从tomcat中的等待队列中等待获取线程执行请求。因此可能出现的瓶颈问题是在这里，也就是说配置中配置的tomcat连接数太少，导致请求阻塞。但是如果问题是出现在这里，那么最小能够吞吐的量也是现实配置的tomcat线程最小值，48核的线上服务器，处理2000-2400线程应该是可以的(这个经验值，基本上单核处理50线程基本差不多了)。也就是可能是因为压测线程太多，有请求排队，这个也是正常现象，如果都没有堵塞的话，QPS也不会是这个值了。

继续对当前拉下来的线程栈进行分析，发现如下问题：

"http-nio-7016-exec-2694" #2789 daemon prio=5 os_prio=0 tid=0x00007f47fc3f8800 nid=0x1484e waiting on condition [0x00007f463fefb000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000003c0619398> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199) at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209) at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210) at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421) at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:414) at ch.qos.logback.classic.Logger.trace(Logger.java:433) ......

出现大量的：parking to wait for <0x00000003c0619398> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

排查一下具体的代码层问题：

整个代码中有同步代码块和加锁操作。这个是日志的追加写的过程。也就是打日志了。分析代码排查原因。发现原打日志中，使用了切面统计接口方法耗时，同时针对每个请求都将请求入职打印出来了。是否是因为打印日志的同步追加写入，多线程竞争锁导致的。因此将其中的logback的日志文件的写入调整为了异步过程，具体实现如下：

<appender name="asyncRequestAppender" class="ch.qos.logback.classic.AsyncAppender"> <discardingThreshold>0</discardingThreshold> <queueSize>40960</queueSize> <appender-ref ref ="requestAppender" /> </appender>

调整后，在基于上面的请求排队堵塞的问题，这次采用1000线程进行压测，效果极佳，压测结果：

线程数:1000 平均响应时间:47.9938225 90%响应时间不超过:8.0 最大响应耗时:7045 平均吞吐量:14749.5753841

这次调整后，QPS上升明显。

2.5 代码问题持续排查

从上面的结果看，最大响应耗时可以达到7s。这个对于接口服务来说是不可忍受的，虽然从整体看，这个最大耗时是个别异常点导致的，这个也需要排查。

再次进行压测，观察整个持续压测过程每个方法的耗时，评估可能发生的异常点。这里排查使用的是arthas。阿里的一套开源工具，用于支持线上故障分析。基础的使用这里就不赘述了。从某个请求开始到结束的整个链路中进行观察具体的请求耗时情况：

trace com.xxxxxController getxxxxx '#cost > 50'

trace是基础的监控工具，可以排查监控的包和方法。上面这个命令的意思是：将方法耗时大于100ms的方法调用链路打出来。经过排查发现：有一个方法耗存在耗时大于100ms的方法。这个命令的简答使用如下：

单个方法的耗时后，通过在代码中最加日志的方法发现，是因为有一个for循环，for循环中执行字段驼峰转换，这个驼峰转换，在第一转换时普遍存在耗时大，在进行for循环，将耗时累加后，外层方法的耗时就上去了。由于针对的是一个接口，因此接口吐的数据结构和字段数据在第一次和之后是一致的。这里类似于数据预热。第一次耗时严重。不过初步分析后，这里的耗时第一次基本在60-70ms左右。对整体的影响并不大，最大耗时严重基本排除是这个原因。

继续分析接口耗时的问题，统计耗时超过100ms的方法，发现从缓存中拉取数据耗时有时可以达到1s以上，初步的一个问题点找到。可能是这里有问题。分析代码：

return redisTemplate.execute(connection -> { RedisSerializer<String> serializer = new StringRedisSerializer(); byte[] value = connection.get(xxxxx); if (Objects.isNull(value) || value.length == 0) { return null; } return xxxxxxx });

这段代码初步看应该是没有什么问题的，将这个代码持续跟进后，源码如下：

public <T> T execute(RedisCallback<T> action, boolean exposeConnection, boolean pipeline) { Assert.isTrue(initialized, "template not initialized; call afterPropertiesSet() before using it"); Assert.notNull(action, "Callback object must not be null"); RedisConnectionFactory factory = getConnectionFactory(); RedisConnection conn = null; try { if (enableTransactionSupport) { // only bind resources in case of potential transaction synchronization conn = RedisConnectionUtils.bindConnection(factory, enableTransactionSupport); } else { conn = RedisConnectionUtils.getConnection(factory); } boolean existingConnection = TransactionSynchronizationManager.hasResource(factory); RedisConnection connToUse = preProcessConnection(conn, existingConnection); boolean pipelineStatus = connToUse.isPipelined(); if (pipeline && !pipelineStatus) { connToUse.openPipeline(); } RedisConnection connToExpose = (exposeConnection ? connToUse : createRedisConnectionProxy(connToUse)); T result = action.doInRedis(connToExpose); // close pipeline if (pipeline && !pipelineStatus) { connToUse.closePipeline(); } // TODO: any other connection processing? return postProcessResult(result, connToUse, existingConnection); } finally { RedisConnectionUtils.releaseConnection(conn, factory); } }

在这个代码中，exposeConnection为false的话，会创建一个代理类，经过拉线程栈发现，这个地方存在并发锁问题。这个是否使用代理类，是为了安全，保护当前的连接是否暴露到回调函数中，这个对于代码来说，这个可以忽略，代码调整为：

return redisTemplate.execute(connection -> { RedisSerializer<String> serializer = new StringRedisSerializer(); byte[] value = connection.get(xxxxx); if (Objects.isNull(value) || value.length == 0) { return null; } return xxxxxxx },true); //=> 这里多了一个参数

调整后，再次压测，性能应持续到

线程数:1000 平均响应时间:42.09 90%响应时间不超过:13 最大响应耗时:3297 平均吞吐量:17528.069

2.6 代码问题再排查

线上最大的相应耗时有降低，但是还是有将近3s的大小，继续排查最大响应耗时，这时继续使用arthas来分析，继续抓耗时严重的方法，发现还是从缓存中获取数据的方法均存在一定是的耗时严重的问题，初步的猜测：

1 连接数的问题，导致竞争2 代码中有共同点，同时这个共同点有竞争导致

redis的连接数的优化，这个是频繁的调试压测来分析，初步的压测过程是：

1000 redis连接数 19749 QPS2000 redis连接数 15610 QPS500 redis连接数 19552 QPS

初步将redis的最大连接数设置为1000后，还是存在相应耗时严重的问题，那么是否是有共同点导致的。初步核对代码发现：这些代码中均从缓存中拉去数据，数据对应的key为加密值。也就是说根据相应的参数构造一个加密的key，根据这个key去redis中取数据。是否是因为加密这里导致的，这个拉取线程栈的过程很辛苦，线程栈很长很大，没有block的地址。于是乎采用另外一种方式来分析系统性能问题 - 火焰图

火焰图的生成过程：

先将生成火焰图的一套脚本下载下来，找到一个目录后将其脚本clone下来，具体的命令是

git clone 

插件下来后，使用perf生成火焰图，生成火焰图前，需要监控系统时间，采集CPU调用的函数和调用栈的情况，具体的命令为：

sudo perf record -F 99 -p xxxxxx -g -- sleep 120

perf record 表示采集系统事件, 没有使用 -e 指定采集事件, 则默认采集 cycles(即 CPU clock 周期), -F 99 表示每秒 99 次, -p xxx 是进程号, 即对哪个进程进行分析, -g 表示记录调用栈, sleep 120 则是持续 120 秒

下面开始生成火焰图

perf script > out.perfFlameGraph/stackcollapse-perf.pl out.perf > out.foldedFlameGraph/flamegraph.pl out.folded > cpu.svg

将火焰图打开后如下：

整个火焰图上缺少了明显的java中方法名，火焰图是很厉害的一个工具，没怎能用过这个，分析起来有些无从下手，有兴趣可以自己去多找找资料学习下。这里有平顶的地方就是有系统瓶颈点。这里初步看有三个比较明显的地方。

由于能力有限，火焰图的分析卡住了，继续拉取线程栈和持续使用arthas分析堵塞线程，终于有所发现，存在少量的locked sun.security.provider.Sun。经过排查后，发现缓存读取的地方都使用了加密算法，而加密算法使用的是sha加密的，这里sha加密需要使用的SecureRandom这个类。

这个类是用于生成可靠随机数的，这个在大量产生随机数的场景下，性能会较低(这里来源于搜索出来的)，为了验证这个问题，需要将所有缓存key的随机加密调整一下，将加密去掉验证QPS，同时在验证一下对应的火焰图。

本次压测后续还要继续，随机加密的这个未验证。

3 总结和思考

新能问题可能出现的点:

1 锁竞争导致的，现在内存和网络CPU等基本上对于一下小流量应用不存在瓶颈点2 各种连接池的配置调整，导致的资源竞争3 错误的参数和启动参数配置导致

这里没有对JVM内存进行调整，这里可以适当调整年轻代对应的大小，减少GC的次数，降低停顿时间。