作者:FishBones 鏈接:https://juejin.cn/post/7185479136599769125 背景 公司的一個ToB系統,因為客戶使用的也不多,沒啥併發要求,就一直沒有經過壓測。這兩天來了一個“大客戶”,對併發量提出了要求:核心介面與幾個重點使用場景單節點吞吐量要滿足最低50 ...
作者:FishBones
鏈接:https://juejin.cn/post/7185479136599769125
背景
公司的一個ToB系統,因為客戶使用的也不多,沒啥併發要求,就一直沒有經過壓測。這兩天來了一個“大客戶”,對併發量提出了要求:核心介面與幾個重點使用場景單節點吞吐量要滿足最低500/s的要求。
當時一想,500/s吞吐量還不簡單。Tomcat按照100個線程,那就是單線程1S內處理5個請求,200ms處理一個請求即可。這個沒有問題,平時介面響應時間大部分都100ms左右,還不是分分鐘滿足的事情。
然而壓測一開,100 的併發,吞吐量居然只有 50 ...
而且再一查,100的併發,CPU使用率居然接近 80% ...
從上圖可以看到幾個重要的信息。
最小值: 表示我們非併發場景單次介面響應時長。還不足100ms。挺好!
最大值: 併發場景下,由於各種鎖或者其他串列操作,導致部分請求等待時長增加,介面整體響應時間變長。5秒鐘。有點過分了!!!
再一看百分位,大部分的請求響應時間都在4s。無語了!!!
所以 1s鐘的 吞吐量 單節點只有 50 。距離 500 差了10倍。 難受!!!!
推薦一個開源免費的 Spring Boot 實戰項目:
分析過程
定位“慢”原因
這裡暫時先忽略 CPU 占用率高的問題
首先平均響應時間這麼慢,肯定是有阻塞。先確定阻塞位置。重點檢查幾處:
- 鎖 (同步鎖、分散式鎖、資料庫鎖)
- 耗時操作 (鏈接耗時、SQL耗時)
結合這些先配置耗時埋點。
- 介面響應時長統計。超過500ms列印告警日誌。
- 介面內部遠程調用耗時統計。200ms列印告警日誌。
- Redis訪問耗時。超過10ms列印告警日誌。
- SQL執行耗時。超過100ms列印告警日誌。
上述配置生效後,通過日誌排查到介面存在慢SQL。具體SQL類似與這種:
<!-- 主要類似與庫存扣減 每次-1 type 只有有限的幾種且該表一共就幾條數據(一種一條記錄)-->
<!-- 壓測時可以認為 type = 1 是寫死的 -->
update table set field = field - 1 where type = 1 and filed > 1;
上述SQL相當於併發操作同一條數據,肯定存在鎖等待。日誌顯示此處的等待耗時占介面總耗時 80% 以上。
二話不說先改為敬。因為是壓測環境,直接先改為非同步執行,確認一下效果。
PS:當時心裡是這麼想的: 妥了,大功告成。就是這裡的問題!絕壁是這個原因!優化一下就解決了。當然,如果這麼簡單就沒有必要寫這篇文章了...
優化後的效果:
嗯...
emm...
好! 這個優化還是很明顯的,提升提升了近2倍。
此時已經感覺到有些不對了,慢SQL已經解決了(非同步了~ 隨便吧~ 你執行 10s我也不管了),雖然對吞吐量的提升沒有預期的效果。但是數據是不會騙人的。
最大值: 已經從 5s -> 2s
百分位值: 4s -> 1s
這已經是很大的提升了。
繼續定位“慢”的原因
通過第一階段的“優化”,我們距離目標近了很多。廢話不多說,繼續下一步的排查。
我們繼續看日誌,此時日誌出現類似下邊這種情況:
2023-01-04 15:17:05:347 INFO **.**.**.***.50 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:348 INFO **.**.**.***.21 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:350 INFO **.**.**.***.47 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:465 INFO **.**.**.***.234 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:467 INFO **.**.**.***.123 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:581 INFO **.**.**.***.451 [TID: 1s22s72s8ws9w00] **********************
2023-01-04 15:17:05:702 INFO **.**.**.***.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:其實中間還對資料庫參數一通瞎搞,這裡不多說了。
推薦一個開源免費的 Spring Boot 實戰項目:
其實也不是沒有收穫,至少在減少服務線程數量後還是有一定收穫的。另外,已經關註到了另外一個點:CPU使用率,減少了線程數量後,CPU的使用率並沒有明顯的下降,這裡是很有問題的,當時認為CPU的使用率主要與開啟的線程數量有關,之前線程多,CPU使用率較高可以理解。但是,在砍掉了一大半的線程後,依然居高不下這就很奇怪了。
此時關註的重點開始從代碼“慢”方向轉移到“CPU高”方向。
定位CPU使用率高的原因
CPU的使用率高,通常與線程數相關肯定是沒有問題的。當時對居高不下的原因考慮可能有以下兩點:
- 有額外的線程存在。
- 代碼有部分CPU密集操作。
然後繼續一頓操作:
- 觀察服務活躍線程數。
- 觀察有無CPU占用率較高線程。
在觀察過程中發現,沒有明顯CPU占用較高線程。所有線程基本都在10%以內。類似於下圖,不過有很多線程。
沒有很高就證明大家都很正常,只是多而已...
此時沒有下一步的排查思路了。當時想著,算了列印一下堆棧看看吧,看看到底幹了啥~
在看的過程中發現這段日誌:
"http-nio-6071-exec-9" #82 daemon prio=5 os_prio=0 tid=0x00007fea9aed1000 nid=0x62 runnable [0x00007fe934cf4000]
java.lang.Thread.State: RUNNABLE
at org.springframework.core.annotation.AnnotationUtils.getValue(AnnotationUtils.java:1058)
at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.resolveExpression(AbstractAspectJAdvisorFactory.java:216)
at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory$AspectJAnnotation.<init>(AbstractAspectJAdvisorFactory.java:197)
at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAnnotation(AbstractAspectJAdvisorFactory.java:147)
at org.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAspectJAnnotationOnMethod(AbstractAspectJAdvisorFactory.java:135)
at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvice(ReflectiveAspectJAdvisorFactory.java:244)
at org.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.instantiateAdvice(InstantiationModelAwarePointcutAdvisorImpl.java:149)
at org.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.<init>(InstantiationModelAwarePointcutAdvisorImpl.java:113)
at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisor(ReflectiveAspectJAdvisorFactory.java:213)
at org.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisors(ReflectiveAspectJAdvisorFactory.java:144)
at org.springframework.aop.aspectj.annotation.BeanFactoryAspectJAdvisorsBuilder.buildAspectJAdvisors(BeanFactoryAspectJAdvisorsBuilder.java:149)
at org.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator.findCandidateAdvisors(AnnotationAwareAspectJAutoProxyCreator.java:95)
at org.springframework.aop.aspectj.autoproxy.AspectJAwareAdvisorAutoProxyCreator.shouldSkip(AspectJAwareAdvisorAutoProxyCreator.java:101)
at org.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.wrapIfNecessary(AbstractAutoProxyCreator.java:333)
at org.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.postProcessAfterInitialization(AbstractAutoProxyCreator.java:291)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsAfterInitialization(AbstractAutowireCapableBeanFactory.java:455)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1808)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:353)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:233)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean(DefaultListableBeanFactory.java:1282)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean(DefaultListableBeanFactory.java:1243)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveBean(DefaultListableBeanFactory.java:494)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBean(DefaultListableBeanFactory.java:349)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBean(DefaultListableBeanFactory.java:342)
at cn.hutool.extra.spring.SpringUtil.getBean(SpringUtil.java:117)
......
......
上邊的堆棧發現了一個點: 在執行getBean的時候,執行了createBean方法。我們都知道Spring托管的Bean都是提前實例化好放在IOC容器中的。createBean要做的事情有很多,比如Bean的初始化,依賴註入其他類,而且中間還有一些前後置處理器執行、代理檢查等等,總之是一個耗時方法,所以都是在程式啟動時去掃描,載入,完成Bean的初始化。
而我們在運行程式線程堆棧中發現了這個操作。而且通過檢索發現竟然有近200處。
推薦一個開源免費的 Spring Boot 實戰項目:
通過堆棧信息很快定位到執行位置:
<!--BeanUtils 是 hutool 工具類。也是從IOC容器獲取Bean 等價於 @Autowired 註解 -->
RedisTool redisTool = BeanUtils.getBean(RedisMaster.class);
而RedisMaster類
@Component
@Scope("prototype")
public class RedisMaster implements IRedisTool {
// ......
}
沒錯就是用了多例。而且使用的地方是Redis(系統使用Jedis客戶端,Jedis並非線程安全,每次使用都需要新的實例),介面對Redis的使用還是比較頻繁的,一個介面得有10次左右獲取Redis數據。也就是說執行10次左右的createBean邏輯 ...
嘆氣!!!
趕緊改代碼,直接使用萬能的 new 。
在看結果之前還有一點需要提一下,由於系統有大量統計耗時的操作。實現方式是通過:
long start = System.currentTimeMillis();
// ......
long end = System.currentTimeMillis();
long runTime = start - end;
或者Hutool提供的StopWatch:
這裡感謝一下huoger 同學的評論,當時還誤以為該方式能夠降低性能的影響,但是實際上也只是一層封裝。底層使用的是 System.nanoTime()。
StopWatch watch = new StopWatch();
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左右。
近期熱文推薦:
1.1,000+ 道 Java面試題及答案整理(2022最新版)
4.別再寫滿屏的爆爆爆炸類了,試試裝飾器模式,這才是優雅的方式!!
覺得不錯,別忘了隨手點贊+轉發哦!