公司的一個(gè)ToB系統(tǒng)，因?yàn)榭蛻?hù)使用的也不多，沒(méi)啥并發(fā)要求，就一直沒(méi)有經(jīng)過(guò)壓測(cè)。這兩天來(lái)了一個(gè)“大客戶(hù)”，對(duì)并發(fā)量提出了要求：核心接口與幾個(gè)重點(diǎn)使用場(chǎng)景單節(jié)點(diǎn)吞吐量要滿(mǎn)足最低500/s的要求。

當(dāng)時(shí)一想，500/s吞吐量還不簡(jiǎn)單。Tomcat按照100個(gè)線(xiàn)程，那就是單線(xiàn)程1S內(nèi)處理5個(gè)請(qǐng)求，200ms處理一個(gè)請(qǐng)求即可。這個(gè)沒(méi)有問(wèn)題，平時(shí)接口響應(yīng)時(shí)間大部分都100ms左右，還不是分分鐘滿(mǎn)足的事情。

然而壓測(cè)一開(kāi)，100 的并發(fā)，吞吐量居然只有 50 ...

而且再一查，100的并發(fā)，CPU使用率居然接近 80% ...

從上圖可以看到幾個(gè)重要的信息。

最小值： 表示我們非并發(fā)場(chǎng)景單次接口響應(yīng)時(shí)長(zhǎng)。還不足100ms。挺好!

最大值： 并發(fā)場(chǎng)景下，由于各種鎖或者其他串行操作，導(dǎo)致部分請(qǐng)求等待時(shí)長(zhǎng)增加，接口整體響應(yīng)時(shí)間變長(zhǎng)。5秒鐘。有點(diǎn)過(guò)分了?。?！

再一看百分位，大部分的請(qǐng)求響應(yīng)時(shí)間都在4s。無(wú)語(yǔ)了！?。?/p>

所以 1s鐘的 吞吐量 單節(jié)點(diǎn)只有 50 。距離 500 差了10倍。 難受！?。。?/p>

分析過(guò)程

定位“慢”原因

?

這里暫時(shí)先忽略 CPU 占用率高的問(wèn)題

?

首先平均響應(yīng)時(shí)間這么慢，肯定是有阻塞。先確定阻塞位置。重點(diǎn)檢查幾處：

鎖 (同步鎖、分布式鎖、數(shù)據(jù)庫(kù)鎖)

耗時(shí)操作 (鏈接耗時(shí)、SQL耗時(shí))

結(jié)合這些先配置耗時(shí)埋點(diǎn)。

接口響應(yīng)時(shí)長(zhǎng)統(tǒng)計(jì)。超過(guò)500ms打印告警日志。

接口內(nèi)部遠(yuǎn)程調(diào)用耗時(shí)統(tǒng)計(jì)。200ms打印告警日志。

Redis訪(fǎng)問(wèn)耗時(shí)。超過(guò)10ms打印告警日志。

SQL執(zhí)行耗時(shí)。超過(guò)100ms打印告警日志。

上述配置生效后，通過(guò)日志排查到接口存在慢SQL。具體SQL類(lèi)似與這種：

updatetablesetfield=field-1wheretype=1andfiled>1;

上述SQL相當(dāng)于并發(fā)操作同一條數(shù)據(jù)，肯定存在鎖等待。日志顯示此處的等待耗時(shí)占接口總耗時(shí) 80% 以上。

二話(huà)不說(shuō)先改為敬。因?yàn)槭菈簻y(cè)環(huán)境，直接改為異步執(zhí)行，確認(rèn)一下效果。

?

PS：當(dāng)時(shí)心里是這么想的： 妥了，大功告成。就是這里的問(wèn)題！絕壁是這個(gè)原因！優(yōu)化一下就解決了。當(dāng)然，如果這么簡(jiǎn)單就沒(méi)有必要寫(xiě)這篇文章了...

?

優(yōu)化后的效果：

嗯...

emm...

好！ 這個(gè)優(yōu)化還是很明顯的，提升提升了近2倍。

