Python3.6 Dtrace實戰

02-02

題圖來自動態追蹤技術漫談

整理了內部的一次分享

前言

Python3.6.0於上周 (2016-12-23號，話說周五還發版不怕周末加班么)愉快的進入了Stable階段，標誌著新特性已經加完了開始進入修BUG階段，

按照版本號來說，也是Python3系列的下半場了，因為大於5了嘛。。

本次大版本的釋出，應該說令人愉悅的特性還是挺多的，例如asyncio這個庫的性能大幅提高，API也進入穩定期，同時3.5的asyncio也合併進入穩定期了。

（所以以前都是日狗期？_(:з」∠)_那一堆asyncio之上的框架、庫作者會怎麼想

但個人覺得比較有利於生產環境的特性，是dtrace支持和tracemalloc的改進

當然，我們Python界的兼容性一向是個大毛病，Guido大大已經不止一次讓大家火速用Python3了，遙想Python3,剛發出的時候，那還是2010年啊，6年了

生產環境上Python3.6,這件事情我持悲觀，希望3年內有個微服務可以搞起來（然後是遍地的坑吧

現在能做的是：寫單元測試，以後有機會爭取一把過。。

內存和計算

編程這件事情，最重要的也許就是計算和存儲了。。存儲一部分是內存，一部分是外存，網路簡單點也就是個IO。。

貼一個圖：

來自：http://www.brendangregg.com/blog/2016-10-27/dtrace-for-linux-2016.html

dtrace

dtrace是個探測器，可以實時在生產環境中進行探測，而不影響業務

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

————《漫談動態追蹤技術》[6]

編譯時使用--with-dtrace開啟支持（BTW，發現了好多編譯時標誌位），它為解釋器中的以下事件啟用了靜態標誌器：

函數調用／返回

垃圾回收開始/結束

執行代碼行。

簡單的說，就是這幾種事件可以被dtrace獲得，由此而知，事實上就可以進行行粒度的性能測量

艾瑪鋪墊好累，直接脫衣服上：看看Python上怎麼用起來,以及發揮了什麼作用

文檔在：Instrumenting CPython with DTrace and SystemTap

註：apt-get裝的dtrace不是真的dtrace，上面的各種參數都沒有，上面這篇文章應該是在Mac上寫的。。

CentOS/Ubuntu等Linux系統建議使用systemtap，也是一種動態追蹤技術，語法基本可以兼容

# zhutou @ Phoenix in ~/Downloads/Python-3.6.0 [22:53:03]n$ readelf -n ./python n nDisplaying notes found at file offset 0x00000254 with length 0x00000020:n Owner Data size Descriptionn GNU 0x00000010 NT_GNU_ABI_TAG (ABI version tag)n OS: Linux, ABI: 2.6.32n nDisplaying notes found at file offset 0x00000274 with length 0x00000024:n Owner Data size Descriptionn GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring)n Build ID: 1cd6bc27090778c9758e801820933061ca2af08cn nDisplaying notes found at file offset 0x002f8010 with length 0x0000019c:n Owner Data size Descriptionn stapsdt 0x00000030 NT_STAPSDT (SystemTap probe descriptors)n Provider: pythonn Name: gc__donen Location: 0x000000000042654b, Base: 0x0000000000644d30, Semaphore: 0x00000000008f7fd8n Arguments: -8@%r14n stapsdt 0x00000035 NT_STAPSDT (SystemTap probe descriptors)n Provider: pythonn Name: gc__startn Location: 0x00000000004265a7, Base: 0x0000000000644d30, Semaphore: 0x00000000008f7fd6n Arguments: -4@40(%rsp)n stapsdt 0x0000003f NT_STAPSDT (SystemTap probe descriptors)n Provider: pythonn Name: linen Location: 0x0000000000472063, Base: 0x0000000000644d30, Semaphore: 0x00000000008f7fd4n Arguments: 8@24(%rsp) 8@%rax -4@%r15dn stapsdt 0x00000045 NT_STAPSDT (SystemTap probe descriptors)n Provider: pythonn Name: function__entryn Location: 0x000000000047345c, Base: 0x0000000000644d30, Semaphore: 0x00000000008f7fc8n Arguments: 8@%r14 8@%r12 -4@%eaxn stapsdt 0x00000046 NT_STAPSDT (SystemTap probe descriptors)n Provider: pythonn Name: function__returnn Location: 0x0000000000473c21, Base: 0x0000000000644d30, Semaphore: 0x00000000008f7fcan Arguments: 8@%r14 8@%rbx -4@%eaxn

