動態追蹤技術(中) - Dtrace、SystemTap、火焰圖

ronon77發表於2016-05-06

動態追蹤技術中篇,關於 DTrace、SystemTap 和 火焰圖的那點事。

DTrace 與 SystemTap

說到動態追蹤就不能不提到 DTrace(1) 。DTrace 算是現代動態追蹤技術的鼻祖了,它於 21 世紀初誕生於 Solaris 作業系統,是由原來的 Sun Microsystems 公司的工程師編寫的。可能很多同學都聽說過 Solaris 系統和 Sun 公司的大名。

最初產生的時候,我記得有這樣一個故事,當時 Solaris 作業系統的幾個工程師花了幾天幾夜去排查一個看似非常詭異的線上問題。開始他們以為是很高階的問題,就特別賣力,結果折騰了幾天,最後發現其實是一個非常愚蠢的、某個不起眼的地方的配置問題。自從那件事情之後,這些工程師就痛定思痛,創造了 DTrace 這樣一個非常高階的除錯工具,來幫助他們在未來的工作當中避免把過多精力花費在愚蠢問題上面。畢竟大部分所謂的“詭異問題”其實都是低階問題,屬於那種“調不出來很鬱悶,調出來了更鬱悶”的型別。

應該說 DTrace 是一個非常通用的除錯平臺,它提供了一種很像 C 語言的指令碼語言,叫做 D。基於 DTrace 的除錯工具都是使用這種語言編寫的。D 語言支援特殊的語法用以指定“探針”,這個“探針”通常有一個位置描述的資訊。你可以把它定位在某個核心函式的入口或出口,抑或是某個使用者態程式的 函式入口或出口,甚至是任意一條程式語句或機器指令上面。編寫 D 語言的除錯程式是需要對系統有一定的瞭解和知識的。這些除錯程式是我們重拾對複雜系統的洞察力的利器。Sun 公司有一位工程師叫做 Brendan Gregg,他是最初的 DTrace 的使用者,甚至早於 DTrace 被開源出來。Brendan 編寫了很多可以複用的基於 DTrace 的除錯工具,一齊放在一個叫做 DTrace Toolkit(2) 的開源專案中。Dtrace 是最早的動態追蹤框架,也是最有名的一個。

DTrace 的優勢是它採取了跟作業系統核心緊密整合的一種方式。D 語言的實現其實是一個虛擬機器(VM),有點像 Java 虛擬機器(JVM)。它的一個好處在於 D 語言的執行時是常駐核心的,而且非常小巧,所以每個除錯工具的啟動時間和退出時間都很短。但是我覺得 DTrace 也是有明顯缺點的。其中一個讓我很難受的缺點是 D 語言缺乏迴圈結構,這導致許多針對目標程式中的複雜資料結構的分析工具很難編寫。雖然 DTrace 官方聲稱缺少迴圈的原因是為了避免過熱的迴圈,但顯然 DTrace 是可以在 VM 級別上面有效限制每一個迴圈的執行次數的。另外一個較大的缺點是,DTrace 對於使用者態程式碼的追蹤支援比較弱,沒有自動的載入使用者態除錯符號的功能,需要自己在 D 語言裡面宣告用到的使用者態 C 語言結構體之類的型別。

DTrace 的影響是非常大的,很多工程師把它移植到其他的作業系統。比方說蘋果的 Mac OS X 作業系統上就有 DTrace 的移植。其實近些年釋出的每一臺蘋果筆記本或者桌上型電腦上面,都有現成的 dtrace 命令列工具可以呼叫,大家可以去在蘋果機器的命令列終端上嘗試一下。這是蘋果系統上面的一個 DTrace 的移植。FreeBSD 作業系統也有這樣一個 DTrace 的移植。只不過它並不是預設啟用的。你需要通過命令去載入 FreeBSD 的 DTrace 核心模組。Oracle 也有在它自己的 Oracle Linux 作業系統發行版當中開始針對 Linux 核心進行 DTrace 移植。不過 Oracle 的移植工作好像一直沒有多少起色,畢竟 Linux 核心並不是 Oracle 控制的,而 DTrace 是需要和作業系統核心緊密整合的。出於類似的原因,民間一些勇敢的工程師嘗試的 DTrace 的 Linux 移植也一直距離生產級別的要求很遠。

