我做了近十年后端開發(fā)和性能調(diào)優(yōu)經(jīng)手過不少“線上突然卡死”“接口一天比一天慢”的疑難雜癥。排查這類問題最核心的手段就是代碼性能剖析Profiling?？梢赃@么說沒有剖析工具性能調(diào)優(yōu)基本等于閉著眼猜有了剖析工具問題的定位效率能提升一個(gè)數(shù)量級(jí)。這篇文章我不打算講枯燥的理論而是結(jié)合我這么多年的實(shí)操經(jīng)驗(yàn)把這個(gè)主題拆開揉碎講清楚代碼性能剖析工具到底是什么、能解決什么問題、不同場(chǎng)景下怎么選型、具體怎么用以及那些文檔里不會(huì)寫但實(shí)戰(zhàn)中一定會(huì)踩的坑。文章面向的讀者包括剛接觸性能優(yōu)化不久的新人也包括想系統(tǒng)梳理工具鏈的資深開發(fā)。我會(huì)把重點(diǎn)放在工具背后的原理、參數(shù)選擇的依據(jù)以及排查思路的建立上?？赐曛竽銘?yīng)該能拿著手頭的項(xiàng)目直接照著這套方法論動(dòng)手做一次完整的性能剖析。1. 性能剖析工具的本質(zhì)給代碼做“體檢”很多人對(duì)性能剖析工具有個(gè)誤解覺得它就是拿來測(cè)個(gè)耗時(shí)、看看哪個(gè)函數(shù)跑得慢。其實(shí)不只如此。代碼性能剖析工具的定位更像醫(yī)院的體檢設(shè)備它不直接幫你治病但能精準(zhǔn)告訴你病灶在哪里。它解決的問題是“我的代碼到底把時(shí)間花在哪了”“內(nèi)存都去哪了”“為什么CPU占用這么高”這三個(gè)問題的答案就是性能優(yōu)化的全部起點(diǎn)。1.1 為什么不能靠“感覺”定位性能瓶頸我見過太多團(tuán)隊(duì)排查性能問題靠的是“經(jīng)驗(yàn)”和“猜測(cè)”覺得某個(gè)接口慢就把里面所有日志打出來看耗時(shí)覺得內(nèi)存漲得快就到處加打印。這種做法在小項(xiàng)目里勉強(qiáng)能用一旦代碼量上來、調(diào)用鏈變長(zhǎng)基本就失效了。原因很簡(jiǎn)單一個(gè)請(qǐng)求經(jīng)過的函數(shù)可能有幾十上百個(gè)任何一個(gè)環(huán)節(jié)都可能成為瓶頸靠肉眼掃代碼效率極低而且經(jīng)常被“看起來慢”的代碼誤導(dǎo)。舉個(gè)我實(shí)際遇到的案例。一個(gè)在線報(bào)表系統(tǒng)導(dǎo)出數(shù)據(jù)時(shí)非常慢開發(fā)第一反應(yīng)是SQL查詢慢優(yōu)化了一周索引效果甚微。后來我用剖析工具一跑發(fā)現(xiàn)SQL查詢只占總耗時(shí)的15%真正的大頭反而是一個(gè)不起眼的Excel格式轉(zhuǎn)換函數(shù)——它嵌套循環(huán)里做了大量的字符串拼接觸發(fā)了頻繁的內(nèi)存分配和復(fù)制。這個(gè)函數(shù)藏在工具類里平時(shí)根本沒人會(huì)注意到。這個(gè)案例說明性能問題往往藏在“你以為不是瓶頸”的地方只有基于數(shù)據(jù)才能找到真相。1.2 剖析工具的三種典型工作模式要理解剖析工具就得先理解它的工作原理。市面上的剖析工具五花八門但底層工作模式就三種采樣Sampling、插樁Instrumentation、事件追蹤Event Tracing。采樣模式最簡(jiǎn)單粗暴。它就像每隔一段時(shí)間給程序拍一張快照記錄“此刻CPU正在執(zhí)行哪個(gè)函數(shù)”。比如每10毫秒采樣一次跑100毫秒就能得到10個(gè)樣本點(diǎn)樣本點(diǎn)最集中的函數(shù)就是熱點(diǎn)函數(shù)。這種模式開銷極小幾乎不影響程序本身的行為適合定位CPU密集型瓶頸。代價(jià)是精度有限極端情況下可能漏掉執(zhí)行時(shí)間很短的函數(shù)。插樁模式則是在函數(shù)入口、出口、循環(huán)內(nèi)部插入統(tǒng)計(jì)代碼精確記錄每個(gè)函數(shù)被調(diào)用了多少次、耗時(shí)多少。它得到的數(shù)據(jù)非常精確能生成完整的調(diào)用樹和耗時(shí)分布但開銷也比較大在線上環(huán)境啟用的話可能把程序的性能拖慢20%到50%。所以插樁模式更適合測(cè)試環(huán)境和預(yù)發(fā)環(huán)境不適合高并發(fā)的生產(chǎn)環(huán)境。事件追蹤模式介于兩者之間它不統(tǒng)計(jì)函數(shù)耗時(shí)而是記錄特定事件比如鎖等待、GC停頓、磁盤IO、網(wǎng)絡(luò)請(qǐng)求發(fā)生的時(shí)機(jī)和持續(xù)時(shí)長(zhǎng)。這種模式對(duì)排查“響應(yīng)慢但CPU不高”的問題特別有效因?yàn)槠款i往往不在計(jì)算而在等待外部資源。1.3 剖析工具能發(fā)現(xiàn)哪幾類典型問題弄清了工作模式再聊聊剖析工具實(shí)際能挖出哪些問題。根據(jù)我的經(jīng)驗(yàn)最常見的是以下五類。第一類是CPU熱點(diǎn)。表現(xiàn)為某個(gè)純計(jì)算函數(shù)占用了70%以上的CPU時(shí)間典型原因包括低效算法、不必要的字符串拼接、正則表達(dá)式回溯等。第二類是內(nèi)存問題。包括內(nèi)存泄漏某塊內(nèi)存被持有后永遠(yuǎn)無法釋放導(dǎo)致內(nèi)存占用持續(xù)攀升內(nèi)存抖動(dòng)大量短生命周期對(duì)象被頻繁創(chuàng)建和回收導(dǎo)致GC壓力過大和CPU飆升。第三類是鎖競(jìng)爭(zhēng)。多個(gè)線程同時(shí)競(jìng)爭(zhēng)同一把鎖導(dǎo)致大量線程處于阻塞狀態(tài)CPU利用率不高但程序極慢。第四類是IO阻塞。程序大量時(shí)間花在等待磁盤讀寫、網(wǎng)絡(luò)請(qǐng)求或數(shù)據(jù)庫響應(yīng)上這類問題用CPU剖析往往看不到熱點(diǎn)需要用IO追蹤或線程狀態(tài)分析。第五類是調(diào)用次數(shù)異常。某個(gè)函數(shù)本身耗時(shí)不長(zhǎng)但被調(diào)用了成百上千萬次累計(jì)耗時(shí)驚人。這類問題在插樁模式的調(diào)用樹里一目了然但在采樣模式下容易被忽略。這五類問題覆蓋了絕大多數(shù)我遇到過的性能事故。掌握剖析工具本質(zhì)上就是掌握了一套系統(tǒng)發(fā)現(xiàn)這些問題的方法論。2. 工具選型不同語言和環(huán)境該用哪個(gè)代碼性能剖析工具沒有“通吃”的版本不同語言、不同規(guī)模的項(xiàng)目適合的工具差異很大。我自己的習(xí)慣是先根據(jù)項(xiàng)目的運(yùn)行環(huán)境和技術(shù)棧篩選再結(jié)合剖析需求CPU還是內(nèi)存、在線還是離線做最終決定。下面這幾種組合是我在不同階段和不同項(xiàng)目里驗(yàn)證過比較穩(wěn)的方案。2.1 Python項(xiàng)目cProfile與py-spy的搭配Python是動(dòng)態(tài)語言剖析工具的選擇比較有講究。官方標(biāo)準(zhǔn)庫里自帶cProfile屬于插樁模式的剖析器用起來非常簡(jiǎn)單# 方式一直接剖析一段代碼 python -m cProfile -o output.prof my_script.py # 方式二在代碼內(nèi)部啟動(dòng)和停止剖析 import cProfile profiler cProfile.Profile() profiler.enable() # ... 要剖析的業(yè)務(wù)代碼 ... profiler.disable() profiler.dump_stats(output.prof)生成了.prof文件之后可以用pstats模塊在命令行里做交互式分析也可以用可視化工具跑出火焰圖。我習(xí)慣的命令行分析是import pstats p pstats.Stats(output.prof) p.sort_stats(cumulative).print_stats(30)這里有個(gè)關(guān)鍵參數(shù)要說明一下。sort_stats有幾種排序維度time表示按函數(shù)自身耗時(shí)排序cumulative表示按函數(shù)累計(jì)耗時(shí)包括它調(diào)用的所有子函數(shù)排序。我個(gè)人的習(xí)慣是先按cumulative看前十名找出調(diào)用鏈路上累計(jì)耗時(shí)最高的入口函數(shù)再切換成time找出真正“干活”最多的純計(jì)算函數(shù)。兩者結(jié)合才能既看到宏觀調(diào)用鏈又鎖定微觀熱點(diǎn)。cProfile的缺點(diǎn)是插樁模式開銷大線上生產(chǎn)環(huán)境基本沒法用。這時(shí)就需要py-spy出場(chǎng)了。py-spy是一個(gè)采樣模式的剖析器它可以直接附加到正在運(yùn)行的Python進(jìn)程上不需要修改代碼也不需要重啟服務(wù)對(duì)程序性能的影響控制在5%以內(nèi)。這在排查線上事故時(shí)是救命級(jí)別的工具我甚至遇到過——進(jìn)程卡死到連top都打不開——py-spy還能正常采樣的場(chǎng)景這也間接說明了py-spy的強(qiáng)悍。它采集數(shù)據(jù)的命令是# 生成火焰圖所需的原始數(shù)據(jù) py-spy record --pid 進(jìn)程PID -o profile.svg # 直接查看進(jìn)程當(dāng)前正在執(zhí)行的代碼 py-spy dump --pid 進(jìn)程PIDpy-spy dump是我日常用得最多的子命令。它能立即打印出進(jìn)程內(nèi)所有線程的當(dāng)前調(diào)用棧幾秒鐘就能定位“線程卡在哪了”。比如線程卡在socket.read說明在等網(wǎng)絡(luò)卡在threading.Lock.acquire說明在等鎖。這種實(shí)時(shí)快照的定位能力是cProfile不具備的。2.2 Java項(xiàng)目async-profiler與Arthas的選擇Java生態(tài)的剖析工具非常豐富但很多重量級(jí)工具比如JProfiler、YourKit是需要付費(fèi)的。我個(gè)人的首選是async-profiler——它是完全免費(fèi)的開源工具由阿里巴巴的工程師主導(dǎo)開發(fā)。它厲害的地方在于同時(shí)支持CPU采樣、內(nèi)存分配采樣、鎖競(jìng)爭(zhēng)分析和GC停頓分析而且開銷極低可以直接在生產(chǎn)環(huán)境使用。在開始之前我們需要記住它的一般用法# 在Linux平臺(tái)分配10毫秒的CPU采樣 ./profiler.sh -d 30 -e cpu -o flamegraph -i 10ms PID # Java 11以上可以直接基于JFRJava Flight Recorder ./profiler.sh -d 30 -e alloc -o flamegraph PID這里-d 30表示采樣30秒-e cpu是事件類型-i 10ms是采樣間隔。采樣間隔這個(gè)參數(shù)很重要設(shè)得太小會(huì)導(dǎo)致剖析器自身消耗過多CPU干擾被分析程序設(shè)得太大又可能漏掉短命的熱點(diǎn)函數(shù)。我自己的經(jīng)驗(yàn)值是對(duì)cpu事件用1ms到10ms對(duì)alloc事件用100us左右可以根據(jù)程序的實(shí)際特點(diǎn)調(diào)整。如果你用的是Java且不想裝額外工具還有個(gè)更輕的選擇JFRJava Flight Recorder本身。JDK 11以上自帶不需要第三方依賴。啟動(dòng)時(shí)加上-XX:StartFlightRecordingfilenamerecording.jfr,duration60s,settingsprofile就能采集60秒的性能數(shù)據(jù)然后用jfr print --events jdk.ExecutionSample命令解析。雖然命令行的體驗(yàn)不如火焰圖直觀但在沒有外部工具的環(huán)境中它是最快的應(yīng)急方案。Arthas也是阿里巴巴開源的一個(gè)工具它的定位是Java診斷平臺(tái)功能很全包括在線反編譯、方法調(diào)用追蹤、線程棧查看等。但要說性能剖析的專業(yè)度它不如async-profiler。我的用法是跑火焰圖選async-profiler線上看線程狀態(tài)和處理復(fù)雜問題選Arthas。Arthas特別適合解決“哪個(gè)線程卡的”和“這個(gè)方法入?yún)⒊鰠⑹鞘裁础边@類現(xiàn)場(chǎng)診斷問題。2.3 Go項(xiàng)目與系統(tǒng)級(jí)工具pprof和perf的實(shí)戰(zhàn)組合Go語言自帶runtime/pprof這是我認(rèn)為所有語言中做得最好的內(nèi)置性能剖析工具沒有之一。它支持CPU剖析、堆內(nèi)存剖析、goroutine阻塞分析、鎖競(jìng)爭(zhēng)分析而且用法統(tǒng)一。在服務(wù)代碼里加入下面幾行就能通過HTTP接口暴露剖析數(shù)據(jù)import _ net/http/pprof // 在main函數(shù)中啟動(dòng)HTTP服務(wù) go func() { http.ListenAndServe(:6060, nil) }()啟動(dòng)服務(wù)后獲取剖析數(shù)據(jù)的方式很直接# 采集30秒的CPU剖析數(shù)據(jù) go tool pprof http://localhost:6060/debug/pprof/profile?seconds30 # 直接進(jìn)入pprof的交互式命令行 go tool pprof http://localhost:6060/debug/pprof/heapgo tool pprof進(jìn)入交互式命令行后有幾個(gè)常用命令值得記一下。輸入top查看占用最高的函數(shù)輸入list加上函數(shù)名可以查看該函數(shù)每一行代碼的耗時(shí)明細(xì)輸入web生成調(diào)用圖并用瀏覽器打開。這些命令配合起來基本可以完成從“熱點(diǎn)函數(shù)”到“熱點(diǎn)代碼行”的下鉆分析。如果問題不在Go進(jìn)程內(nèi)部而在于整個(gè)系統(tǒng)的資源消耗就需要用系統(tǒng)級(jí)工具perf了。perf是Linux內(nèi)核自帶的性能剖析工具理論上可以剖析任何進(jìn)程——包括編譯后的C/C程序、Java的JIT代碼、Go的運(yùn)行時(shí)——但需要內(nèi)核開啟CONFIG_PERF_EVENTS支持。它的用法如下# 以49Hz頻率采樣指定進(jìn)程60秒 perf record -F 49 -p PID -- sleep 60 # 生成剖析報(bào)告 perf reportperf生成的報(bào)告能顯示每個(gè)函數(shù)的CPU占用率和調(diào)用路徑對(duì)系統(tǒng)級(jí)性能問題比如某個(gè)系統(tǒng)調(diào)用耗時(shí)異常、CPU緩存命中率低有很敏銳的洞察。它的門檻比語言特定工具高一些需要理解一些內(nèi)核調(diào)度的概念但對(duì)排查混合語言架構(gòu)的項(xiàng)目非常關(guān)鍵。3. 實(shí)操全流程從發(fā)現(xiàn)卡頓到精準(zhǔn)定位工具選得再好不會(huì)用等于零。這一節(jié)我用一個(gè)模擬的真實(shí)案例把從發(fā)現(xiàn)問題到找到根因的完整流程走一遍。案例背景是一個(gè)Python寫的定時(shí)任務(wù)每天凌晨處理一批數(shù)據(jù)最近幾天處理時(shí)間從30分鐘暴漲到3小時(shí)運(yùn)維已經(jīng)催了好幾輪。3.1 第一步用實(shí)時(shí)快照確認(rèn)初步方向接到這類問題我不會(huì)直接上重型剖析而是先用py-spy對(duì)運(yùn)行中的進(jìn)程做個(gè)實(shí)時(shí)快照確認(rèn)程序當(dāng)前到底在干什么。這一步很像醫(yī)生先量體溫、測(cè)血壓目的是建立對(duì)病情的初步判斷。py-spy dump --pid 28471輸出會(huì)顯示每個(gè)線程的當(dāng)前棧幀。我當(dāng)時(shí)看到的情況是主線程卡在了一個(gè)函數(shù)內(nèi)部的深層調(diào)用里而且它調(diào)用的子函數(shù)大量集中在正則表達(dá)式處理上。這說明問題可能是正則引擎的回溯導(dǎo)致的——這是Python里非常著名的性能殺手。有了這個(gè)初步判斷我才決定用cProfile做一次詳細(xì)的插樁剖析拿到精確的耗時(shí)分布。這里有個(gè)經(jīng)驗(yàn)值得分享采樣模式的快照適合“寬泛定位”但要精確定位到具體函數(shù)和代碼行還是得靠插樁數(shù)據(jù)。這兩種模式是互補(bǔ)的實(shí)戰(zhàn)中常組合使用。3.2 第二步完整采集剖析數(shù)據(jù)并生成火焰圖為了不影響線上的正常服務(wù)我把剖析動(dòng)作放在了測(cè)試環(huán)境的同樣數(shù)據(jù)量上進(jìn)行然后用cProfile采集完整數(shù)據(jù)python -m cProfile -o task.prof task_runner.py數(shù)據(jù)采集完畢后我利用snakeviz庫快速生成可視化報(bào)表snakeviz task.profsnakeviz會(huì)在瀏覽器里打開一個(gè)交互式界面可以點(diǎn)擊任意函數(shù)查看它的累計(jì)耗時(shí)和調(diào)用關(guān)系。相比pstats的純文本輸出可視化界面的定位效率高很多。我在剖析報(bào)告里很快鎖定了三個(gè)耗時(shí)最高的函數(shù)一個(gè)數(shù)據(jù)清洗函數(shù)、一個(gè)正則匹配函數(shù)、一個(gè)JSON序列化函數(shù)。合起來占了總耗時(shí)的76%。這一步的關(guān)鍵是生成可復(fù)現(xiàn)的剖析數(shù)據(jù)。剖析結(jié)果要盡可能穩(wěn)定至少跑兩次如果兩次的結(jié)果差異很大說明程序行為受外部因素網(wǎng)絡(luò)波動(dòng)、磁盤IO競(jìng)爭(zhēng)影響明顯需要選擇數(shù)據(jù)量更可控的測(cè)試數(shù)據(jù)集。我見過不少新手在剖析時(shí)忽略了這一點(diǎn)結(jié)果被一次偶然的GC停頓帶偏了方向。3.3 第三步從耗時(shí)分布推斷根因并修復(fù)有了熱點(diǎn)函數(shù)清單接下來的分析才是真正考驗(yàn)經(jīng)驗(yàn)的部分。同樣是高耗時(shí)成因可能完全不同。以那個(gè)正則匹配函數(shù)為例我發(fā)現(xiàn)它消耗了40%的CPU時(shí)間。仔細(xì)檢查代碼后發(fā)現(xiàn)它用一個(gè)復(fù)合正則表達(dá)式去匹配一行很長(zhǎng)的日志文本而這個(gè)正則里包含多個(gè)交替分支pattern r(?:http://\S|\bERROR\b|status\d|timeout)問題在于當(dāng)文本不匹配時(shí)正則引擎需要嘗試所有分支組合發(fā)生復(fù)雜的回溯。修復(fù)方案是用前綴匹配分離這個(gè)復(fù)合正則比如先做if http:// in line的字符串預(yù)判斷再跑正則。這樣就能讓絕大多數(shù)無關(guān)行在第一步就被過濾掉。修改后這個(gè)函數(shù)的耗時(shí)從40%降到了3%。類似的正則性能問題我處理過不下十次字符串預(yù)篩選永遠(yuǎn)是最簡(jiǎn)單又最有效的手段。再看那個(gè)JSON序列化函數(shù)高耗時(shí)背后是死循環(huán)式的大量嵌套遍歷。原代碼在處理嵌套數(shù)據(jù)時(shí)反復(fù)序列化同一個(gè)子結(jié)構(gòu)——同一個(gè)子結(jié)構(gòu)被序列化了幾百次。修復(fù)方案是加一層緩存或者把結(jié)果存儲(chǔ)到臨時(shí)字段中避免重復(fù)計(jì)算。這個(gè)改動(dòng)看似不起眼但對(duì)海量數(shù)據(jù)來說減少的重復(fù)操作量是驚人的。數(shù)據(jù)清洗函數(shù)的耗時(shí)高則另有原因。它里面有一個(gè)排序操作用的Python自帶的列表sort()本以為沒有問題——但后來剖析數(shù)據(jù)顯示這個(gè)排序占用的比例遠(yuǎn)高于同規(guī)模數(shù)據(jù)排查后發(fā)現(xiàn)列表里存儲(chǔ)的是字典而排序時(shí)要反復(fù)調(diào)用key函數(shù)去抽取排序字段。優(yōu)化的方式很簡(jiǎn)單用operator.itemgetter替代lambda表達(dá)式作為key排序速度提升了接近一倍。3.4 第四步優(yōu)化后的驗(yàn)證與回歸我做完三處優(yōu)化后在相同數(shù)據(jù)量下重新運(yùn)行了一次剖析。優(yōu)化后的報(bào)告顯示原來三個(gè)熱點(diǎn)函數(shù)的CPU占用率大幅下降總耗時(shí)的前幾名已經(jīng)變成了文件讀取和數(shù)據(jù)庫寫入這兩個(gè)真正的IO密集型操作。此時(shí)程序的總執(zhí)行時(shí)間從3小時(shí)降回到35分鐘基本恢復(fù)到了正常水平。這里要特別強(qiáng)調(diào)一次“回歸剖析”的重要性。性能優(yōu)化最怕的是按下葫蘆浮起瓢——你覺得某個(gè)熱點(diǎn)解決了但代碼改動(dòng)引入了新的問題。所以每次優(yōu)化后都必須重新跑一遍剖析工具確認(rèn)熱點(diǎn)確實(shí)消失、沒有新的熱點(diǎn)冒出來。我自己的習(xí)慣是在數(shù)據(jù)量不變的前提下把優(yōu)化前后的火焰圖放在一起對(duì)比直觀看到熱點(diǎn)的轉(zhuǎn)移過程。這個(gè)步驟看似簡(jiǎn)單卻是保證優(yōu)化有效性的最后一道防線。4. 實(shí)戰(zhàn)中的常見誤區(qū)與排查心得工具會(huì)用了、流程也走通了但真正的差距往往體現(xiàn)在細(xì)節(jié)處理上。這一節(jié)我把這幾年在項(xiàng)目里踩過的坑、總結(jié)出的經(jīng)驗(yàn)挑幾個(gè)最有代表性的分享一下。4.1 誤區(qū)一只看總耗時(shí)忽略調(diào)用次數(shù)很多人拿到剖析報(bào)告第一反應(yīng)就是找總耗時(shí)最長(zhǎng)的函數(shù)這是不全面的?？偤臅r(shí)長(zhǎng)的函數(shù)確實(shí)值得關(guān)注但有些函數(shù)單次耗時(shí)不長(zhǎng)、調(diào)用次數(shù)卻極其驚人累計(jì)起來也是性能殺手。比如一個(gè)工具函數(shù)單次執(zhí)行只要0.1毫秒但是在一個(gè)循環(huán)里被調(diào)用了千萬次累計(jì)耗時(shí)高達(dá)100秒。排查這類問題要特別注意剖析報(bào)告里的tottime函數(shù)自身耗時(shí)和cumtime累計(jì)耗時(shí)之外的第三個(gè)維度調(diào)用次數(shù)ncalls。我建議養(yǎng)成一個(gè)習(xí)慣每次拿到剖析報(bào)告除了看耗時(shí)排序還專門看一遍調(diào)用次數(shù)排序。如果一個(gè)函數(shù)的調(diào)用次數(shù)比同模塊其他函數(shù)高出幾個(gè)數(shù)量級(jí)非常值得警惕看是不是循環(huán)里被無意中放進(jìn)了重復(fù)的計(jì)算。4.2 誤區(qū)二在錯(cuò)誤的環(huán)境里做剖析剖析結(jié)果的可靠性嚴(yán)重依賴運(yùn)行環(huán)境。在本地開發(fā)機(jī)高配、空閑CPU上剖析出來的熱點(diǎn)和生產(chǎn)環(huán)境多租戶、CPU爭(zhēng)搶、IO競(jìng)爭(zhēng)的實(shí)際情況可能有很大的差異。所以剖析環(huán)境最好盡量貼近真實(shí)運(yùn)行環(huán)境數(shù)據(jù)量要有代表性不能太少否則熱點(diǎn)不明顯負(fù)載要是常態(tài)負(fù)載不能摻雜大量并發(fā)用戶否則所有時(shí)間都耗在線程調(diào)度上機(jī)器配置和部署方式要和生產(chǎn)一致。舉個(gè)例子一個(gè)磁盤密集型應(yīng)用在本地SSD上剖析耗時(shí)占比最高的可能是一個(gè)計(jì)算函數(shù)但部署到生產(chǎn)環(huán)境的機(jī)械硬盤上后耗時(shí)占比最高的變成了磁盤IO等待。如果一開始就在錯(cuò)誤的環(huán)境里優(yōu)化等于對(duì)著錯(cuò)誤的靶子打了半天。所以我的習(xí)慣是線上問題優(yōu)先線上剖析用采樣工具比如py-spy、async-profiler、pprof線下復(fù)現(xiàn)只是補(bǔ)充。4.3 誤區(qū)三剖析工具本身的干擾被忽視插樁模式的剖析工具會(huì)給程序帶來額外開銷有時(shí)候這個(gè)開銷還不是平均分配的。比如cProfile在每個(gè)函數(shù)調(diào)用時(shí)都要記錄時(shí)間戳如果程序里有大量短小函數(shù)生成的剖析數(shù)據(jù)就會(huì)非常大而且程序自身的性能會(huì)被明顯拖慢。這類額外開銷會(huì)導(dǎo)致剖析結(jié)果出現(xiàn)“假熱點(diǎn)”——工具自身的邏輯消耗掉了大量CPU。為了避免這種情況我有幾個(gè)經(jīng)驗(yàn)。一是如果程序有明顯的短小函數(shù)簇優(yōu)先選擇采樣模式而不是插樁模式二是插樁剖析的時(shí)長(zhǎng)控制在合理范圍內(nèi)通常不超過幾分鐘避免數(shù)據(jù)量膨脹到無法分析三是在做剖析時(shí)關(guān)閉不必要的日志輸出避免日志IO干擾真實(shí)的熱點(diǎn)分布。4.4 內(nèi)存剖析和CPU剖析的思路完全不同不少新手以為內(nèi)存剖析和CPU剖析是同一套流程其實(shí)差異很大。CPU剖析關(guān)心的是“時(shí)間花在哪”內(nèi)存剖析關(guān)心的是“空間給了誰”。內(nèi)存問題通常分兩類泄漏和抖動(dòng)分析路徑截然不同。內(nèi)存泄漏的排查需要觀察不同時(shí)間點(diǎn)的堆快照對(duì)比哪些對(duì)象的存活數(shù)量在持續(xù)增長(zhǎng)。以Go語言為例我會(huì)分別取相隔5分鐘的兩次heap剖析數(shù)據(jù)go tool pprof http://localhost:6060/debug/pprof/heap # 輸入 top記住占用最大的類型 # 5分鐘后再取一次對(duì)比增長(zhǎng)增長(zhǎng)最快的對(duì)象類型往往就是泄漏源。接著用list命令下鉆到具體代碼行就能看到對(duì)象是在哪里被分配的。在Java里道理相同但工具有所不同。我一般會(huì)用async-profiler的alloc事件采集內(nèi)存分配熱點(diǎn)配合JFR的jdk.ObjectAllocationSample事件分析哪些代碼路徑觸發(fā)了大量對(duì)象分配。內(nèi)存抖動(dòng)則是另一番景象。這類問題在剖析報(bào)告里表現(xiàn)為GC時(shí)間占比很高比如Go的STW或Java的Young GC特別頻繁但堆快照里的存活對(duì)象并不多。遇到這種情況重點(diǎn)要關(guān)注對(duì)象分配速率找“每秒分配了大量對(duì)象”的代碼路徑而不是找“哪些對(duì)象一直活著”。這兩個(gè)方向經(jīng)常被混淆導(dǎo)致一大批人拿著內(nèi)存泄漏的思路查抖動(dòng)問題方向反了自然查不出結(jié)果。4.5 定位鎖競(jìng)爭(zhēng)需要結(jié)合線程狀態(tài)分析鎖競(jìng)爭(zhēng)問題在CPU剖析數(shù)據(jù)里常常不顯眼因?yàn)榫€程都在阻塞CPU占用率不高但響應(yīng)時(shí)間卻飆升。這時(shí)候分析線程狀態(tài)比分析CPU熱點(diǎn)更有效。在Go語言中可以直接用pprof分析goroutine阻塞情況go tool pprof http://localhost:6060/debug/pprof/block這個(gè)數(shù)據(jù)會(huì)明確顯示每個(gè)goroutine阻塞在哪里、阻塞了多長(zhǎng)時(shí)間一眼就能看出哪把鎖是最大的爭(zhēng)搶點(diǎn)。在Java中async-profiler的lock事件同樣能實(shí)現(xiàn)類似目的./profiler.sh -d 30 -e lock -o flamegraph PID生成火焰圖后鎖競(jìng)爭(zhēng)的火焰圖形態(tài)與CPU熱點(diǎn)完全不同。鎖競(jìng)爭(zhēng)火焰圖中占用大量面積的函數(shù)名稱通常是Lock::lock或Monitor::enter這類同步原語而不是業(yè)務(wù)代碼。看到這種形態(tài)就要從鎖的粒度、持鎖時(shí)間、鎖內(nèi)嵌套調(diào)用入手去優(yōu)化了。鎖競(jìng)爭(zhēng)優(yōu)化中常見的手段是減小鎖粒度、用讀寫鎖替代互斥鎖、用無鎖數(shù)據(jù)結(jié)構(gòu)替換加鎖操作但每次改動(dòng)后都一定要重新剖析火焰圖確認(rèn)競(jìng)爭(zhēng)點(diǎn)確實(shí)下降——我見過改完鎖反而引入死鎖的案例所以在鎖優(yōu)化上回歸驗(yàn)證永遠(yuǎn)不能省。4.6 從剖析到優(yōu)化的閉環(huán)思考最后想聊聊剖析和優(yōu)化之間的鏈路。剖析工具的價(jià)值不只是幫你找到問題更重要的是幫你建立“數(shù)據(jù)驅(qū)動(dòng)優(yōu)化”的思維模式。我用剖析工具這么多年最深刻的體會(huì)就是性能問題很少是“一個(gè)點(diǎn)”的問題而往往是多個(gè)因素疊加的結(jié)果。一次完整剖析之后會(huì)冒出一堆可以優(yōu)化的點(diǎn)此時(shí)必須抵抗住“看到什么就改什么”的沖動(dòng)而是把問題按影響程度排序然后定量分析每一個(gè)改動(dòng)的收益。我甚至給自己定了個(gè)規(guī)矩每做一次優(yōu)化改動(dòng)都必須回答三個(gè)問題——這個(gè)熱點(diǎn)的絕對(duì)耗時(shí)占比是多少優(yōu)化后的預(yù)期收益是多少優(yōu)化會(huì)不會(huì)引入新風(fēng)險(xiǎn)三個(gè)問題都能回答才動(dòng)手改代碼。還有一點(diǎn)剖析不是一錘子買賣。代碼是持續(xù)迭代的每次發(fā)版后性能都可能發(fā)生變化。我現(xiàn)在負(fù)責(zé)的項(xiàng)目組里已經(jīng)養(yǎng)成了每個(gè)版本發(fā)布前跑一次剖析的習(xí)慣不求每次都深入優(yōu)化但至少要確保沒有新的性能退化。這樣做了半年以后線上性能事故的發(fā)生頻率明顯下降了。我建議有條件的朋友可以把剖析納入持續(xù)集成的流程里雖然初期會(huì)花一點(diǎn)時(shí)間但長(zhǎng)期來看這筆投入的回報(bào)率非常高。真正優(yōu)秀的性能優(yōu)化不是靠靈光一現(xiàn)而是靠一套可重復(fù)、可驗(yàn)證的方法論。剖析工具就是這套方法論的核心引擎。平時(shí)多花點(diǎn)時(shí)間把工具吃透、把流程理順等線上真正出問題的時(shí)候你就能比別人快一步、穩(wěn)一步。這也是我寫這篇長(zhǎng)文的初衷——把這些經(jīng)驗(yàn)傳給更多人讓大家在性能調(diào)優(yōu)的路上少踩一些我當(dāng)年踩過的坑。