FISCO BCOS工程師經常使用的性能分析工具推薦

FISCO BCOS是徹底開源的聯盟區塊鏈底層技術平臺，由金融區塊鏈合做聯盟(深圳)(簡稱金鍊盟)成立開源工做組通力打造。開源工做組成員包括博彥科技、華爲、深證通、神州數碼、四方精創、騰訊、微衆銀行、亦筆科技和越秀金科等金鍊盟成員機構。

代碼倉庫：https://github.com/FISCO-BCOS

 

前 言

We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil. Yet we should not pass up our opportunities in that critical 3%.

『過早的優化是萬惡之源』

說出這句話的計算機科學先驅Donald Knuth並非反對優化，而是強調要對系統中的關鍵位置進行優化。假設一個for循環耗時0.01秒，即便使用循環展開等各類奇技淫巧將其性能提高100倍，把耗時降到0.00001秒，對於用戶而言，也基本沒法感知到。對性能問題進行量化測試以前，在代碼層面進行各類炫技式優化，可能不只提高不了性能，反而會增長代碼維護難度或引入更多錯誤。

『沒有任何證據支撐的優化是萬惡之源』

在對系統施展優化措施前，必定要對系統進行詳盡的性能測試，從而找出真正的性能瓶頸。奮戰在FISCO BCOS性能優化的前線上，咱們對如何使用性能測試工具來精肯定位性能熱點這件事積累了些許經驗心得。本文將咱們在優化過程當中使用到的工具進行了整理彙總，以饗讀者。

 

1.Poor Man's Profiler

 

窮人的分析器，簡稱PMP。儘管名字有些讓人摸不着頭腦，但人家真的是一種正經的性能分析手段，甚至有本身的官方網站https://poormansprofiler.org/。PMP的原理是Stack Sampling，經過調用第三方調試器（好比gdb），反覆獲取進程中每一個線程的堆棧信息，PMP即可以獲得目標進程的熱點分佈。

 

第一步，獲取必定數量的線程堆棧快照：

pid=$(pidof fisco-bcos)num=10for x in $(seq 1 $(num))dogdb -ex "set pagination 0" -ex "thread apply all bt" -batch -p $pidsleep 0.5done

 

第二步，從快照中取出函數調用棧信息，按照調用頻率排序：

awk 'BEGIN { s = ""; }/^Thread/ { print s; s = ""; }/^\#/ { if (s != "" ) { s = s "," $4} else { s = $4 } }END { print s }' | \sort | uniq -c | sort -r -n -k

 

最後獲得輸出，以下圖所示：

從輸出中能夠觀察到哪些線程的哪些函數被頻繁採樣，進而可按圖索驥找出可能存在的瓶頸。上述寥寥數行shell腳本即是PMP所有精華之所在。極度簡單易用是PMP的最大賣點，除了依賴一個隨處可見的調試器外，PMP不須要安裝任何組件，正如PMP做者在介紹中所言：『儘管存在更高級的分析技術，但毫無例外它們安裝起來都太麻煩了……Poor man doesn't have time. Poor man needs food.』😝。

PMP的缺點也比較明顯：gdb的啓動很是耗時，限制了PMP的採樣頻率不能過高，所以一些重要的函數調用事件可能會被遺漏，從而致使最後的profile結果不夠精確。

可是在某些特殊場合，PMP仍是能發揮做用的，好比在一些中文技術博客中，就有開發人員提到使用PMP成功定位出了線上生產環境中的死鎖問題，PMP做者也稱這項技術在Facebook、Intel等大廠中有所應用。無論怎樣，這種閃爍着程序員小智慧又帶點小幽默的技術，值得一瞥。

 

2.perf

 

perf的全稱是Performance Event，在2.6.31版本後的Linux內核中均有集成，是Linux自帶的強力性能分析工具，使用現代處理器中的特殊硬件PMU（Performance Monitor Unit，性能監視單元）和內核性能計數器統計性能數據。

