Java應(yīng)用性能瓶頸分析思路
點擊上方藍色字體，選擇“標(biāo)星公眾號”
優(yōu)質(zhì)文章，第一時間送達
作者 | 王.小輝
來源 | urlify.cn/FNZfIj
1 問題描述
因產(chǎn)品架構(gòu)的復(fù)雜性，可能會導(dǎo)致性能問題的因素有很多。根據(jù)部署架構(gòu)，大致的可以分為應(yīng)用端瓶頸、數(shù)據(jù)庫端瓶頸、環(huán)境瓶頸三大類。可以根據(jù)瓶頸的不同部位，選擇相應(yīng)的跟蹤工具進行跟蹤分析。
應(yīng)用層面瓶頸大致有如下兩類，一是應(yīng)用服務(wù)端復(fù)雜的邏輯處理導(dǎo)致應(yīng)用端代碼執(zhí)行慢；二是資源鎖爭用導(dǎo)致線程阻塞問題（最典型的特征是線程狀態(tài)為“java.lang.Thread.State: BLOCKED (on object monitor)”）等。
數(shù)據(jù)庫層面瓶頸表現(xiàn)出來的現(xiàn)象都是SQL執(zhí)行慢，其原因可分為兩種，一是因索引缺失、SQL不規(guī)范等導(dǎo)致的SQL自身性能差；二是因為受環(huán)境資源瓶頸或并發(fā)資源鎖等影響出現(xiàn)等待導(dǎo)致的SQL執(zhí)行慢。
環(huán)境瓶頸導(dǎo)致的影響通常是整體性的，常見的有應(yīng)用及數(shù)據(jù)庫服務(wù)器的資源瓶頸（CPU、內(nèi)存、IO等）、網(wǎng)絡(luò)瓶頸等。
根據(jù)業(yè)務(wù)場景的不同特征，針對單點和并發(fā)兩種場景，可以采用不同的方式進行跟蹤分析。在分析單點場景性能問題時，可以通過相關(guān)agent探針追蹤鏈路信息，進而進行進一步分析，復(fù)雜場景可以借助JProfiler、Arthas、連續(xù)多次抓取線程快照等方式進行跟蹤分析。JProfiler、Arthas兩個工具優(yōu)點是可以直觀方便的進行跟蹤分析，但是性能開銷較大。在并發(fā)場景，一般采用多次抓取線程及數(shù)據(jù)庫會話快照的方式進行跟蹤分析。
2 故障排查
2.1 整體思路
明確現(xiàn)象，跟蹤數(shù)據(jù)，尋找瓶頸，優(yōu)化瓶頸。
無論應(yīng)用還是數(shù)據(jù)庫，無論用各種工具分析報告還是原始的線程堆棧、會話日志的方式進行跟蹤分析，其思路都是一致的，都是依據(jù)跟蹤數(shù)據(jù)，明確熱點內(nèi)容，分析性能瓶頸。根據(jù)跟蹤的數(shù)據(jù)分析線程或DB會話狀態(tài)、執(zhí)行的線程堆棧、SQL內(nèi)容等信息，明確熱點內(nèi)容，進而定位性能瓶頸。
2.2單點場景性能分析
單點場景性能分析，可以通過集成相關(guān)鏈路性能跟蹤探針進行定性分析，類似插件可以跟蹤請求和SQL信息，可以直觀的得到瓶頸內(nèi)容。有時瓶頸出現(xiàn)在應(yīng)用服務(wù)端，但是因業(yè)務(wù)邏輯較復(fù)雜，一個請求涉及跨多個產(chǎn)品模塊的調(diào)用，很難根據(jù)程序跟蹤器的日志快速定位到準(zhǔn)確的瓶頸點，這種場景則需要借助調(diào)試工具做進一步分析。在此，重點針對功能較完善的JProfiler工具和所有環(huán)境都適應(yīng)的JDK Jcmd工具進行示例。其他工具可以根據(jù)個人喜好，參考幫助文檔使用。
2.2.1 Jprofiler跟蹤方案
應(yīng)用層面單點性能跟蹤的主要目標(biāo)為應(yīng)用方法級耗時分析，可針對方法消耗的CPU資源進行跟蹤。具體方法為：在開始驗證問題之前，先通過“StartRecording”開啟跟蹤，然后重現(xiàn)問題，操作完成后點擊“StopRecording”即可完成跟蹤。
Start Recording
Stop Recording
跟蹤結(jié)束后，選擇CPU views-Call Tree即可查看跟蹤時段的方法級耗時分布情況。
注意，因跟蹤過程中會記錄跟蹤時段JVM所有的信息，為減少其他操作對目標(biāo)場景的影響，一般建議在跟蹤時盡量減少其他人員同時操作系統(tǒng)。如無法避免其他人員操作帶來的干擾，可以通過方法名、類名等搜索過濾關(guān)鍵信息來快速定位。
2.2.2 JDK內(nèi)部工具跟蹤方案
有時可能因用戶管理規(guī)范等原因，項目環(huán)境無法安裝JProfiler等第三方工具，我們也可以通過連續(xù)抓取線程快照的方式，在驗證問題時進行高頻采樣，統(tǒng)計業(yè)務(wù)典型堆棧出現(xiàn)的頻數(shù)，根據(jù)不同堆棧內(nèi)容出現(xiàn)的頻數(shù)比例即可大概的明確性能耗時分布情況。具體操作方式如下：
跳轉(zhuǎn)到JDK的bin目錄，執(zhí)行如下命令開啟連續(xù)打印線程快照，開啟線程快照打印之后重現(xiàn)有問題的功能場景，功能執(zhí)行結(jié)束之后，通過Ctrl+C命令終止快照打印，跟蹤結(jié)束后在JDK bin目錄下即會產(chǎn)生一個線程快照文件SingleTrace.log。
for i in {1..10000}; do ./jcmd /jstack/runtime/caf-bootstrap.jar Thread.print >> SingleTrace.log ; done;
最終生成的線程快照文件通常較大，可以借助VSCode、notepad++等工具進行統(tǒng)計分析。文件打開之后，第一步可以先統(tǒng)計每個線程快照頂部的“Full thread dump OpenJDK 64-Bit Server VM”得到抓取線程快照的總次數(shù)，之后可以結(jié)合業(yè)務(wù)場景的典型方法進行統(tǒng)計在相關(guān)方法出現(xiàn)頻數(shù)，根據(jù)典型場景占總次數(shù)的比例即可大概的明確對應(yīng)方法在總耗時中占用的比例。
2.3 并發(fā)場景性能分析
在做并發(fā)場景性能跟蹤時，為減小因抓取性能數(shù)據(jù)對系統(tǒng)整體帶來過大的性能開銷，通常以固定時間間隔（如每次間隔5s）連續(xù)多次抓取快照的方式進行收集性能數(shù)據(jù)。結(jié)合產(chǎn)品的實際情況，通常需要重點關(guān)注應(yīng)用層面線程狀態(tài)和數(shù)據(jù)庫層面的會話狀態(tài)兩類信息。因此，在跟蹤過程中通常采用應(yīng)用線程快照+數(shù)據(jù)庫會話快照相結(jié)合的方式進行跟蹤。分析時可用結(jié)合問題時段的線程狀態(tài)、堆棧信息、數(shù)據(jù)庫會話狀態(tài)情況定位性能瓶頸。一般來說，線程狀態(tài)為RUNNABLE狀態(tài)，在同一份線程快照出現(xiàn)頻率高、或者不同快照中出現(xiàn)頻率高的線程一般為性能瓶頸內(nèi)容。
2.3.1 應(yīng)用層跟蹤方案
收集線程堆?？煺盏拿睿簀cmd PID Thread.print >>tracelog.log。
為了操作方便，整理了批量腳本，按照如下步驟操作即可收集內(nèi)存及線程信息，在分析線程問題時，只關(guān)注線程堆棧相關(guān)內(nèi)容即可。
① 將troubleshooting.sh文件放到JDK的bin目錄下，具體路徑為*/jstack/runtime/java/x86_64-linux/bin
②將troubleshooting.sh授予可執(zhí)行權(quán)限：chmod +x troubleshooting.sh
③運行troubleshooting.sh抓取堆棧信息：./troubleshooting.sh 。執(zhí)行后在jdk bin目錄下會產(chǎn)生一個命名為trace.log的日志文件，trace.log默認只保存最近一次抓取的日志內(nèi)容。
④通過 sz trace.log命令或其他文件傳輸工具將日志文件下載到本地查看即可。
2.3.2 數(shù)據(jù)庫會話跟蹤
DBSQLMonitor工具（http://gsk.inspur.com/File/t-7237）可以自動定期記錄數(shù)據(jù)庫會話信息，工具支持跟蹤所有會話和僅阻塞兩種模式。在大量復(fù)雜的DB阻塞場景，僅阻塞模式生成的日志可以快速的定位阻塞源；所有會話模式生成的日志更并發(fā)場景分析SQL瓶頸。
工具部署。將工具部署于任一能連接數(shù)據(jù)庫的機器，使用具有管理員權(quán)限的用戶登錄工具，根據(jù)分析場景的需要，將跟蹤方式設(shè)置為所有會話或僅阻塞模式，并設(shè)置記錄會話快照的時間間隔。在并發(fā)性能分析時，為能夠更準(zhǔn)確的記錄真實的環(huán)境信息，通常將時間間隔設(shè)置為工具允許的最小時間間隔3s。
日志分析。跟蹤結(jié)束后，在分析并發(fā)場景SQL性能時，可以直接篩選活動狀態(tài)（非sleeping、Inactive）的會話，結(jié)合會話狀態(tài)、等待事件、會話內(nèi)容等信息確定數(shù)據(jù)庫層面性能情況。
日志說明。Idx表示一次會話快照中的日志編號;logTime為時間戳，相同時間戳的多條記錄表示在時間戳?xí)r刻的多個會話；spid為sessionID；blocked為阻塞當(dāng)前會話的sessionID，該字段內(nèi)容對應(yīng)spid，blocked為0的表示沒有被阻塞；status為當(dāng)前會話狀態(tài)；lastWaittype為會話等待事件；programName為當(dāng)前連接對應(yīng)的進程名稱，GSCloud對應(yīng)的進程名為JDBC Thin Client；sqlText為當(dāng)前會話正在執(zhí)行的SQL腳本。
2.3.3 典型場景分析思路
并發(fā)場景性能瓶頸大致可以分為如下幾種情況：
（1）應(yīng)用自身代碼邏輯執(zhí)行慢
應(yīng)用層面代碼執(zhí)行慢的問題，表現(xiàn)到線程跟蹤日志上就是某個活動狀態(tài)的線程在某個方法執(zhí)行的時間很長。如JProfiler日志中某方法耗時很長、同一個快照有多個線程在執(zhí)行相同內(nèi)容或連續(xù)多個線程快照均在執(zhí)行某方法等。明確瓶頸方法后，分析棧頂或Jprofiler中top耗時的最葉子節(jié)點即可。
典型特征：線程狀態(tài)為RUNNABLE狀態(tài)，且棧頂為非等待類型堆棧。
如下示例中，多次抓取線程快照，線程狀態(tài)一直保持RUNNABLE，產(chǎn)品線程棧頂均為XXX.readValue()，且棧頂代碼沒有出現(xiàn)等待。因此，我們可以得出，XXX.readValue()是由于String.intern()導(dǎo)致。
（2）非應(yīng)用自身邏輯導(dǎo)致的等待
有時還會出現(xiàn)因應(yīng)用以下層面資源導(dǎo)致的性能瓶頸，如SQL效率低導(dǎo)致應(yīng)用長時間等待數(shù)據(jù)庫返回數(shù)據(jù)、應(yīng)用與數(shù)據(jù)庫之間網(wǎng)絡(luò)環(huán)境不佳導(dǎo)致接收數(shù)據(jù)庫返回的結(jié)果集時耗時過長等。
①數(shù)據(jù)庫SQL執(zhí)行慢
當(dāng)發(fā)現(xiàn)大量活動線程在等待數(shù)據(jù)庫返回時，則需要進一步結(jié)合數(shù)據(jù)庫session日志做進一步分析。以如下示例為例，當(dāng)前時刻的線程快照中有61個線程在等待網(wǎng)絡(luò)返回，此時可以檢查相關(guān)時段活動狀態(tài)的會話情況，假如線程快照前后的數(shù)據(jù)庫會話中活動會話數(shù)與等待網(wǎng)絡(luò)返回的數(shù)目接近，則基本可以確定應(yīng)用層面的等待是由于SQL性能差導(dǎo)致。
典型特征：線程狀態(tài)為RUNNABLE，且棧頂在存在網(wǎng)絡(luò)相關(guān)等待，且數(shù)據(jù)庫會話中存在大量活動狀態(tài)會話。
②網(wǎng)絡(luò)等環(huán)境因素導(dǎo)致等待
有時還會有另一種場景，線程快照中存在大量等待網(wǎng)絡(luò)返回的活動線程，但是數(shù)據(jù)庫層面并沒有與之對應(yīng)的出現(xiàn)大量活動狀態(tài)的會話，這種情況可能是如棧頂代碼所示，應(yīng)用和數(shù)據(jù)庫服務(wù)器之間真正的出現(xiàn)了網(wǎng)絡(luò)瓶頸。
典型特征：線程狀態(tài)為RUNNABLE，且棧頂在存在網(wǎng)絡(luò)相關(guān)等待，且數(shù)據(jù)庫會話中沒有貨只有個別零散的活動狀態(tài)會話（個別是指一次出現(xiàn)的活動會話數(shù)很少；零散是指活動會話出現(xiàn)的頻率低，間隔很長時間出現(xiàn)一次）。
Linux環(huán)境還可以使用iftop工具進行網(wǎng)絡(luò)情況監(jiān)控。
（3）應(yīng)用層面出現(xiàn)并發(fā)等待（線程阻塞）
在并發(fā)場景，有時候會出現(xiàn)因為資源鎖導(dǎo)致的等待問題，線程阻塞問題涉及兩種狀態(tài)的內(nèi)容，一是阻塞源線程，阻塞源線程狀態(tài)為RUNNABLE狀態(tài)，此類線程通常是由于自身或某些外部因素導(dǎo)致的線程執(zhí)行慢，進而導(dǎo)致申請的資源鎖未能及時釋放；二是被阻塞的線程，此類線程均為BLOCKED狀態(tài)，且等待的多為同一個資源。
以如下被阻塞的線程為例，當(dāng)前線程在執(zhí)行_addSymbol()方法時，對lock <0x00000004d23c52c0>加鎖失敗導(dǎo)致出現(xiàn)等待，進而該線程處于被阻塞狀態(tài)。一般來說，相同方法申請同一個資源的概率相對更大，因此，我們可以用等待加鎖的方法作為關(guān)鍵詞，搜索存在相關(guān)關(guān)鍵詞的非BLOCKED狀態(tài)線程大概率即為阻塞源線程，最終發(fā)現(xiàn)該線程阻塞是由于場景（1）中XXX.readValue()方法的String.intern()導(dǎo)致。
典型特征：線程狀態(tài)為BLOCKED
3 解決方案
根據(jù)分析結(jié)論，優(yōu)化瓶頸內(nèi)容。
鋒哥最新SpringCloud分布式電商秒殺課程發(fā)布
??????
??長按上方微信二維碼 2 秒
感謝點贊支持下哈 