相比 Solaris 上面原生的 DTrace,這些 DTrace 移植都或多或少的缺乏某些高階特性,所以從能力上來說,還不及最本初的 DTrace。

DTrace 對 Linux 作業系統的另一個影響反映在 SystemTap(3) 這個開源專案。這是由 Red Hat 公司的工程師建立的較為獨立的動態追蹤框架。SystemTap 提供了自己的一種小語言(4),和 D 語言並不相同。顯然,Red Hat 自己服務於非常多的企業級使用者,他們的工程師每天需要處理的各種線上的“詭異問題”自然也是極多的。這種技術的產生必然是現實需求激發的。我覺得 SystemTap 是目前 Linux 世界功能最強大,同時也是最實用的動態追蹤框架。我在自己的工作當中已經成功使用多年。SystemTap 的作者 Frank Ch. Eigler 和 Josh Stone 等人,都是非常熱情、同時非常聰明的工程師。我在 IRC 或者郵件列表裡的提問,他們一般都會非常快且非常詳盡地進行解答。值得一提的是,我也曾給 SystemTap 貢獻過一個較為重要的新特性,使其能在任意的探針上下文中訪問使用者態的全域性變數的取值。我當時合併到 SystemTap 主線的這個 C++ 補丁(5)的規模達到了約一千行,多虧了 SystemTap 作者們的熱心幫助。這個新特性在我基於 SystemTap 實現的動態指令碼語言(比如 Perl 和 Lua)的火焰圖(6)工具中扮演了關鍵角色。

SystemTap 的優點是它有非常成熟的使用者態除錯符號的自動載入,同時也有迴圈這樣的語言結構可以去編寫比較複雜的探針處理程式,可以支援很多很複雜的分析處理。由於 SystemTap 早些年在實現上的不成熟,導致網際網路上充斥著很多針對它的已經過時了的詬病和批評。最近幾年 SystemTap 已然有了長足的進步。

當然,SystemTap 也是有缺點的。首先,它並不是 Linux 核心的一部分,就是說它並沒有與核心緊密整合,所以它需要一直不停地追趕主線核心的變化。另一個缺點是,它通常是把它的“小語言”指令碼(有點像 D 語言哦)動態編譯成一個 Linux 核心模組的 C 原始碼,因此經常需要線上部署 C 編譯器工具鏈和 Linux 核心的標頭檔案,同時需要動態地載入這些編譯出來的核心模組,以執行我們的除錯邏輯。在我們的除錯工具執行完畢之後,又存在動態解除安裝 Linux 核心模組的問題。出於這些原因,SystemTap 指令碼的啟動相比 DTrace 要慢得多,和 JVM 的啟動時間倒有幾分類似。雖然存在這些缺點,但總的來說,SystemTap 還是一個非常成熟的動態追蹤框架。

Systemtap 工作原理圖

無論是 DTrace 還是 SystemTap,其實都不支援編寫完整的除錯工具,因為它們都缺少方便的命令列互動的原語。所以我們才看到現實世界中許多基於它們的工具,其實最外面都有一個 Perl、Python 或者 Shell 指令碼編寫的包裹。為了便於使用一種乾淨的語言編寫完整的除錯工具,我曾經給 SystemTap 語言進行了擴充套件,實現了一個更高層的“巨集語言”,叫做 stap++(7)。我自己用 Perl 實現的 stap++ 直譯器可以直接解釋執行 stap++ 原始碼,並在內部呼叫 SystemTap 命令列工具。有興趣的朋友可以檢視我開源在 GitHub 上面的 stapxx 這個程式碼倉庫。這個倉庫裡面也包含了很多直接使用我的 stap++ 巨集語言實現的完整的除錯工具。

SystemTap 在生產上的應用

DTrace 有今天這麼大的影響離不開著名的 DTrace 佈道士 Brendan Gregg(8) 老師。前面我們也提到了他的名字。他最初是在 Sun Microsystems 公司,工作在 Solaris 的檔案系統優化團隊,是最早的 DTrace 使用者。他寫過好幾本有關 DTrace 和效能優化方面的書,也寫過很多動態追蹤方面的部落格文章。

