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