此時(shí)已經(jīng)感覺(jué)到有些不對(duì)了，慢SQL已經(jīng)解決了（異步了~ 隨便吧~ 你執(zhí)行 10s我也不管了），雖然對(duì)吞吐量的提升沒(méi)有預(yù)期的效果。但是數(shù)據(jù)是不會(huì)騙人的。

最大值： 已經(jīng)從 5s -> 2s

百分位值： 4s -> 1s

這已經(jīng)是很大的提升了。

繼續(xù)定位“慢”的原因

通過(guò)第一階段的“優(yōu)化”，我們距離目標(biāo)近了很多。廢話(huà)不多說(shuō)，繼續(xù)下一步的排查。

我們繼續(xù)看日志，此時(shí)日志出現(xiàn)類(lèi)似下邊這種情況：

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日志沒(méi)有問(wèn)題，間隔很小。第4 ~ 第5，第6 ~ 第7，第7 ~ 第8 很明顯有百毫秒的耗時(shí)。檢查代碼發(fā)現(xiàn)，這部分沒(méi)有任何耗時(shí)操作。那么這段時(shí)間干什么了呢？

發(fā)生了線(xiàn)程切換，換其他線(xiàn)程執(zhí)行其他任務(wù)了。(線(xiàn)程太多了)

日志打印太多了，壓測(cè)5分鐘日志量500M。（記得日志打印太多是有很大影響的）

STW。（但是日志還在輸出，所以前兩種可能性很高，而且一般不會(huì)停頓百毫秒）

按照這三個(gè)思路做了以下操作：

首先，提升日志打印級(jí)別到DEBUG。emm... 提升不大，好像增加了10左右。

然后，拆線(xiàn)程 @Async 注解使用線(xiàn)程池，控制代碼線(xiàn)程池?cái)?shù)量（之前存在3個(gè)線(xiàn)程池，統(tǒng)一配置的核心線(xiàn)程數(shù)為100）結(jié)合業(yè)務(wù)，服務(wù)總核心線(xiàn)程數(shù)控制在50以?xún)?nèi)，同步增加阻塞最大大小。結(jié)果還可以，提升了50，接近200了。

最后，觀察JVM的GC日志，發(fā)現(xiàn)YGC頻次4/s，沒(méi)有FGC。1分鐘內(nèi)GC時(shí)間不到1s，很明顯不是GC問(wèn)題，不過(guò)發(fā)現(xiàn)JVM內(nèi)存太小只有512M，直接給了4G。吞吐量沒(méi)啥提升，YGC頻次降低為2秒1次。

唉，一頓操作猛如虎。

?

PS：其實(shí)中間還對(duì)數(shù)據(jù)庫(kù)參數(shù)一通瞎搞，這里不多說(shuō)了。

?

其實(shí)也不是沒(méi)有收獲，至少在減少服務(wù)線(xiàn)程數(shù)量后還是有一定收獲的。

另外，已經(jīng)關(guān)注到了另外一個(gè)點(diǎn)：CPU使用率，減少了線(xiàn)程數(shù)量后，CPU的使用率并沒(méi)有明顯的下降，這里是很有問(wèn)題的，當(dāng)時(shí)認(rèn)為CPU的使用率主要與開(kāi)啟的線(xiàn)程數(shù)量有關(guān)，之前線(xiàn)程多，CPU使用率較高可以理解。但是，在砍掉了一大半的線(xiàn)程后，依然居高不下這就很奇怪了。

此時(shí)關(guān)注的重點(diǎn)開(kāi)始從代碼“慢”方向轉(zhuǎn)移到“CPU高”方向。

定位CPU使用率高的原因

CPU的使用率高，通常與線(xiàn)程數(shù)相關(guān)肯定是沒(méi)有問(wèn)題的。當(dāng)時(shí)對(duì)居高不下的原因考慮可能有以下兩點(diǎn)：

有額外的線(xiàn)程存在。

代碼有部分CPU密集操作。

然后繼續(xù)一頓操作：

觀察服務(wù)活躍線(xiàn)程數(shù)。