perf的工做方式是對運行中的進程按必定頻率進行中斷採樣，獲取當前執行的函數名及調用棧。若是大部分的採樣點都落在同一個函數上，則代表該函數執行的時間較長或該函數被頻繁調用，可能存在性能問題。

使用perf須要首先對目標進程進行採樣：

$ sudo perf record -F 1000 -p `pidof fisco-bcos` -g -- sleep 60

 

在上述命令中， 咱們使用perf record指定記錄性能的統計數據；使用-F指定採樣的頻率爲1000Hz，即一秒鐘採樣1000次；使用-p指定要採樣的進程ID（既fisco-bcos的進程ID），咱們能夠直接經過pidof命令獲得；使用-g表示記錄調用棧信息；使用sleep指定採樣持續時間爲60秒。

待採樣完成後，perf會將採集到的性能數據寫入當前目錄下的perf.data文件中。

$ perf report -n

上述命令會讀取perf.data並統計每一個調用棧的百分比，且按照從高到低的順序排列，以下圖所示：

信息已足夠豐富，但可讀性仍然不太友好。儘管示例中perf的用法較爲簡單，但實際上perf能作的遠不止於此。配合其餘工具，perf採樣出的數據可以以更加直觀清晰的方式展示在咱們面前，這即是咱們接下來要介紹的性能分析神器——火焰圖。

 

3.火焰圖

 

火焰圖，即Flame Graph，藉由系統性能大牛 Brendan Gregg提出的動態追蹤技術而發揚光大，主要用於將性能分析工具生成的數據進行可視化處理，方便開發人員一眼就能定位到性能問題所在。火焰圖的使用較爲簡單，咱們僅需將一系列工具從github上下載下來，置於本地任一目錄便可：​​​​​​​

wget https://github.com/brendangregg/FlameGraph/archive/master.zipunzip master.zip

 

3.一、CPU火焰圖

當咱們發現FISCO BCOS性能較低時，直覺上會想弄清楚究竟是哪一部分的代碼拖慢了總體速度，CPU是咱們的首要考察對象。

首先使用perf對FISCO BCOS進程進行性能採樣：​​​​​​​

sudo perf record  -F 10000 -p `pidof fisco-bcos` -g -- sleep 60# 對採樣數據文件進行解析生成堆棧信息sudo perf script > cpu.unfold

生成了採樣數據文件後，接下來調用火焰圖工具生成火焰圖：​​​​​​​

# 對perf.unfold進行符號摺疊sudo ./stackcollapse-perf.pl cpu.unfold > cpu.folded# 生成SVG格式的火焰圖sudo ./flamegraph.pl  cpu.folded > cpu.svg

最後輸出一個SVG格式圖片，用來展現CPU的調用棧，以下圖所示：

縱軸表示調用棧。每一層都是一個函數，也是其上一層的父函數，最頂部就是採樣時正在執行的函數，調用棧越深，火焰就越高。

橫軸表示抽樣數。注意，並非表示執行時間。若一個函數的寬度越寬，則表示它被抽到的次數越多，全部調用棧會在彙總後，按字母序列排列在橫軸上。

火焰圖使用了SVG格式，可交互性大大提升。在瀏覽器中打開時，火焰的每一層都會標註函數名，當鼠標懸浮其上，會顯示完整的函數名、被抽樣次數和佔總抽樣字數的百分比，以下：

點擊某一層時，火焰圖會水平放大，該層會佔據全部寬度，並顯示詳細信息，點擊左上角的『Reset Zoom』便可還原。下圖展現了PBFT模塊在執行區塊時，各個函數的抽樣數佔比：

從圖中能夠看出，在執行區塊時，主要開銷在交易的解碼中，這是因爲傳統的RLP編碼在解碼時，RLP編碼中每一個對象的長度不肯定，且RLP編碼只記錄了對象的個數，沒記錄對象的字節長度，若要獲取其中的一個編碼對象，必須遞歸解碼其前序的全部對象。