2011 年我離開淘寶以後,曾經在福州過了一年所謂的“田園生活”。在田園生活的最後幾個月當中,我通過 Brendan 的公開部落格(9)較為系統地學習了 DTrace 和動態追蹤技術。其實最早聽說 DTrace 是因為一位微博好友的評論,他只提到了 DTrace 這個名字。於是我便想了解一下這究竟是什麼東西。誰知,不瞭解不知道,一瞭解嚇一跳。這竟然是一個全新的世界,徹底改變了我對整個計算世界的看法。於是我就花了非常多的時間,一篇一篇地仔細精讀 Brendan 的個人部落格。後來終於有一天,我有了一種大徹大悟的感覺,終於可以融會貫通,掌握到了動態追蹤技術的精妙。

2012 年我結束了在福州的“田園生活”,來到美國加入目前這家 CDN 公司。然後我就立即開始著手把 SystemTap 以及我已領悟到的動態追蹤的一整套方法,應用到這家 CDN 公司的全球網路當中去,用於解決那些非常詭異非常奇怪的線上問題。我在這家公司觀察到其實很多工程師在排查線上問題的時候,經常會自己在軟體系統裡面埋點。這主要是在業務程式碼裡,乃至於像 Nginx 這樣的系統軟體的程式碼基(code base)裡,自己去做修改,新增一些計數器,或者去埋下一些記錄日誌的點。通過這種方式,大量的日誌會線上上被實時地採集起來,進入專門的資料庫,然後再進行離線分析。顯然這種做法的成本是巨大的,不僅涉及業務系統本身的修改和維護成本的陡然提高,而且全量採集和儲存大量的埋點資訊的線上開銷,也是非常可觀的。而且經常出現的情況是,張三今天在業務程式碼裡面埋了一個採集點,李四明天又埋下另一個相似的點,事後可能這些點又都被遺忘在了程式碼基裡面,而沒有人再去理會。最後這種點會越來越多,把程式碼基搞得越來越凌亂。這種侵入式的修改,會導致相應的軟體,無論是系統軟體還是業務程式碼,變得越來越難以維護。

埋點的方式主要存在兩大問題,一個是“太多”的問題,一個是“太少”的問題。“太多”是指我們往往會採集一些根本不需要的資訊,只是一時貪多貪全,從而造成不必要的採集和儲存開銷。很多時候我們通過取樣就能進行分析的問題,可能會習慣性的進行全網全量的採集,這種代價累積起來顯然是非常昂貴的。那“太少”的問題是指,我們往往很難在一開始就規劃好所需的所有資訊採集點,畢竟沒有人是先知,可以預知未來需要排查的問題。所以當我們遇到新問題時,現有的採集點蒐集到的資訊幾乎總是不夠用的。這就導致頻繁地修改軟體系統,頻繁地進行上線操作,大大增加了開發工程師和運維工程師的工作量,同時增加了線上發生更大故障的風險。

另外一種暴力除錯的做法也是我們某些運維工程師經常採用的,即把機器拉下線,然後設定一系列臨時的防火牆規則,以遮蔽使用者流量或者自己的監控流量,然後在生產機上各種折騰。這是很繁瑣影響很大的過程。首先它會讓機器不能再繼續服務,降低了整個線上系統的總的吞吐能力。同時有些只有真實流量才能復現的問題,此時再也無法復現了。可以想象這些粗暴的做法有多麼讓人頭疼。

實際上運用 SystemTap 動態追蹤技術可以很好地解決這樣的問題,有“潤物細無聲”之妙。首先我們不需要去修改我們的軟體棧(software stack)本身,不管是系統軟體還是業務軟體。我經常會編寫一些有針對性的工具,然後在一些關鍵的系統「穴位」上面放置一些經過仔細安排的探針。這些探針會採集各自的資訊,同時除錯工具會把這些資訊彙總起來輸出到終端。用這種方式我可以在某一臺機器或某幾臺機器上面,通過取樣的方式,很快地得到我想要的關鍵資訊,從而快速地回答一些非常基本的問題,給後續的除錯工作指明方向。