觀察有無(wú)CPU占用率較高線(xiàn)程。

在觀察過(guò)程中發(fā)現(xiàn)，沒(méi)有明顯CPU占用較高線(xiàn)程。所有線(xiàn)程基本都在10%以?xún)?nèi)。類(lèi)似于下圖，不過(guò)有很多線(xiàn)程。

沒(méi)有很高就證明大家都很正常，只是多而已...

此時(shí)沒(méi)有下一步的排查思路了。當(dāng)時(shí)想著,算了打印一下堆?？纯窗桑纯吹降赘闪松秪

在看的過(guò)程中發(fā)現(xiàn)這段日志：

"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.(AbstractAspectJAdvisorFactory.java:197) atorg.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAnnotation(AbstractAspectJAdvisorFactory.java:147) atorg.springframework.aop.aspectj.annotation.AbstractAspectJAdvisorFactory.findAspectJAnnotationOnMethod(AbstractAspectJAdvisorFactory.java:135) atorg.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvice(ReflectiveAspectJAdvisorFactory.java:244) atorg.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.instantiateAdvice(InstantiationModelAwarePointcutAdvisorImpl.java:149) atorg.springframework.aop.aspectj.annotation.InstantiationModelAwarePointcutAdvisorImpl.(InstantiationModelAwarePointcutAdvisorImpl.java:113) atorg.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisor(ReflectiveAspectJAdvisorFactory.java:213) atorg.springframework.aop.aspectj.annotation.ReflectiveAspectJAdvisorFactory.getAdvisors(ReflectiveAspectJAdvisorFactory.java:144) atorg.springframework.aop.aspectj.annotation.BeanFactoryAspectJAdvisorsBuilder.buildAspectJAdvisors(BeanFactoryAspectJAdvisorsBuilder.java:149) atorg.springframework.aop.aspectj.annotation.AnnotationAwareAspectJAutoProxyCreator.findCandidateAdvisors(AnnotationAwareAspectJAutoProxyCreator.java:95) atorg.springframework.aop.aspectj.autoproxy.AspectJAwareAdvisorAutoProxyCreator.shouldSkip(AspectJAwareAdvisorAutoProxyCreator.java:101) atorg.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.wrapIfNecessary(AbstractAutoProxyCreator.java:333) atorg.springframework.aop.framework.autoproxy.AbstractAutoProxyCreator.postProcessAfterInitialization(AbstractAutoProxyCreator.java:291) atorg.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyBeanPostProcessorsAfterInitialization(AbstractAutowireCapableBeanFactory.java:455) atorg.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1808) atorg.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:620) atorg.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) atorg.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:353) atorg.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:233) atorg.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean(DefaultListableBeanFactory.java:1282) atorg.springframework.beans.factory.support.DefaultListableBeanFactory.resolveNamedBean(DefaultListableBeanFactory.java:1243) atorg.springframework.beans.factory.support.DefaultListableBeanFactory.resolveBean(DefaultListableBeanFactory.java:494) atorg.springframework.beans.factory.support.DefaultListableBeanFactory.getBean(DefaultListableBeanFactory.java:349) atorg.springframework.beans.factory.support.DefaultListableBeanFactory.getBean(DefaultListableBeanFactory.java:342) atcn.hutool.extra.spring.SpringUtil.getBean(SpringUtil.java:117) ...... ......

上邊的堆棧發(fā)現(xiàn)了一個(gè)點(diǎn)： 在執(zhí)行g(shù)etBean的時(shí)候，執(zhí)行了createBean方法。我們都知道Spring托管的Bean都是提前實(shí)例化好放在IOC容器中的。createBean要做的事情有很多，比如Bean的初始化，依賴(lài)注入其他類(lèi)，而且中間還有一些前后置處理器執(zhí)行、代理檢查等等，總之是一個(gè)耗時(shí)方法，所以都是在程序啟動(dòng)時(shí)去掃描，加載，完成Bean的初始化。