所以，RLP編碼的解碼過程是一個串行的過程，當區塊中交易數量較大時，這一部分的開銷將變得十分巨大。對此，咱們提出了一種並行解碼RLP編碼的優化方案，具體實現細節能夠參考上一篇文章《FISCO BCOS中的並行化實踐 》。

有了火焰圖，可以很是方便地查看CPU的大部分時間開銷都消耗在何處，進而也能針對性進行優化了。

 

3.二、Off-CPU火焰圖

在實現FISCO BCOS的並行執行交易功能時，咱們發現有一個使人困惑的現象：有時即便交易量很是大，區塊的負載已經打滿，可是經過top命令觀察到CPU的利用率仍然比較低，一般4核CPU的利用率不足200%。在排除了交易間存在依賴關係的可能後，推測CPU可能陷入了I/O或鎖等待中，所以須要肯定CPU到底在什麼地方等待。

使用perf，咱們能夠輕鬆地瞭解系統中任何進程的睡眠過程，其原理是利用perf static tracer抓取進程的調度事件，並經過perf inject對這些事件進行合併，最終獲得誘發進程睡眠的調用流程以及睡眠時間。

咱們要經過perf分別記錄sched:sched_stat_sleep、sched:sched_switch、sched:sched_process_exit三種事件，這三種事件分別表示進程主動放棄 CPU 而進入睡眠的等待事件、進程因爲I/O和鎖等待等緣由被調度器切換而進入睡眠的等待事件、進程的退出事件。​​​​​​​

perf record -e sched:sched_stat_sleep -e sched:sched_switch \-e sched:sched_process_exit -p `pidof fisco-bcos` -g \-o perf.data.raw sleep 60perf inject -v -s -i perf.data.raw -o perf.data# 生成Off-CPU火焰圖perf script -f comm,pid,tid,cpu,time,period,event,ip,sym,dso,trace | awk 'NF > 4 { exec = $1; period_ms = int($5 / 1000000) }NF > 1 && NF <= 4 && period_ms > 0 { print $2 }NF < 2 && period_ms > 0 { printf "%s\n%d\n\n", exec, period_ms }' | \./stackcollapse.pl | \./flamegraph.pl --countname=ms --title="Off-CPU Time Flame Graph" --colors=io > offcpu.svg

在較新的Ubuntu或CentOS系統中，上述命令可能會失效，出於性能考慮，這些系統並不支持記錄調度事件。好在咱們能夠選擇另外一種profile工具——OpenResty的SystemTap，來替代perf幫助咱們收集進程調度器的性能數據。咱們在CentOS下使用SystemTap時，只須要安裝一些依賴kenerl debuginfo便可使用。​​​​​​​

wget https://raw.githubusercontent.com/openresty/openresty-systemtap-toolkit/master/sample-bt-off-cpuchmod +x sample-bt-off-cpu./sample-bt-off-cpu -t 60 -p `pidof fisco-bcos` -u > out.stap./stackcollapse-stap.pl out.stap > out.folded./flamegraph.pl --colors=io out.folded > offcpu.svg

獲得的Off-CPU火焰圖以下圖所示：

展開執行交易的核心函數後，位於火焰圖中右側的一堆lock_wait很快引發了咱們的注意。分析過它們的調用棧後，咱們發現這些lock_wait的根源，來自於咱們在程序中有大量打印debug日誌的行爲。

在早期開發階段，咱們爲了方便調試，添加了不少日誌代碼，後續也沒有刪除。雖然咱們在測試過程當中將日誌等級設置得較高，但這些日誌相關的代碼仍會產生運行時開銷，如訪問日誌等級狀態來決定是否打印日誌等。因爲這些狀態須要線程間互斥訪問，所以致使線程因爲競爭資源而陷入飢餓。