正如我前面提到的,與其在生產系統裡面人工去埋點去記日誌,再蒐集日誌入庫,還不如把整個生產系統本身看成是一個可以直接查詢的“資料庫”,我們直接從這個“資料庫”裡安全快捷地得到我們想要的資訊,而且絕不留痕跡,絕不去採集我們不需要的資訊。利用這種思想,我編寫了很多除錯工具,絕大部分已經開源在了 GitHub 上面,很多是針對像 Nginx、LuaJIT 和作業系統核心這樣的系統軟體,也有一些是針對更高層面的像 OpenResty 這樣的 Web 框架。有興趣的朋友可以檢視 GitHub 上面的 nginx-systemtap-toolkit(10)perl-systemtap-toolkit(11)和 stappxx(12) 這幾個程式碼倉庫。


我的 SystemTap 工具雲

利用這些工具,我成功地定位了數不清的線上問題,有些問題甚至是我意外發現的。下面就隨便舉幾個例子吧。

第一個例子是,我使用基於 SystemTap 的火焰圖工具分析我們線上的 Nginx 程式,結果發現有相當一部分 CPU 時間花費在了一條非常奇怪的程式碼路徑上面。這其實是我一位同事在很久之前除錯一個老問題時遺留下來的臨時的除錯程式碼,有點兒像我們前面提到的“埋點程式碼”。結果它就這樣被遺忘在了線上,遺忘在了公司程式碼倉庫裡,雖然當時那個問題其實早已解決。由於這個代價高昂的“埋點程式碼”一直沒有去除,所以一直都產生著較大的效能損耗,而一直都沒有人注意到。所以可謂是我意外的發現。當時我就是通過取樣的方式,讓工具自動繪製出一張火焰圖。我一看這張圖就可以發現問題並能採取措施。這是非常非常有效的方式。

第二個例子是,很少量的請求存在延時較長的問題,即所謂的“長尾請求”。這些請求數目很低,但可能達到「秒級」這樣的延時。當時有同事亂猜說是我的 OpenResty 有 bug,我不服氣,於是立即編寫了一個 SystemTap 工具去線上進行取樣,對那些超過一秒總延時的請求進行分析。該工具會直接測試這些問題請求內部的時間分佈,包括請求處理過程中各個典型 I/O 操作的延時以及純 CPU 計算延時。結果很快定位到是 OpenResty 在訪問 Go 編寫的 DNS 伺服器時,出現延時緩慢。然後我再讓我的工具輸出這些長尾 DNS 查詢的具體內容,發現都是涉及 CNAME 展開。顯然,這與OpenResty 無關了,而進一步的排查和優化也有了明確的方向。

第三個例子是,我們曾注意到某一個機房的機器存在比例明顯高於其他機房的網路超時的問題,但也只有 1% 的比例。一開始我們很自然的去懷疑網路協議棧方面的細節。但後來我通過一系列專門的 SystemTap 工具直接分析那些超時請求的內部細節,便定位到了是硬碟 配置方面的問題。從網路到硬碟,這種除錯是非常有趣的。第一手的資料讓我們快速走上正確的軌道。

還有一個例子是,我們曾經通過火焰圖在 Nginx 程式裡觀察到檔案的開啟和關閉操作佔用了較多的 CPU 時間,於是我們很自然地啟用了 Nginx 自身的檔案控制程式碼快取配置,但是優化效果並不明顯。於是再做出一張新的火焰圖,便發現因為這回輪到 Nginx 的檔案控制程式碼快取的後設資料所使用的“自旋鎖”佔用很多 CPU 時間了。這是因為我們雖然啟用了快取,但把快取的大小設定得過大,所以導致後設資料的自旋鎖的開銷抵消掉了快取帶來的好處。這一切都能在火焰圖上面一目瞭然地看出來。假設我們沒有火焰圖,而只是盲目地試驗,很可能會得出 Nginx 的檔案控制程式碼快取沒用的錯誤結論,而不會去想到去調整快取的引數。

