我們都知道，MySQL 中的錯誤日志，慢查詢日志可以幫你快速定位問題。但有時候，日志記錄的信息過少，或者是你感興趣信息被沒有被記下來，有時候又記錄了過多問題，大量無效信息干擾你排查問題。因此，這篇文章介紹一種新的思路——探針技術，這種技術可以在不影響 MySQL 運行，不破現場環(huán)境的前提下，在系統(tǒng)中的關鍵節(jié)點插入一些探針來收集信息。理論上，探針可以插入 MySQL 或者 Linux 內核任意函數進出口，輕松訪問參數等其他詳細信息，資源損失很少，一旦移除探針后沒有任何損失。就像醫(yī)生給病人拍片子一樣，在不影響病人健康前提下，實時觀察病人體內情況，為分析病因提供依據和支撐。
這篇文章介紹的探針像調試程序時候打斷點一樣，只不過打斷點是有交互的，同時是以字節(jié)碼形式運行在內核虛擬機(BPF)中的。異常（exception）?就是控制流中的突變，用來響應處理器狀態(tài)中的某些變化。理解異常有助于理解探針技術。下圖 所示處理器在執(zhí)行時執(zhí)行時，發(fā)生了一個重要的變化，我們把它稱為事件（event）。事件可能與當前指令直接相關，如缺頁異常，算術溢出，嘗試除以 0 。也有可能無關如定時器產生信號，I/O 完成。在任何情況下處理器通過異常表進行一個間接過程調用到專門的異常處理程序來處理。異常可以分成四類：中斷（interrupt)， 陷阱（trap），故障（fault）和終止（abort）。中斷是異步發(fā)生的，是來自處理器外部 I/O （鼠標，鍵盤，網卡等）設備信號的結果。硬件中斷不是由任何一條專門的指令造成，從這個意義講它是異步的。剩下的異常類型（陷阱，故障，終止）是同步發(fā)生的，是執(zhí)行當前指令的結果。我們把這種指令稱為故障指令。陷阱是有意的異常，是程序員“主動”觸發(fā)的，就像是自己在代碼埋下一個陷阱一樣。陷阱最常見的用戶是進程發(fā)起系統(tǒng)調用，通過 INT 從用戶態(tài) trap 進內核態(tài)。故障由錯誤情況引起，能夠被故障處理程序修正。當故障發(fā)生時，處理器講控制轉移給故障處理程序。例如當缺頁異常發(fā)生時，故障處理程序可以從磁盤中間對應的頁 swap 進物理內存。終止，是不可恢復的致命錯誤造成的結果，通常是一些硬件錯誤。程序員平常調試代碼時，給程序添加斷點，讓程序在我們想要的地方停住。調試器能夠隨心所欲控制程序運行，主要靠軟件中斷。軟件斷點在 X86 系統(tǒng)中就是指令 INT 3。當程序執(zhí)行到 INT 3 指令時，會引發(fā)軟件中斷。這就是上文提到的陷阱。不同于我們在 Visual Studio 和 GDB 中交互式的斷點，如果程序在 trap 發(fā)生時，自動執(zhí)行預定義和 handle 記錄和統(tǒng)計運行情況，不影響程序的正常運行，達到觀察 MySQL 的目的。為了捕捉程序運行情況，我們在程序中設置一些 “ 陷阱 ”，并設置處理程序，我們稱之為探針。有的探針是在代碼中預定義的，有的是在運行時動態(tài)添加的。靜態(tài)探針是事先在程序中定義好，并編譯到程序或者內核的探針。靜態(tài)探針只有被開啟時才會運行，不開啟就不會運行，常見的靜態(tài)探針包括內核中的跟蹤點（tracepoints）和 USDT（Userland Statically Defined Tracing）探針。tracepoints 在代碼中埋下鉤子，在運行時調用相連接的探針。它有“打開”（已連接探針）和“關閉”（未連接探針）兩種狀態(tài)。當跟蹤點處于“關閉”狀態(tài)時，它沒有任何作用，只增加微小的時間損失（檢查分支的條件）和空間損失。當跟蹤點為“ 打開”時，每次在調用者的執(zhí)行上下文中執(zhí)行跟蹤點時，都會調用相連接的探針。探針函數執(zhí)行完后，將返回到調用方。USDT和tracepoint類似，只不過是用戶態(tài)的，在代碼中插入DTRACE_PROBE()即可。動態(tài)探針是應用程序沒有定義，在程序運行時動態(tài)添加的探針。動態(tài)探針類似于異常處理機制，當系統(tǒng)產生一個異常，就會跳轉去執(zhí)行對應的 handle。動態(tài)探針會在函數入口和出口插入一些斷點，程序執(zhí)行到斷點時候會去執(zhí)行對應的 handle，從而達到觀測應用程序的目的。這里的中斷是指 trap（陷阱)，在X86體系是int3指令。
KProbes 是 Linux 內核探針，可以用于監(jiān)視生產系統(tǒng)中的事件。您可以使用它來解決性能瓶頸，記錄特定事件，跟蹤問題等。KProbes 能實時在內核代碼中插入中斷指令，雖然這聽上去有點不可思議，實際上 KProbes 做了很多安全性保證，例如 stop_machine 用于確保其他CPU在被修改時停止執(zhí)行。實際上 kprobes 最大風險是給一些調用十分頻繁的函數加上探針，如在網絡模塊中，頻繁中斷可能造成一定的性能風險。KProbe需要定義 pre-handler 和 post-handler，當被探測的指令要被執(zhí)行時，先執(zhí)行pre-handler程序。同樣，當被探測指令執(zhí)行之后立即執(zhí)行post-handler。uprobes 是Linux提供用戶態(tài)的動態(tài)探針，合并于2012年7月發(fā)布的 Linux 3.5 內核中。uprobes 和 kprobes 十分相似，用于用戶態(tài)。BPF(Berkeley Packet Filter)?最早開發(fā)在 BSD 操作系統(tǒng)中，是 TCP/IP 包過濾的工業(yè)標注，被 tcpdump 使用。它的工作方法有點特別：用戶自定義包過濾表達式，然后注入內核中的 BPF 中運行，這樣的好處就是在內核進行過濾而不是將包拷貝到用戶態(tài)，避免大量數據從內核態(tài)拷貝到用戶態(tài)，因此具有較好的性能。后來出現了eBPF(extend BPF), eBPF 有自己的語言，用戶自己編寫程序編譯后通過 BPF 調用注入到內核的 BPF 虛擬機中運行，可以安全訪問內核內存，它使得內核變成可編程。運行在內核中因為不需要把數據拷貝到用戶空間往往具有比較高的性能，因此 BPF 被很多性能追蹤工具使用。
上文介紹了相關的技術背景，接下來介紹使用追蹤工具觀測 bpftrace, 它是一種使用 BPF 進行性能分析的前端工具，使用起來很方便，類似與 awk 語言。由于 MySQL 是運行在用戶態(tài)態(tài)的，要追蹤 MySQL 本身只能使用** USDT** 和** uprobes**。
MySQL 在系統(tǒng)中一些關鍵位置定義了 USDT, 參考文檔 mysqld DTrace Probe Reference(DTrace 是 Solaris 中的動態(tài)追蹤工具，bpftrace 是 Linux 版本的 DTrace) 下面展示一下記錄追蹤到的慢查詢的腳本。#!/usr/bin/bpftrace
BEGIN{ printf("Tracing mysqld queries slower than %d ms. Ctrl-C to end.\n", $1); printf("%-10s %-6s %6s %s\n", "TIME(ms)", "PID", "MS", "QUERY");}
usdt:/usr/sbin/mysqld:mysql:query__start{ @query[tid] = str(arg0); @start[tid] = nsecs;}
usdt:/usr/sbin/mysqld:mysql:query__done/@start[tid]/{ $dur = (nsecs - @start[tid]) / 1000000; if ($dur > $1) { printf("%-10u %-6d %6d %s\n", elapsed / 1000000, pid, $dur, @query[tid]); } delete(@query[tid]); delete(@start[tid]);}
解讀一下 ** BEGIN** 是這個腳本剛開始運行時候的執(zhí)行的，打印一些提示信息。usdt:/usr/sbin/mysqld:mysql:query__start 是給** query__start ** 這個函數加的探針，當程序執(zhí)行到這里時，記錄一下第一個參數 arg0(query), 和當前時間時間戳，并把這些信息保存在 BPF 的 map 中。query__done 探針被執(zhí)行時，記錄當前時間，減去開始時間（從 BPF 的 map 中獲取），就是這個查詢的花費時間，如果超過閾值就打印出來。如果你會說 MySQL 有慢查詢日志啊，不過這里優(yōu)勢是不需要重啟 MySQL，可以實時修改閾值。而且 usdt 在高級版本MySQL 會被移除，同時需要編譯時設置參數 -DENABLE_DTRACE=1 才能支持 usdt。不同與 usdt 需要事先在代碼中設置觀測點，uprobes 可以在程序中動態(tài)添加，可以插入到任意函數的進口和出口位置。下面展示是使用 uprobes 探針對 dispatch_command 進行追蹤，打印出慢查詢語句。#!/usr/bin/bpftrace
BEGIN{ printf("Tracing mysqld queries slower than %d ms. Ctrl-C to end.\n", $1); printf("%-10s %-6s %6s %s\n", "TIME(ms)", "PID", "MS", "QUERY");}
uprobe:/usr/sbin/mysqld:*dispatch_command*{ $COM_QUERY = 3; if (arg2 == $COM_QUERY) { @query[tid] = str(*arg1); @start[tid] = nsecs; }}
uretprobe:/usr/sbin/mysqld:*dispatch_command*/@start[tid]/{ $dur = (nsecs - @start[tid]) / 1000000; if ($dur > $1) { printf("%-10u %-6d %6d %s\n", elapsed / 1000000, pid, $dur, @query[tid]); } delete(@query[tid]); delete(@start[tid]);}
運行一下 這里使用參數 10，表示慢查詢閾值是 10 ms.sudo ./mysql_uprobe_slow.bt 10Attaching 3 probes...Tracing mysqld queries slower than 10 ms. Ctrl-C to end.TIME(ms) PID MS QUERY35976 1083 742 select employees.first_name, employees.last_name, titles.title 93145 1083 224 select * from employees125348 1083 1727 select * from salaries
bpftrace 還提供了直方圖工具，可以將所有查詢耗時記錄下來，最后打印出耗時分布直方圖。#!/usr/bin/bpftrace
BEGIN{ printf("Tracing MySQL query... Hit Ctrl-C to end.\n");}
uprobe:/usr/sbin/mysqld:*dispatch_command*{ @start[tid] = nsecs;}
uretprobe:/usr/sbin/mysqld:*dispatch_command*/@start[tid]/{ @usecs = hist((nsecs - @start[tid]) / 1000000); delete(@start[tid]);}
END{ clear(@start);}
sudo ./histo.bt Attaching 4 probes...Tracing MySQL query... Hit Ctrl-C to end.^C
@usecs: [0] 10 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|[1] 0 | |[2, 4) 0 | |[4, 8) 0 | |[8, 16) 0 | |[16, 32) 0 | |[32, 64) 0 | |[64, 128) 0 | |[128, 256) 1 |@@@@@ |[256, 512) 1 |@@@@@ |[512, 1K) 0 | |[1K, 2K) 1 |@@@@@ |
除了本文展示的 USDT 和 UProbes 兩種探針，展示例子比較簡單，還可以同時插入多個探針，使用 BPF 的 map 來共享信息，達到更強的觀測能力。除了這兩種探針，還可以使用 tracepoints 和 KProbe 來分析內核態(tài)，例如網絡運行情況，磁盤 I/O 情況，當然這需要你對程序有一定熟悉，要不然不知道這些探針加到哪個地方好。
PS：如果覺得我的分享不錯，歡迎大家隨手點贊、在看。
?關注公眾號：Java后端編程，回復下面關鍵字?
要Java學習完整路線，回復??路線?
缺Java入門視頻，回復：?視頻?
要Java面試經驗，回復??面試?
缺Java項目，回復：?項目?
進Java粉絲群：?加群?
PS：如果覺得我的分享不錯，歡迎大家隨手點贊、在看。
最近面試BAT，整理一份面試資料《Java面試BAT通關手冊》，覆蓋了Java核心技術、JVM、Java并發(fā)、SSM、微服務、數據庫、數據結構等等。獲取方式：關注公眾號并回復?java?領取，更多內容陸續(xù)奉上。