這裡顯示了ELF頭的信息。一個有用的命令，之前我在《深度探索Linux操作系統》讀到過。。

這裡顯示了5種信號：gc開始/結束、每行代碼被執行、函數進入、函數返回

簡單的介紹一下Dtrace，這是一種動態追蹤工具，寫的腳本叫做D語言，常被用於性能分析和異常追蹤，在C生態圈裡比較常見

主要基於事件

Dtrace的幾種概念：

事件提供者Provider。是一個實體，用於訪問類和函數。一個典型的Provider是系統調用syscall。在Python3這裡，Provider就是編譯好的Python3.6二進位
模塊module. 取決於提供者，諸如libc.so這種動態鏈接庫就是模塊
函數function. 通常意義的函數。例如read這個系統調用
名稱name. 可以類比於參數，例如entry代表進入一個函數，return代表一個函數的退出

接下來開始實戰：

dtrace腳本核心語法

就一行：

probe event {statements}n

probe這個關鍵詞定義一個探針

會在事件event（這裡可能是syscall啦、vfs.write啦）發生時，執行statements對應的腳本程序

列出所有探針

stap --dump-probe-typesn

顯示systemtap的文檔可以使用的探針，上面那篇Python的文檔用起來會出錯，會顯示while resolving probe point: identifier process ,查了一下是沒法找到對應的進程標識（難道procname還不夠。。。

上面這個probe-types找到了可以用的探針：process(number).function(number) 按尿性這個process里的參數數字應該就是PID唄，試了下果然（此處一個窗口打開Python，一個窗口使用stap調試）

效果如圖，因為是在repl環境弄得，但這樣看起來和Python文檔里的不一樣，搜了一下，發現了解決方案（在參考文檔7里

查看二進位程序探針[7]

stap -L process("/home/zhutou/Downloads/Python-3.6.0/python").mark("*")

陷入了沉思。。。那麼好像這樣可以的話，我們可以對Python那個文檔稍作改動,用這個腳本試試：

probe process("/home/zhutou/Downloads/Python-3.6.0/python").mark("function__entry") {n filename = user_string($arg1);n funcname = user_string($arg2);n lineno = $arg3;n n printf("%s => %s in %s:%dn",n thread_indent(1), funcname, filename, lineno);n}n nprobe process("/home/zhutou/Downloads/Python-3.6.0/python").mark("function__return") {n filename = user_string($arg1);n funcname = user_string($arg2);n lineno = $arg3;n n printf("%s <= %s in %s:%dn",n thread_indent(-1), funcname, filename, lineno);n}nprobe process("/home/zhutou/Downloads/Python-3.6.0/python").end {n exit()n}n

最後一個探針是我即興發揮的，意思是：探測到這個進程結束，那麼探針進程也結束（問題是為啥最後出來的是core dump異常。。。_(:з」∠)_。。還是偶發。。

保存以上內容為.stp結尾，其他後綴的沒研究過，但發現.d後綴不管用(好像是dtrace的後綴)

打開探針stap ，然後執行一個Python腳本

握草一樣的完美。。。

那麼DTrace接下來的一個工具特性，就是根據這個特性開始畫火焰圖了

火焰圖

同樣的寫探針，記錄，火焰圖本身有很多種畫法，記內存可以變成內存火焰圖，尋找內存泄漏，記CPU時間，可以查找最耗時的部分，章大的文章里介紹了很多神奇的場景

有的Profile（現行的profile、cPrifile）或者探針腳本，在繪製CPU時間火焰圖上非常簡單粗暴：隔一段微小的時間開始dump整個棧，最後根據棧裡面各個部分的次數來繪製火焰圖

形如：