而我們?cè)谶\(yùn)行程序線(xiàn)程堆棧中發(fā)現(xiàn)了這個(gè)操作。而且通過(guò)檢索發(fā)現(xiàn)竟然有近200處。

通過(guò)堆棧信息很快定位到執(zhí)行位置：

RedisToolredisTool=BeanUtils.getBean(RedisMaster.class);

而RedisMaster類(lèi)

@Component @Scope("prototype") publicclassRedisMasterimplementsIRedisTool{ //...... }

沒(méi)錯(cuò)就是用了多例。而且使用的地方是Redis（系統(tǒng)使用Jedis客戶(hù)端，Jedis并非線(xiàn)程安全，每次使用都需要新的實(shí)例），接口對(duì)Redis的使用還是比較頻繁的，一個(gè)接口得有10次左右獲取Redis數(shù)據(jù)。也就是說(shuō)執(zhí)行10次左右的createBean邏輯 ...

嘆氣?。。?/p>

趕緊改代碼，直接使用萬(wàn)能的 new 。

在看結(jié)果之前還有一點(diǎn)需要提一下，由于系統(tǒng)有大量統(tǒng)計(jì)耗時(shí)的操作。實(shí)現(xiàn)方式是通過(guò)：

longstart=System.currentTimeMillis(); //...... longend=System.currentTimeMillis(); longrunTime=start-end;

或者Hutool提供的StopWatch：

這里感謝一下huoger 同學(xué)的評(píng)論，當(dāng)時(shí)還誤以為該方式能夠降低性能的影響，但是實(shí)際上也只是一層封裝。底層使用的是 System.nanoTime()。

StopWatchwatch=newStopWatch(); watch.start(); //...... watch.stop(); System.out.println(watch.getTotalTimeMillis());

而這種在并發(fā)量高的情況下，對(duì)性能影響還是比較大的，特別在服務(wù)器使用了一些特定時(shí)鐘的情況下。這里就不多說(shuō)，感興趣的可以自行搜索一下。

最終結(jié)果：

排查涉及的命令如下：

查詢(xún)服務(wù)進(jìn)程CPU情況： top–Hp pid

查詢(xún)JVM GC相關(guān)參數(shù)：jstat -gc pid 2000 (對(duì) pid [進(jìn)程號(hào)] 每隔 2s 輸出一次日志)

打印當(dāng)前堆棧信息： jstack -l pid >> stack.log

總結(jié)

結(jié)果是好的，過(guò)程是曲折的?？偟膩?lái)說(shuō)還是知識(shí)的欠缺，文章看起來(lái)還算順暢，但都是事后諸葛亮，不對(duì)，應(yīng)該是時(shí)候臭皮匠?；径际沁叢橘Y料邊分析邊操作，前后花費(fèi)了4天時(shí)間，嘗試了很多。

「Mysql :」Buffer Pool 、Change Buffer 、Redo Log 大小、雙一配置...

「代碼 :」異步執(zhí)行，線(xiàn)程池參數(shù)調(diào)整，tomcat 配置，Druid連接池配置...

「JVM :」內(nèi)存大小，分配，垃圾收集器都想換...

總歸一通瞎搞，能想到的都試試。

后續(xù)還需要多了解一些性能優(yōu)化知識(shí)，至少要做到排查思路清晰，不瞎搞。

最后5行代碼有哪些：

「new Redis實(shí)例：」1

「耗時(shí)統(tǒng)計(jì)：」3

「SQL異步執(zhí)行 @Async：」1

上圖最終的結(jié)果是包含該部分的，時(shí)間原因未對(duì)SQL進(jìn)行處理，后續(xù)會(huì)考慮Redis原子操作+定時(shí)同步數(shù)據(jù)庫(kù)方式來(lái)進(jìn)行，避免同時(shí)操數(shù)據(jù)庫(kù)

TODO

問(wèn)題雖然解決了。但是原理還不清楚，需要繼續(xù)深挖。

「為什么createBean對(duì)性能影響這么大？」

如果影響這么大，Spring為什么還要有多例？

