公司來了個大牛:短短改了幾行代碼,介面吞吐量提升了 10 倍。。

来源:https://www.cnblogs.com/javastack/archive/2023/11/21/17845625.html
-Advertisement-
Play Games

作者: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 實戰項目:

https://github.com/javastacks/spring-boot-best-practice

分析過程

定位“慢”原因

這裡暫時先忽略 CPU 占用率高的問題

首先平均響應時間這麼慢,肯定是有阻塞。先確定阻塞位置。重點檢查幾處:

  • 鎖 (同步鎖、分散式鎖、資料庫鎖)
  • 耗時操作 (鏈接耗時、SQL耗時)

結合這些先配置耗時埋點。

  1. 介面響應時長統計。超過500ms列印告警日誌。
  2. 介面內部遠程調用耗時統計。200ms列印告警日誌。
  3. Redis訪問耗時。超過10ms列印告警日誌。
  4. 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 很明顯有百毫秒的耗時。檢查代碼發現,這部分沒有任何耗時操作。那麼這段時間乾什麼了呢?

  1. 發生了線程切換,換其他線程執行其他任務了。(線程太多了)
  2. 日誌列印太多了,壓測5分鐘日誌量500M。(記得日誌列印太多是有很大影響的)
  3. 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 實戰項目:

https://github.com/javastacks/spring-boot-best-practice


其實也不是沒有收穫,至少在減少服務線程數量後還是有一定收穫的。另外,已經關註到了另外一個點:CPU使用率,減少了線程數量後,CPU的使用率並沒有明顯的下降,這裡是很有問題的,當時認為CPU的使用率主要與開啟的線程數量有關,之前線程多,CPU使用率較高可以理解。但是,在砍掉了一大半的線程後,依然居高不下這就很奇怪了。

此時關註的重點開始從代碼“慢”方向轉移到“CPU高”方向。

定位CPU使用率高的原因

CPU的使用率高,通常與線程數相關肯定是沒有問題的。當時對居高不下的原因考慮可能有以下兩點:

  1. 有額外的線程存在。
  2. 代碼有部分CPU密集操作。

然後繼續一頓操作:

  1. 觀察服務活躍線程數。
  2. 觀察有無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 實戰項目:

https://github.com/javastacks/spring-boot-best-practice

通過堆棧信息很快定位到執行位置:

<!--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行代碼有哪些:

  1. new Redis實例:1
  2. 耗時統計:3
  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最新版)

2.勁爆!Java 協程要來了。。。

3.Spring Boot 2.x 教程,太全了!

4.別再寫滿屏的爆爆爆炸類了,試試裝飾器模式,這才是優雅的方式!!

5.《Java開發手冊(嵩山版)》最新發佈,速速下載!

覺得不錯,別忘了隨手點贊+轉發哦!


您的分享是我們最大的動力!

-Advertisement-
Play Games
更多相關文章
  • Lambda表達式 Lambda是一個匿名函數,我們可以把Lambda表達式理解為是一段可以傳遞的代碼(將代碼像數據一樣進行傳遞)。使用它可以寫出更簡潔、更靈活的代碼。作為一種更緊湊的代碼風格,使Java的語言表達能力得到了提升。 本質: 作為函數式介面的實例, 沒有介面就沒意義了. // 簡單使用 ...
  • keycloak目前提供了幾種分散式緩存,我們自己的緩存,如果希望是分散式的,可以將緩存添加到以下幾個緩存里即可 actionTokens clientSessions loginFailures offlineClientSessions offlineSessions sessions work ...
  • 一、讀取寫入視頻文件 1 import cv2 2 3 # 創建一個視屏捕獲對象 4 videoCapture = cv2.VideoCapture('AVI.avi') 5 6 # 獲取視頻的屬性值,cv2.CAP_PROP_FPS獲取視頻幀率 7 fps = videoCapture.get(c ...
  • 題目: 給你兩個按 非遞減順序 排列的整數數組 nums1 和 nums2,另有兩個整數 m 和 n ,分別表示 nums1 和 nums2 中的元素數目。 請你 合併 nums2 到 nums1 中,使合併後的數組同樣按 非遞減順序 排列。 註意:最終,合併後數組不應由函數返回,而是存儲在數組 n ...
  • AcWing 演算法基礎課week 1 總結 總結點 1:快速排序(分治思想) 題1:從小到大排序 主體思路:定義一個數x屬於數組s,利用雙指針,將數組分為大於等於x和小於等於x的兩部分,然後遞歸處理。(具體步驟如下) 1. 如上圖所示,我們定義一個數組s用來儲存n個數據,然後定義兩個指針i j,分別 ...
  • Assistants介紹 隨著OpenAI將Assistants助手API對外發佈,我們搭建個人知識庫變的如此簡單。開發者將自己的應用通過Assistants API與OpenAI對接,就可以讓每一位客戶擁有不一般體驗的個人知識庫。由於Assistants相關API有30+,本文只列舉完成一個最小功 ...
  • 事務是保證業務操作完整性的一種資料庫機制,具有原子性、一致性、隔離性和持久性(ACID)的特點。 在Java中,可以通過JDBC和MyBatis來控制事務,底層都是通過Connection對象完成的。 Spring使用AOP的方式進行事務開發,通過將事務的額外功能封裝在DataSourceTrans... ...
  • 事件緣起我在Linux伺服器(CentOS 7.8)安裝Python3.10,並替換python軟鏈接為python3之後,yum命令不可用。特此記錄一下。 完整安裝步驟如下: Python3.10安裝 1.使用yum程式提前安裝Python依賴。 yum install wget zlib-dev ...