最後一個例子是,我們在某一次上線操作之後,線上上最新的火焰圖中觀察到正規表示式的編譯操作佔用了很多 CPU 時間,但其實我們已經線上上啟用了正則編譯結果的快取。很顯然,我們業務系統中用到的正規表示式的數量,已然超出了我們最初設定的快取大小,於是很自然地想到把線上的正則快取調的更大一些。然後,我們線上上的火焰圖中便再看不到正則編譯操作了。

通過這些例子我們其實可以看到,不同的資料中心,不同的機器,乃至同一臺機器的不同時段,都會產生自己特有的一些新問題。我們需要的是直接對問題本身進行分析,進行取樣,而不是胡亂去猜測去試錯。有了強大的工具,排錯其實是一個事半功倍的事情。

火焰圖

前面我們已經多次提到了火焰圖(Flame Graph)這種東西,那麼火焰圖是什麼呢?它其實是一個非常了不起的視覺化方法,是由前面已經反覆提到的 Brendan Gregg 同學發明的。

火焰圖就像是給一個軟體系統拍的 X 光照片,可以很自然地把時間和空間兩個維度上的資訊融合在一張圖上,以非常直觀的形式展現出來,從而反映系統在效能方面的很多定量的統計規律。


Nginx 的 C 級別 on-CPU 火焰圖示例

比方說,最經典的火焰圖是統計某一個軟體的所有程式碼路徑在 CPU 上面的時間分佈。通過這張分佈圖我們就可以直觀地看出哪些程式碼路徑花費的 CPU 時間較多,而哪些則是無關緊要的。進一步地,我們可以在不同的軟體層面上生成火焰圖,比如說可以在系統軟體的 C/C++ 語言層面上畫出一張圖,然後再在更高的——比如說——動態指令碼語言的層面,例如 Lua 和 Perl 程式碼的層面,畫出火焰圖。不同層面的火焰圖常常會提供不同的視角,從而反映出不同層面上的程式碼熱點。

因為我自己維護著 OpenResty 這樣的開源軟體的社群,我們有自己的郵件列表,我經常會鼓勵報告問題的使用者主動提供自己繪製的火焰圖,這樣我們就可以愜意地看圖說話(13),幫助使用者快速地進行效能問題的定位,而不至於反覆地試錯,和使用者一起去胡亂猜測,從而節約彼此大量的時間,皆大歡喜。

這裡值得注意的是,即使是遇到我們並不瞭解的陌生程式,通過看火焰圖,也可以大致推出效能問題的所在,即使從未閱讀過它的一行原始碼。這是一件非常了不起的事情。因為大部分程式其實是編寫良好的,也就是說它往往在軟體構造的時候就使用了抽象層次,比如通過函式。這些函式的名稱通常會包含語義上的資訊,並在火焰圖上面直接顯示出來。通過這些函式名,我們可以大致推測出對應的函式,乃至對應的某一條程式碼路徑,大致是做什麼事情的,從而推斷出這個程式所存在的效能問題。所以,又回到那句老話,程式程式碼中的命名非常重要,不僅有助於閱讀原始碼,也有助於除錯問題。而反過來,火焰圖也為我們提供了一條學習陌生的軟體系統的捷徑。畢竟重要的程式碼路徑,幾乎總是花費時間較多的那些,所以值得我們重點研究;否則的話,這個軟體的構造方式必然存在很大的問題。

火焰圖其實可以擴充到其他維度,比如剛才我們講的火焰圖是看程式執行在 CPU 上的時間在所有程式碼路徑上的分佈,這是 on-CPU 時間這個維度。類似地,某一個程式不執行在任何 CPU 上的時間其實也是非常有趣的,我們稱之為 off-CPU 時間。off-CPU 時間一般是這個程式因為某種原因處於休眠狀態,比如說在等待某一個系統級別的鎖,或者被一個非常繁忙的程式排程器(scheduler)強行剝奪 CPU 時間片。這些情況都會導致這個程式無法執行在 CPU 上,但是仍然花費很多的掛鐘時間。通過這個維度的火焰圖我們可以得到另一幅很不一樣的圖景。通過這個維度上的資訊,我們可以分析系統鎖方面的開銷(比如 sem_wait 這樣的系統呼叫),某些阻塞的 I/O 操作(例如 openread 之類),還可以分析程式或執行緒之間爭用 CPU 的問題。通過 off-CPU 火焰圖,都一目瞭然。