首先非并發(fā)場(chǎng)景速度還是很快的。這個(gè)毋庸置疑。畢竟接口響應(yīng)時(shí)間不足50ms。

所以問(wèn)題一定出在，并發(fā)createBean同一對(duì)象的鎖等待場(chǎng)景。根據(jù)堆棧日志，翻了一下Spring源碼，果然發(fā)現(xiàn)這里出現(xiàn)了同步鎖。相信鎖肯定不止一處。

org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory#doCreateBean

「System.currentTimeMillis并發(fā)度多少才會(huì)對(duì)性能產(chǎn)生影響，影響有多大？」

很多公司（包括大廠）在業(yè)務(wù)代碼中，還是會(huì)頻繁的使用System.currentTimeMillis獲取時(shí)間戳。比如：時(shí)間字段賦值場(chǎng)景。所以，性能影響肯定會(huì)有，但是影響的門(mén)檻是不是很高。

「繼續(xù)學(xué)習(xí)性能優(yōu)化知識(shí)」

吞吐量與什么有關(guān)？

首先，接口響應(yīng)時(shí)長(zhǎng)。直接影響因素還是接口響應(yīng)時(shí)長(zhǎng)，響應(yīng)時(shí)間越短，吞吐量越高。一個(gè)接口響應(yīng)時(shí)間100ms,那么1s就能處理10次。

其次，線(xiàn)程數(shù)。現(xiàn)在都是多線(xiàn)程環(huán)境，如果同時(shí)10個(gè)線(xiàn)程處理請(qǐng)求，那么吞吐量又能增加10倍。當(dāng)然由于CPU資源有限，所以線(xiàn)程數(shù)也會(huì)受限。理論上，在 CPU 資源利用率較低的場(chǎng)景，調(diào)大tomcat線(xiàn)程數(shù)，以及并發(fā)數(shù)，能夠有效的提升吞吐量。

最后，高性能代碼。無(wú)論接口響應(yīng)時(shí)長(zhǎng)，還是 CPU 資源利用率，都依賴(lài)于我們的代碼，要做高性能的方案設(shè)計(jì)，以及高性能的代碼實(shí)現(xiàn)，任重而道遠(yuǎn)。

CPU使用率的高低與哪些因素有關(guān)？

CPU使用率的高低，本質(zhì)還是由線(xiàn)程數(shù)，以及CPU使用時(shí)間決定的。

假如一臺(tái)10核的機(jī)器，運(yùn)行一個(gè)單線(xiàn)程的應(yīng)用程序。正常這個(gè)單線(xiàn)程的應(yīng)用程序會(huì)交給一個(gè)CPU核心去運(yùn)行，此時(shí)占用率就是10%。而現(xiàn)在應(yīng)用程序都是多線(xiàn)程的，因此一個(gè)應(yīng)用程序可能需要全部的CPU核心來(lái)執(zhí)行，此時(shí)就會(huì)達(dá)到100%。

此外，以單線(xiàn)程應(yīng)用程序?yàn)槔蟛糠智闆r下，我們還涉及到訪(fǎng)問(wèn)Redis/Mysql、RPC請(qǐng)求等一些阻塞等待操作，那么CPU就不是時(shí)刻在工作的。

所以阻塞等待的時(shí)間越長(zhǎng)，CPU利用率也會(huì)越低。也正是因?yàn)槿绱?，為了充分的利用CPU資源，多線(xiàn)程也就應(yīng)運(yùn)而生（一個(gè)線(xiàn)程雖然阻塞了，但是CPU別閑著，趕緊去運(yùn)行其他的線(xiàn)程）。

一個(gè)服務(wù)線(xiàn)程數(shù)在多少比較合適（算上Tomcat，最終的線(xiàn)程數(shù)量是226），執(zhí)行過(guò)程中發(fā)現(xiàn)即使tomcat線(xiàn)程數(shù)量是100，活躍線(xiàn)程數(shù)也很少超過(guò)50，整個(gè)壓測(cè)過(guò)程基本維持在20左右。

作者：FishBones

編輯：何安