一周排行
    -Advertisement-
    Play Games
  • 移動開發(一):使用.NET MAUI開發第一個安卓APP 對於工作多年的C#程式員來說,近來想嘗試開發一款安卓APP,考慮了很久最終選擇使用.NET MAUI這個微軟官方的框架來嘗試體驗開發安卓APP,畢竟是使用Visual Studio開發工具,使用起來也比較的順手,結合微軟官方的教程進行了安卓 ...
  • 前言 QuestPDF 是一個開源 .NET 庫,用於生成 PDF 文檔。使用了C# Fluent API方式可簡化開發、減少錯誤並提高工作效率。利用它可以輕鬆生成 PDF 報告、發票、導出文件等。 項目介紹 QuestPDF 是一個革命性的開源 .NET 庫,它徹底改變了我們生成 PDF 文檔的方 ...
  • 項目地址 項目後端地址: https://github.com/ZyPLJ/ZYTteeHole 項目前端頁面地址: ZyPLJ/TreeHoleVue (github.com) https://github.com/ZyPLJ/TreeHoleVue 目前項目測試訪問地址: http://tree ...
  • 話不多說,直接開乾 一.下載 1.官方鏈接下載: https://www.microsoft.com/zh-cn/sql-server/sql-server-downloads 2.在下載目錄中找到下麵這個小的安裝包 SQL2022-SSEI-Dev.exe,運行開始下載SQL server; 二. ...
  • 前言 隨著物聯網(IoT)技術的迅猛發展,MQTT(消息隊列遙測傳輸)協議憑藉其輕量級和高效性,已成為眾多物聯網應用的首選通信標準。 MQTTnet 作為一個高性能的 .NET 開源庫,為 .NET 平臺上的 MQTT 客戶端與伺服器開發提供了強大的支持。 本文將全面介紹 MQTTnet 的核心功能 ...
  • Serilog支持多種接收器用於日誌存儲,增強器用於添加屬性,LogContext管理動態屬性,支持多種輸出格式包括純文本、JSON及ExpressionTemplate。還提供了自定義格式化選項,適用於不同需求。 ...
  • 目錄簡介獲取 HTML 文檔解析 HTML 文檔測試參考文章 簡介 動態內容網站使用 JavaScript 腳本動態檢索和渲染數據,爬取信息時需要模擬瀏覽器行為,否則獲取到的源碼基本是空的。 本文使用的爬取步驟如下: 使用 Selenium 獲取渲染後的 HTML 文檔 使用 HtmlAgility ...
  • 1.前言 什麼是熱更新 游戲或者軟體更新時,無需重新下載客戶端進行安裝,而是在應用程式啟動的情況下,在內部進行資源或者代碼更新 Unity目前常用熱更新解決方案 HybridCLR,Xlua,ILRuntime等 Unity目前常用資源管理解決方案 AssetBundles,Addressable, ...
  • 本文章主要是在C# ASP.NET Core Web API框架實現向手機發送驗證碼簡訊功能。這裡我選擇是一個互億無線簡訊驗證碼平臺,其實像阿裡雲,騰訊雲上面也可以。 首先我們先去 互億無線 https://www.ihuyi.com/api/sms.html 去註冊一個賬號 註冊完成賬號後,它會送 ...
  • 通過以下方式可以高效,並保證數據同步的可靠性 1.API設計 使用RESTful設計,確保API端點明確,並使用適當的HTTP方法(如POST用於創建,PUT用於更新)。 設計清晰的請求和響應模型,以確保客戶端能夠理解預期格式。 2.數據驗證 在伺服器端進行嚴格的數據驗證,確保接收到的數據符合預期格 ...