global s;nglobal quit = 0;nprobe timer.profile {n if (pid() == target()) {n if (quit) {n foreach (i in s-) {n print_ustack(i);n printf("t%dn", @count(s[i]));n }n exit()n } else {n s[ubacktrace()] <<< 1;n }n }n}n nprobe timer.s(20) {n quit = 1n}n

這上面的兩個事件探針：

timer.profile 定時執行

timer.s 指的是20秒後執行n

簡單地說就是死循環記錄棧，然後20秒後退出。

基本思想是：那些佔用時間越長的函數，就越會在定時採樣時被捕獲。

但這樣顯然是不那麼有效率的

簡單改了一下，在函數進入和退出的時候記錄一下：

global functimelist;nglobal func_indent;n n nprobe process("/home/zhutou/Downloads/Python-3.6.0/python").mark("function__entry") {n filename = user_string($arg1);n funcname = user_string($arg2);n key = funcname." in ".filenamen functimelist[key] = gettimeofday_us()n thread_indent_depth(1)n}n nprobe process("/home/zhutou/Downloads/Python-3.6.0/python").mark("function__return") {n filename = user_string($arg1);n funcname = user_string($arg2);n key = funcname." in ".filenamen printf("%d,%s,%dn", thread_indent_depth(-1),key, gettimeofday_us()-functimelist[key])n n}n nprobe process("/home/zhutou/Downloads/Python-3.6.0/python").end {n exit()n}n

上面的幾個語法點：

各種類型自動推導
8行 key = funcname." in ".filename 這裡的點是字元串拼接的意思
array可以當成map用，直接往裡面丟key:value

上面的探測腳本把函數的棧關係、調用時間都弄出來了，往stdout里打了csv格式的數據

需要格式化成：

unix`_sys_sysenter_post_swapgs 1401

unix`_sys_sysenter_post_swapgs;genunix`close 5

unix`_sys_sysenter_post_swapgs;genunix`close;genunix`closeandsetf 85

unix`_sys_sysenter_post_swapgs;genunix`close;genunix`closeandsetf;c2audit`audit_closef 26

unix`_sys_sysenter_post_swapgs;genunix`close;genunix`closeandsetf;c2audit`audit_setf 5

unix`_sys_sysenter_post_swapgs;genunix`close;genunix`closeandsetf;genunix`audit_getstate 6

unix`_sys_sysenter_post_swapgs;genunix`close;genunix`closeandsetf;genunix`audit_unfalloc 2

unix`_sys_sysenter_post_swapgs;genunix`close;genunix`closeandsetf;genunix`closef 48

[...]

的形式，文檔11中 ./flamegraph.pl 腳本才可以處理

這樣用一個小Python腳本處理

# coding=utf-8nfrom __future__ import unicode_literalsnimport csvn nwith open("call.csv") as fin:n reader = csv.reader(fin)n current_depth = 0n module_stack = []n for depth, func_in_module, utime in reader:n if depth > current_depth:n module_stack.append(func_in_module)n print ";".join(module_stack), utimen elif depth < current_depth:n if module_stack:n module_stack.pop()n print ";".join(module_stack + [func_in_module]), utimen else:n print ";".join(module_stack + [func_in_module]), utimen current_depth = depthn

把上面腳本的輸出重定向，再處理，就得到火焰圖了：

(知乎傳svg圖片的時候500了，所以這裡SVG圖片上不來，截了個圖）

這個腳本是以定時採樣為基礎的，但因為我們的腳本記的是微秒時間，所以最後這個292,824個取樣，實質上指的是整個解釋器啟動的時間是292ms。另外SVG本身在瀏覽器里可以進行交互，每個矩形都可以點

那麼就到這，Have Fun

參考文檔

Hooked on DTrace, part 1
Instrumenting CPython with DTrace and SystemTap
Introduction - Dynamic Tracing Guide
動態追蹤技術：Linux喜迎DTrace - 系統運維 - IT問道
How do I install DTrace?
動態追蹤技術漫談 -
RE: python tracing
openresty/openresty-systemtap-toolkit nginx探針腳本
Kernel/Systemtap - Ubuntu Wiki ubuntu 運行systemtap的一些必備步驟
SystemTap Language Reference
brendangregg/FlameGraph