前面瞭解了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的日誌文件的寫入調整為了異步過程，具體實現如下：
0 40960
調整後，在基於上面的請求排隊堵塞的問題，這次採用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 serializer = new StringRedisSerializer();
byte[] value = connection.get(xxxxx);
if (Objects.isNull(value) || value.length == 0) { return null; }
return xxxxxxx
});這段代碼初步看應該是沒有什麼問題的，將這個代碼持續跟進後，源碼如下：
public T execute(RedisCallback 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 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 QPS 2000 redis連接數 15610 QPS 500 redis連接數 19552 QPS
初步將redis的最大連接數設置為1000後，還是存在相應耗時嚴重的問題，那麼是否是有共同點導致的。初步核對代碼發現：這些代碼中均從緩存中拉去數據，數據對應的key為加密值。也就是說根據相應的參數構造一個加密的key，根據這個key去redis中取數據。是否是因為加密這裡導致的，這個拉取線程棧的過程很辛苦，線程棧很長很大，沒有block的地址。於是乎採用另外一種方式來分析系統性能問題 - 火焰圖
火焰圖的生成過程：
先將生成火焰圖的一套腳本下載下來，找到一個目錄後將其腳本clone下來，具體的命令是
git clone https://github.com/brendangregg/FlameGraph.git
插件下來後，使用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>將火焰圖打開後如下：
整個火焰圖上缺少了明顯的java中方法名，火焰圖是很厲害的一個工具，沒怎能用過這個，分析起來有些無從下手，有興趣可以自己去多找找資料學習下。這裡有平頂的地方就是有系統瓶頸點。這裡初步看有三個比較明顯的地方。
由於能力有限，火焰圖的分析卡住了，繼續拉取線程棧和持續使用arthas分析堵塞線程，終於有所發現，存在少量的locked sun.security.provider.Sun。經過排查後，發現緩存讀取的地方都使用了加密算法，而加密算法使用的是sha加密的，這裡sha加密需要使用的SecureRandom這個類。
這個類是用於生成可靠隨機數的，這個在大量產生隨機數的場景下，性能會較低(這裡來源於搜索出來的)，為了驗證這個問題，需要將所有緩存key的隨機加密調整一下，將加密去掉驗證QPS，同時在驗證一下對應的火焰圖。
本次壓測後續還要繼續，隨機加密的這個未驗證。
3 總結和思考
新能問題可能出現的點:
1 鎖競爭導致的，現在內存和網絡CPU等基本上對於一下小流量應用不存在瓶頸點 2 各種連接池的配置調整，導致的資源競爭 3 錯誤的參數和啟動參數配置導致這裡沒有對JVM內存進行調整，這裡可以適當調整年輕代對應的大小，減少GC的次數，降低停頓時間。