咱們將這些日誌代碼刪除後，執行交易時4核CPU的利用率瞬間升至300%+，考慮到線程間調度和同步的開銷，這個利用率已屬於正常範圍。此次調試的經歷也提醒了咱們，在追求高性能的並行代碼中輸出日誌必定要謹慎，避免因爲沒必要要的日誌而引入無謂的性能損失。

 

3.3 、內存火焰圖

在FISCO BCOS早期測試階段，咱們採起的測試方式是反覆執行同一區塊，再計算執行一個區塊平均耗時，咱們發現，第一次執行區塊的耗時會遠遠高於後續執行區塊的耗時。從表象上看，這彷佛是在第一次執行區塊時，程序在某處分配了緩存，然而咱們並不知道具體是在何處分配的緩存，所以咱們着手研究了內存火焰圖。

內存火焰圖是一種非侵入式的旁路分析方法，相較於模擬運行進行內存分析的Valgrid和統計heap使用狀況的TC Malloc，內存火焰圖能夠在獲取目標進程的內存分配狀況的同時不干擾程序的運行。

製做內存火焰圖，首先須要向perf動態添加探針以監控標準庫的malloc行爲，並採樣捕捉正在進行內存申請/釋放的函數的調用堆棧：

perf record -e probe_libc:malloc -F 1000 -p `pidof fisco-bcos` -g -- sleep 60

 

而後繪製內存火焰圖：​​​​​​​

perf script > memory.perf./stackcollapse-perf.pl memory.perf > memory.folded./flamegraph.pl  --colors=mem memory.folded > memory.svg

獲得的火焰圖以下圖所示：

咱們起初猜測，這塊未知的緩存可能位於LevelDB的數據庫鏈接模塊或JSON解碼模塊中，但經過比對第一次執行區塊和後續執行區塊的內存火焰圖，咱們發現各個模塊中malloc採樣數目的比例大體相同，所以很快便將這些猜測否認掉了。直到結合Off-CPU火焰圖觀察，咱們才注意到第一次執行區塊時調用sysmalloc的次數異常之高。聯想到malloc會在首次被調用時進行內存預分配的特性，咱們猜測第一次執行區塊耗時較多可能就是由此形成的。

爲驗證猜測，咱們將malloc的預分配空間上限調低：

export MALLOC_ARENA_MAX=1

 

而後再次進行測試並繪製Off-CPU火焰圖，發現雖然性能有所下降，可是第一次執行區塊的耗時和sysmalloc調用次數，基本無異於以後執行的區塊。據此，咱們基本能夠判定這種有趣的現象是因爲malloc的內存預分配行爲致使。

固然，這種行爲是操做系統爲了提升程序總體性能而引入的，咱們無需對其進行干涉，何況第一個區塊的執行速度較慢，對用戶體驗幾乎也不會形成負面影響，可是再小的性能問題也是問題，做爲開發人員咱們應當刨根問底，作到知其然且知其因此然。

雖然此次Memory火焰圖並無幫咱們直接定位到問題的本質緣由，但經過直觀的數據比對，咱們可以方便地排除錯誤的緣由猜測，減小了大量的試錯成本。面對複雜的內存問題，不只須要有敏銳的嗅覺，更須要Memory火焰圖這類好幫手。

 

4.DIY工具

儘管已經有如此多優秀的分析工具，幫助咱們在性能優化前進的道路上披荊斬棘，但強大的功能有時也會趕不上性能問題的多變性，這種時候就須要咱們結合自身的需求，自給自足地開發分析工具。

在進行FISCO BCOS的穩定性測試時，咱們發現隨着測試時間的增加，FISCO BCOS節點的性能呈現衰減趨勢，咱們須要獲得全部模塊的性能趨勢變化圖，以排查出致使性能衰減的元兇，但現有的性能分析工具基本沒法快速、便捷地實現這一需求，所以咱們選擇另尋他路。