應該說 off-CPU 火焰圖也算是我自己的一個大膽嘗試。記得最初我在加州和內華達州之間的一個叫做 Tahoe 的湖泊邊,閱讀 Brendan 關於 off-CPU 時間的一篇部落格文章(14)。我當然就想到,或許可以把 off-CPU 時間代替 on-CPU 時間應用到火焰圖這種展現方式上去。於是回來後我就在公司的生產系統中做了這樣一個嘗試,使用 SystemTap 繪製出了 Nginx 程式的 off-CPU 火焰圖。我在推特上公佈了這個成功嘗試之後,Brendan 還專門聯絡到我,說他自己之前也嘗試過這種方式,但效果並不理想。我估計這是因為他當時將之應用於多執行緒的程式,比如 MySQL,而多執行緒的程式因為執行緒同步方面的原因,off-CPU 圖上會有很多噪音,容易掩蓋真正有趣的那些部分。而我應用 off-CPU 火焰圖的場景是像 Nginx 這樣的單執行緒程式,所以 off-CPU 火焰圖裡往往會立即指示出那些阻塞 Nginx 事件迴圈的系統呼叫,抑或是 sem_wait 之類的鎖操作,又或者是搶佔式的程式排程器的強行介入,於是可以非常好地幫助分析一大類的效能問題。在這樣的 off-CPU 火焰圖中,唯一的“噪音”其實就是 Nginx 事件迴圈本身的 epoll_wait 這樣的系統呼叫,很容易識別並忽略掉。


off-CPU 時間

類似地,我們可以把火焰圖擴充到其他的系統指標維度,比如記憶體洩漏的位元組數。有一回我就使用“記憶體洩漏火焰圖”快速定位了 Nginx 核心中的一處很微妙的洩漏問題。由於該洩

漏發生在 Nginx 自己的記憶體池中,所以使用 Valgrind(15) 和 AddressSanitizer(16) 這樣的傳統工具是無法捕捉到的。還有一次也是使用“記憶體洩漏火焰圖”輕鬆定位了一位歐洲開發者自己編寫的 Nginx C 模組中的洩漏。那處洩漏非常細微和緩慢,困撓了他很久,而我幫他定位前都不需要閱讀他的原始碼。細想起來我自己都會覺得有些神奇。當然,我們也可以將火焰圖擴充到檔案 I/O 的延時和資料量等其他系統指標。所以這真是一種了不起的視覺化方法,可以用於很多完全不同的問題類別。

待續。

參考連結:

DTrace(1):http://dtrace.org/blogs/about/
DTrace Toolkit(2):http://www.brendangregg.com/dtracetoolkit.html
SystemTap(3)https://sourceware.org/systemtap/
小語言(4):https://sourceware.org/systemtap/langref/
C++ 補丁(5):https://sourceware.org/ml/systemtap/2013-q2/msg00377.html
火焰圖(6):http://www.brendangregg.com/flamegraphs.html
stap++(7):https://github.com/openresty/stapxx
Brendan Gregg(8):http://www.brendangregg.com/
公開部落格(9):http://www.brendangregg.com/blog/
nginx-systemtap-toolkit(10):https://github.com/openresty/nginx-systemtap-toolkit
perl-systemtap-toolkit(11):https://github.com/agentzh/perl-systemtap-toolkit
stappxx(12):https://github.com/openresty/stapxx
看圖說話(13):https://groups.google.com/d/msg/openresty/psPBSG4KcSU/Ur9VjTvKBAAJ
一篇部落格文章(14):http://www.brendangregg.com/offcpuanalysis.html
Valgrind(15):http://valgrind.org/
AddressSanitizer(16):https://github.com/google/sanitizers/wiki/AddressSanitizer

 

轉自:http://mp.weixin.qq.com/s?__biz=MjM5ODQ2MDIyMA==&mid=2650712266&idx=1&sn=54d909d240eb701ae48467dc798ddc7f&scene=2&srcid=0506gUskHi8qJi6joV2483uM&from=timeline&isappinstalled=0#wechat_redirect

相關文章