如何讓接口吞吐量提升10多倍
公司的一個ToB系統，因為客戶使用的也不多，沒啥并發要求，就一直沒有經過壓測。這兩天來了一個“大客戶”，對并發量提出了要求：核心接口與幾個重點使用場景單節點吞吐量要滿足最低500/s的要求。
當時一想，500/s吞吐量還不簡單。Tomcat按照100個線程，那就是單線程1S內處理5個請求，200ms處理一個請求即可。這個沒有問題，平時接口響應時間大部分都100ms左右，還不是分分鐘滿足的事情。
然而壓測一開，100 的并發，吞吐量居然只有 50 ...
而且再一查，100的并發，CPU使用率居然接近 80% ...
從上圖可以看到幾個重要的信息。
最小值： 表示我們非并發場景單次接口響應時長。還不足100ms。挺好!
最大值： 并發場景下，由于各種鎖或者其他串行操作，導致部分請求等待時長增加，接口整體響應時間變長。5秒鐘。有點過分了！！！
再一看百分位，大部分的請求響應時間都在4s。無語了！！！
所以 1s鐘的 吞吐量 單節點只有 50 。距離 500 差了10倍。 難受！！！！
分析過程
定位“慢”原因
?
這里暫時先忽略 CPU 占用率高的問題
?
首先平均響應時間這么慢，肯定是有阻塞。先確定阻塞位置。重點檢查幾處：
鎖 (同步鎖、分布式鎖、數據庫鎖)
耗時操作 (鏈接耗時、SQL耗時)
結合這些先配置耗時埋點。
接口響應時長統計。超過500ms打印告警日志。
接口內部遠程調用耗時統計。200ms打印告警日志。
Redis訪問耗時。超過10ms打印告警日志。
SQL執行耗時。超過100ms打印告警日志。
上述配置生效后，通過日志排查到接口存在慢SQL。具體SQL類似與這種：
updatetablesetfield=field-1wheretype=1andfiled>1;
上述SQL相當于并發操作同一條數據，肯定存在鎖等待。日志顯示此處的等待耗時占接口總耗時 80% 以上。
二話不說先改為敬。因為是壓測環境，直接改為異步執行，確認一下效果。
?
PS：當時心里是這么想的： 妥了，大功告成。就是這里的問題！絕壁是這個原因！優化一下就解決了。當然，如果這么簡單就沒有必要寫這篇文章了...
?
優化后的效果：
嗯...
emm...
好！ 這個優化還是很明顯的，提升提升了近2倍。
此時已經感覺到有些不對了，慢SQL已經解決了（異步了~ 隨便吧~ 你執行 10s我也不管了），雖然對吞吐量的提升沒有預期的效果。但是數據是不會騙人的。
最大值： 已經從 5s -> 2s
百分位值： 4s -> 1s
這已經是很大的提升了。
繼續定位“慢”的原因
通過第一階段的“優化”，我們距離目標近了很多。廢話不多說，繼續下一步的排查。
我們繼續看日志，此時日志出現類似下邊這種情況：
2023-01-041505:347INFO**.**.**.***.50[TID:1s22s72s8ws9w00]********************** 2023-01-041505:348INFO**.**.**.***.21[TID:1s22s72s8ws9w00]********************** 2023-01-041505:350INFO**.**.**.***.47[TID:1s22s72s8ws9w00]********************** 2023-01-041505:465INFO**.**.**.***.234[TID:1s22s72s8ws9w00]********************** 2023-01-041505:467INFO**.**.**.***.123[TID:1s22s72s8ws9w00]********************** 2023-01-041505:581INFO**.**.**.***.451[TID:1s22s72s8ws9w00]********************** 2023-01-041505:702INFO**.**.**.***.72[TID:1s22s72s8ws9w00]**********************
前三行info日志沒有問題，間隔很小。第4 ~ 第5，第6 ~ 第7，第7 ~ 第8 很明顯有百毫秒的耗時。檢查代碼發現，這部分沒有任何耗時操作。那么這段時間干什么了呢？
發生了線程切換，換其他線程執行其他任務了。(線程太多了)
日志打印太多了，壓測5分鐘日志量500M。（記得日志打印太多是有很大影響的）
STW。（但是日志還在輸出，所以前兩種可能性很高，而且一般不會停頓百毫秒）
按照這三個思路做了以下操作：
首先，提升日志打印級別到DEBUG。emm... 提升不大，好像增加了10左右。
然后，拆線程 @Async 注解使用線程池，控制代碼線程池數量（之前存在3個線程池，統一配置的核心線程數為100）結合業務，服務總核心線程數控制在50以內，同步增加阻塞最大大小。結果還可以，提升了50，接近200了。
最后，觀察JVM的GC日志，發現YGC頻次4/s，沒有FGC。1分鐘內GC時間不到1s，很明顯不是GC問題，不過發現JVM內存太小只有512M，直接給了4G。吞吐量沒啥提升，YGC頻次降低為2秒1次。
唉，一頓操作猛如虎。
?
PS：其實中間還對數據庫參數一通瞎搞，這里不多說了。
?
其實也不是沒有收獲，至少在減少服務線程數量后還是有一定收獲的。
另外，已經關注到了另外一個點：CPU使用率，減少了線程數量后，CPU的使用率并沒有明顯的下降，這里是很有問題的，當時認為CPU的使用率主要與開啟的線程數量有關，之前線程多，CPU使用率較高可以理解。但是，在砍掉了一大半的線程后，依然居高不下這就很奇怪了。
此時關注的重點開始從代碼“慢”方向轉移到“CPU高”方向。
定位CPU使用率高的原因
CPU的使用率高，通常與線程數相關肯定是沒有問題的。當時對居高不下的原因考慮可能有以下兩點：
有額外的線程存在。
代碼有部分CPU密集操作。
然后繼續一頓操作：
觀察服務活躍線程數。
觀察有無CPU占用率較高線程。
在觀察過程中發現，沒有明顯CPU占用較高線程。所有線程基本都在10%以內。類似于下圖，不過有很多線程。
沒有很高就證明大家都很正常，只是多而已...
此時沒有下一步的排查思路了。當時想著,算了打印一下堆棧看看吧，看看到底干了啥~
在看的過程中發現這段日志：
"http-nio-6071-exec-9"#82daemonprio=5os_prio=0tid=0x00007fea9aed1000nid=0x62runnable[0x00007fe934cf4000] java.lang.Thread.State:RUNNABLE atorg.springframework.core.annotation.AnnotationUtils.getValue(AnnotationUtils.java:1058) atorg.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.resolveExpression(AbstractAspectJAdvisorFactory.java:216) atorg.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.
上邊的堆棧發現了一個點： 在執行getBean的時候，執行了createBean方法。我們都知道Spring托管的Bean都是提前實例化好放在IOC容器中的。createBean要做的事情有很多，比如Bean的初始化，依賴注入其他類，而且中間還有一些前后置處理器執行、代理檢查等等，總之是一個耗時方法，所以都是在程序啟動時去掃描，加載，完成Bean的初始化。
而我們在運行程序線程堆棧中發現了這個操作。而且通過檢索發現竟然有近200處。
通過堆棧信息很快定位到執行位置：
RedisToolredisTool=BeanUtils.getBean(RedisMaster.class);
而RedisMaster類
@Component @Scope("prototype") publicclassRedisMasterimplementsIRedisTool{ //...... }
沒錯就是用了多例。而且使用的地方是Redis（系統使用Jedis客戶端，Jedis并非線程安全，每次使用都需要新的實例），接口對Redis的使用還是比較頻繁的，一個接口得有10次左右獲取Redis數據。也就是說執行10次左右的createBean邏輯 ...
嘆氣！！！
趕緊改代碼，直接使用萬能的 new 。
在看結果之前還有一點需要提一下，由于系統有大量統計耗時的操作。實現方式是通過：
longstart=System.currentTimeMillis(); //...... longend=System.currentTimeMillis(); longrunTime=start-end;
或者Hutool提供的StopWatch：
這里感謝一下huoger 同學的評論，當時還誤以為該方式能夠降低性能的影響，但是實際上也只是一層封裝。底層使用的是 System.nanoTime()。
StopWatchwatch=newStopWatch(); watch.start(); //...... watch.stop(); System.out.println(watch.getTotalTimeMillis());
而這種在并發量高的情況下，對性能影響還是比較大的，特別在服務器使用了一些特定時鐘的情況下。這里就不多說，感興趣的可以自行搜索一下。
最終結果：
排查涉及的命令如下：
查詢服務進程CPU情況： top–Hp pid
查詢JVM GC相關參數：jstat -gc pid 2000 (對 pid [進程號] 每隔 2s 輸出一次日志)
打印當前堆棧信息： jstack -l pid >> stack.log
總結
結果是好的，過程是曲折的。總的來說還是知識的欠缺，文章看起來還算順暢，但都是事后諸葛亮，不對，應該是時候臭皮匠。基本都是邊查資料邊分析邊操作，前后花費了4天時間，嘗試了很多。
「Mysql :」Buffer Pool 、Change Buffer 、Redo Log 大小、雙一配置...
「代碼 :」異步執行，線程池參數調整，tomcat 配置，Druid連接池配置...
「JVM :」內存大小，分配，垃圾收集器都想換...
總歸一通瞎搞，能想到的都試試。
后續還需要多了解一些性能優化知識，至少要做到排查思路清晰，不瞎搞。
最后5行代碼有哪些：
「new Redis實例：」1
「耗時統計：」3
「SQL異步執行 @Async：」1
上圖最終的結果是包含該部分的，時間原因未對SQL進行處理，后續會考慮Redis原子操作+定時同步數據庫方式來進行，避免同時操數據庫
TODO
問題雖然解決了。但是原理還不清楚，需要繼續深挖。
「為什么createBean對性能影響這么大？」
如果影響這么大，Spring為什么還要有多例？
首先非并發場景速度還是很快的。這個毋庸置疑。畢竟接口響應時間不足50ms。
所以問題一定出在，并發createBean同一對象的鎖等待場景。根據堆棧日志，翻了一下Spring源碼，果然發現這里出現了同步鎖。相信鎖肯定不止一處。
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory#doCreateBean
「System.currentTimeMillis并發度多少才會對性能產生影響，影響有多大？」
很多公司（包括大廠）在業務代碼中，還是會頻繁的使用System.currentTimeMillis獲取時間戳。比如：時間字段賦值場景。所以，性能影響肯定會有，但是影響的門檻是不是很高。
「繼續學習性能優化知識」
吞吐量與什么有關？
首先，接口響應時長。直接影響因素還是接口響應時長，響應時間越短，吞吐量越高。一個接口響應時間100ms,那么1s就能處理10次。
其次，線程數。現在都是多線程環境，如果同時10個線程處理請求，那么吞吐量又能增加10倍。當然由于CPU資源有限，所以線程數也會受限。理論上，在 CPU 資源利用率較低的場景，調大tomcat線程數，以及并發數，能夠有效的提升吞吐量。
最后，高性能代碼。無論接口響應時長，還是 CPU 資源利用率，都依賴于我們的代碼，要做高性能的方案設計，以及高性能的代碼實現，任重而道遠。
CPU使用率的高低與哪些因素有關？
CPU使用率的高低，本質還是由線程數，以及CPU使用時間決定的。
假如一臺10核的機器，運行一個單線程的應用程序。正常這個單線程的應用程序會交給一個CPU核心去運行，此時占用率就是10%。而現在應用程序都是多線程的，因此一個應用程序可能需要全部的CPU核心來執行，此時就會達到100%。
此外，以單線程應用程序為例，大部分情況下，我們還涉及到訪問Redis/Mysql、RPC請求等一些阻塞等待操作，那么CPU就不是時刻在工作的。
所以阻塞等待的時間越長，CPU利用率也會越低。也正是因為如此，為了充分的利用CPU資源，多線程也就應運而生（一個線程雖然阻塞了，但是CPU別閑著，趕緊去運行其他的線程）。
一個服務線程數在多少比較合適（算上Tomcat，最終的線程數量是226），執行過程中發現即使tomcat線程數量是100，活躍線程數也很少超過50，整個壓測過程基本維持在20左右。
作者：FishBones
編輯：何安
-
代碼
+關注
關注
30文章
4779瀏覽量
68524 -
后端
+關注
關注
0文章
31瀏覽量
2234
原文標題：高端操作，只改了五行代碼接口吞吐量提升了10多倍
文章出處：【微信號：AndroidPush，微信公眾號：Android編程精選】歡迎添加關注！文章轉載請注明出處。
發布評論請先 登錄
相關推薦
如何提高CYBT-243053-02吞吐量？
網卡吞吐量測試解決方案
iperf固定吞吐量測試如何設置
USB CDC吞吐量問題
debug 吞吐量的辦法
debug 吞吐量的辦法
如何顯著提高ATE電源吞吐量？
影響ATE電源系統吞吐量的關鍵因素
工商網監
評論