首先，咱們在代碼中插入大量的樁點，這些樁點用於測量咱們感興趣的代碼段的執行耗時，並將其附加上特殊的標識符記錄於日誌中：​​​​​​​

auto startTime = utcTime();/*...code to be measured...*/auto endTime = utcTime();auto elapsedTime = endTime - startTime;LOG(DEBUG) << MESSAGE("<identifier>timeCost: ") \<< MESSAGE(to_string(elspasedTime));

當節點性能已經開始明顯降低後，咱們將其日誌導出，使用本身編寫的Python腳本將日誌以區塊爲單位進行分割，隨後讀取每一個區塊在執行時產生的樁點日誌，並解析出各個階段的耗時，而後由腳本彙總到一張大的Excel表格中，最後再直接利用Excel自帶的圖表功能，繪製出全部模塊的性能趨勢變化圖，以下圖所示：

其中，橫座標爲區塊高度，縱座標爲執行耗時（ms），不一樣顏色曲線表明了不一樣模塊的性能變化。

從圖中能夠看出，只有由紅色曲線表明的區塊落盤模塊的執行耗時明顯地隨着數據庫中數據量的增大而迅速增長，由此能夠判斷節點性能衰減問題的根源就出在區塊落盤模塊中。使用一樣的方式，對區塊落盤模塊的各個函數進一步剖析，咱們發現節點在向數據庫提交新的區塊數據時，調用的是LevelDB的update方法，並不是insert方法。

二者的區別是，因爲LevelDB以K-V的形式存儲數據，update方法在寫入數據前會進行select操做，由於待update的數據可能在數據庫中已存在，須要先按Key查詢出Value的數據結構才能進行修改，而查詢的耗時與數據量成正比，insert方法則徹底不須要這一步。因爲咱們寫入的是全新的數據，所以查詢這一步是沒必要要的，只需改變數據寫入的方式，節點性能衰減的問題便迎刃而解。

相同的工具稍微變換一下用法，就能衍生出其餘的用途，好比：將兩批樁點性能數據放入同一張Excel表格中，便可以經過柱狀圖工具清晰地展示兩次測試結果的性能變化。

下圖展現的是咱們在優化交易解碼及驗籤流程時，優化先後性能柱狀對比圖：

從圖中能夠看出，交易解碼和驗籤流程優化後的耗時的確比優化前有所下降。藉由柱狀對比圖，咱們可以輕鬆地檢查優化手段是否行之有效，這一點在性能優化的過程當中起到了重要的指導做用。

綜上可見，DIY工具並不必定須要有多複雜，但必定能夠最快地知足咱們的定製化需求。

 

---

 

咱們鼓勵機構成員、開發者等社區夥伴參與開源共建事業，有你在一塊兒，會更了不得。多樣參與方式：

1 進入微信社羣，隨時隨地與圈內最活躍、最頂尖的團隊暢聊技術話題（進羣請添加小助手微信，微信ID：fiscobcosfan）；

2 訂閱咱們的公衆號：「FISCO BCOS開源社區」，咱們爲你準備了開發資料庫、最新FISCO BCOS動態、活動、大賽等信息；

3 來Meetup與開發團隊面對面交流，FISCO BCOS正在全國舉辦巡迴Meetup，深圳、北京、上海、成都……歡迎您公衆號在菜單欄【找活動】中找到附近的Meetup，前往結識技術大咖，暢聊硬核技術；

4 參與代碼貢獻，您能夠在Github提交Issue進行問題交流，歡迎向FISCO BCOS提交Pull Request，包括但不限於文檔修改、修復發現的bug、提交新的功能特性。

代碼貢獻指引：

https://github.com/FISCO-BCOS/FISCO-BCOS/blob/master/docs/CONTRIBUTING_CN.md

 

本文首發於公衆號【FISCO BCOS開源社區】，如轉載請註明出處，原創不易，謝謝珍惜