如何使用動態跟蹤技術SystemTap監控MySQL、Oracle性能

這篇文章主要介紹如何使用動態跟蹤技術SystemTap監控MySQL、Oracle性能，文中介紹的非常詳細，具有一定的參考價值，感興趣的小伙伴們一定要看完！

這次的中國數據庫技術大會有很多關鍵詞，例如源碼、開源、自研等等，尤其是正值中興事件，國內基礎技術研究迎來了一個小高潮。

眾所周知，基礎技術的研究不簡單，所以，經常有朋友和我說，他想研究一下MySQL源碼，但代碼量太大了，放棄了，又或者是他已經編譯好了，就差看了，但遺憾的是再也沒有然后了。為什么總會出現這種情況呢?我認為是沒有建立一個正向的反饋機制。

為什么這樣說呢?當你花了很多精力去研究源碼，但是很長時間過去了，你發現自己并沒有什么收獲，這時就會很容易就放棄了。但如果每過一兩周，我都會有些小收獲，這樣不斷積累，集小勝為大勝，最終在技術上有所突破。這就是建立了一種正向的反饋機制。

如何建立這種反饋機制呢? 這就要提到我們下面要講的SystemTap，動態調試或動態跟蹤。

什么是動態跟蹤?就是在不影響程序的情況下去動態觀察正在運行中的程序。動態跟蹤技術影響力比較大的是Dtrace，雖然我不確定Dtrace是不是動態跟蹤的鼻祖，但可以確定的是SystemTap等眾多動態跟蹤技術都是之后才出現的。

SystemTap是Redhat推出的，如果服務器是Redhat，那么是不需要安裝的，但如果是其它系統則需要安裝，不過安裝也是很簡單的。SystemTap也需要有一定的使用基礎，比如基礎開發的變量、條件、循環、分支以及寫個小程序等等的能力。另外，要熟悉動態跟蹤的目標，例如跟蹤MySQL，那么MySQL的基礎知識、用法是需要掌握的。

動態跟蹤有一個很重要的概念叫探針，探針相當于數據庫里的觸發器，它是操作系統里的觸發器。我們可以利用SystemTap將腳本動態插入到內存里，等到一定條件即探針，被觸發執行。

動態跟蹤技術通常是利用插到內存中的腳本，這類腳本通常不會太復雜，用來顯示內存值、內存狀態、統計時間等等，因為太復雜會拖慢目標進程或者引起其它的不穩定。

這是一個比較簡單的統計MySQL邏輯讀時間消耗的例子。假設已知MySQL邏輯讀操作是從buf_page_get_gen開始到buf_page_release_latch函數為止。我們寫了一個統計邏輯讀耗時的SystemTap腳本，很簡單，一共15行，如果除去空行和括號，那么腳本真正有效的行數就更少了。

其中，第一行定義了一個腳本的解釋器;第三行定義了一個全局變量，因為探針和函數類似，每個函數里的變量不能夠互相傳遞數據，所以如果想跨探針傳遞數據，必須定義全局變量;第5到7行是SystemTap begin 開始探針，當腳本運行時，這個探針就會被觸發。我在這里放了一個輸出“begin”的提示;第九行是一個針對MySQL進程的探針，buf_page_get_gen函數入口點的探針，相當于buf_page_get_gen函數的觸發器，系統執行這個函數時，探針會被先觸發;第十行是記錄時間，利用SystemTap的gettimeofday記錄以微秒計時的時間;第十三行是buf_page_release_latch函數，當這個函數被觸發調用時，用當前時間減去剛才邏輯讀開始的時間就是一次完整的邏輯讀耗時。

上圖兩個屏幕窗口，一個是MySQL客戶端，一個是shell窗口。先在shell窗口去運行lgr1.stp腳本，其中3164是進程號，-x是cmd命令，運行之后會顯示begin。在MySQL客戶端里執行一條select語句，并執行一次邏輯讀。

執行完畢后，我們看到結果是63微秒。當然，這個時間不是固定的，不同的測試機器時間都會不一樣。MySQL完成一次邏輯讀大概是60微秒，兩者相差不是很大，但如果有多個數據庫對比，我們就能了解更多的數據庫性能細節。

下面我們來對比一下Oracle時間消耗。Oracle邏輯讀有好多種方式，我們用一種比較普通的方式，以rowid的方式邏輯讀。這種邏輯讀與MySQL有很大的不同，它先獲得CBC Latch，在CBC Latch的保護下獲得Buffer Pin Lock，然后再讀塊中的行數據。從獲得CBC Latch開始到釋放Buffer Pin Lock為止，這是一次完整的邏輯讀。

其中，kcbgtcr函數對應MySQL里的buf_page_get_gen函數，也就是獲得函數。kcbrls對應MySQL的buf_page_release_latch函數。

有了這兩個函數，那么統計Oracle時間消耗的腳本就很好寫了。腳本內容和上面的差不多，只是函數名替換一下。

下面我們看一下Oracle統計時間的結果，運行lgr_o.stp腳本，跟蹤2630進程，該進程對應的SQL是select * from t1 where rowed=‘AAADs6AAEAAAACRAAB。當begin出現就證明腳本開始運行了，邏輯讀執行完之后，我們看到時間是31微秒。

這個結果顯然要比MySQL快很多。為什么呢?因為MySQL邏輯讀包含了索引對比，要先判斷該行是不是用戶要讀取的行，而Oracle不會進行這樣的對比，所以工作量更少，時間消耗自然也會更少。

Oracle其實也有和MySQL類似的邏輯讀，但因為這里的測試環境是InnoDB表無法完成。但你也可以在Oracle中建立索引組織表來完成同樣的邏輯讀。需要注意的是，即使同樣的邏輯讀，Oracle還是會比MySQL快一點。

如何才能得知對應某個操作的函數名呢?例如，如何得知 buf_page_get_gen函數和buf_page_release_latch函數。這就需要我們去原版中慢慢發掘，花些時間研究源碼，或者寫個小腳本來統計耗時、性能等等，這也契合了我們前面講到的正向反饋。

Oracle有1367個等待事件、1000多個性能資料，共計使用了3000多個指標來反映數據庫的狀態跟性能。相比之下，MySQL這樣的開源數據庫在這方面就弱了很多，但同時也給SystemTap這樣的動態跟蹤技術留下了很大的空間。

進入正題，首先介紹一下技術初衷。前段時間，有個客戶需要做加載操作，每天執行一次，大概加載百萬行數據，耗時十分鐘左右。我看了之后發現這個十分鐘的耗時還是很正常的，因為他們沒使用并行，單線程吞吐量始終是有限的。但是客戶覺得慢，想要有更詳細的時間列表，這樣也就有了我今天的分享內容。

今天，我們主要以介紹方法為主，我主要統計了解析、處理binlog、處理UNDO、處理Redo、總執行時間這五個階段的時間消耗。下面我們以binlog為例，講解一下如何使用SystemTap+源碼統計電腦執行期間處理binlog的消耗時間，注意這里是統計DML執行時間。

如何開始呢?

第一步我們要找到處理binlog所對應的函數，然后按照之前的方法寫個簡單腳本統計時間消耗。這里的關鍵問題就是如何尋找binlog對應函數。有一個重要技能，逆流而上，順藤摸瓜。逆流而上指的就是跟著內存流往前去。

以binlog為例，binlog數據最終是要寫進磁盤的。寫磁盤的時候一定是從某一個buffer寫到磁盤里，我們就稱這個buffer為buffer z，那么這個buffer數據是從哪兒來的?假設buffer z的數據是從buffer y拷貝過去的，那我們就稱buffer y是buffer z的上線。那么buffer y的上線是誰?上上線又是誰?……如此順藤摸瓜，我們就可以找到binlog的處理函數了。

具體方法是什么呢?第一步我們要先找到寫binlog到文件的函數，在MySQL里看它調用了什么函數觸發了寫IO。上圖的這個SystemTap腳本與之前不一樣的地方是，剛才腳本中函數名稱是固定的，而這里使用了*write*，也就是說要跟蹤所有名稱中包含write字樣的函數。

另外，還有一個條件語句，其中Ulong_arg(1)是當探針被觸發時函數的第一個參數。這樣的函數通常第一個參數都是文件號，第二個參數是buffer，第三個參數是長度。131是binlog文件的文件號，我們可以從proc中得到。

如果滿足了函數名稱中帶有write，第一個參數是binlog文件號，那么它就極有可能是寫到文件的函數。我需要具體做什么操作?首先，輸出三個參數，然后我們利用SystemTap的內置函數pp，顯示探針對應的信息，包括探針的函數名等等。之后，輸出一個堆棧，堆棧指的是當前函數的上層，然后以此類推再繼續往上找。

看一下執行結果，先運行腳本，其中3164是mysqld的進程號。等到begin輸出之后，再去執行一條insert語句，然后我們看到沒有任何東西輸出。這是因為Insert語句不觸發IO，等到commit才會被觸發。

再執行一條commit，我們就能看到輸出內容了。方框中是pp函數對應的內容是探針的信息，my_write函數就是MySQL里寫binlog到文件所調用的函數，它在my_write.c的第40行。后面的三個參數分別文件號83， 38114B0是前面所說的buffer z，從這個地方binlog數據被寫到磁盤里面了，但這還不是精確的buffer z， 17是長度，換算成十進制就是279字節。

下面看一下my_weite.c的內容，在my_write.c的第40行有my_write函數，第63行是它調用庫函數write完成實際的IO操作，這里的第一個參數仍然是文件號，第二個是buffer，并且這個參數可能與buffer z的準確地址有關。

我們先準備一條有辨識度的SQL，什么叫有辨識度的SQL?就是SQL中有大量的重復數據，容易辨認。比如，第二列有8個小寫a，16進制的ASCII碼就是6161616161616161，你在內存里會看到八個連續的61。

之后我們以第二列列值為準來尋找精確的buffer z地址。具體操作時，我們還要再引入另外一個調試工具叫GDB。

其中，3164是正在運行mysqld的進程號，執行之后會輸出很多信息，當GDB運行之后，目標程序里的任何操作都需要經過GDB的批準。這時如果在MySQL里執行一條SQL語句，那么這個SQL語句會被HANG住。原因很簡單，我們沒有在CBD里發命令讓它繼續跑。

首先，我會在my_write.c的63行設置一個斷點，斷點跟探針差不多，當某個函數或操作執行時觸發斷點。設置完后，我會執行C命令，C命令在GDB里相當于continue，之后執行Insert語句繼續，剛才被Hang住的語句并沒有觸發探針，因為Insert語句不會去觸發binlog的IO。

之后執行commit，再次被Hang住了，這時是斷點被觸發了。

斷點處的信息就是剛才第63行write庫函數的信息，仍然是第一個參數是文件號，第二個參數是緩存，第三個參數是279長度。

在GDB里面使用p命令驗證一下，輸出Filedes與binlog文件號對比。

p命令顯示buffer z的地址是3810A40，與剛才腳本輸出內容是一樣的。但3810A4并不是精確的buffer z的地址，精確的buffer z地址應該是Insert語句里的8個a。

如何尋找呢?首先，使用X命令顯示381040的內存值。

3810B20內存地址有一個61080000的數據，GDB做了一個自動轉換使其轉變為00000861，在后面的一個字節是0x08616161，這不就是Insert語句的第二列，那么它的準確地址是什么呢?0x3810B20往后挪兩個字節0x3810B22。

之后，用watch設置一個觀察點，相當于GDB里的斷點，當進程讀寫到指定內存時被觸發。如前文所述，0x3810b22是我們找到的buffer z，設置了監察點之后，只要誰給buffer z傳遞數據，那么監察點就會被觸發。

之后運行C命令，讓MySQL跑下去，并在MySQL客戶端里再執行一條Insert語句。執行完之后，我們發現探針并沒有被觸發。

然后再去執行commit，又一次被 Hang住了，探針也被觸發了，我們在這里看到了兩個值Old Value和New Value。

因為探針是來監測buffer z被修改的，所以Old Value就是修改前的原值，而New Value是新值。新值其實就是08616161，那么探針對應的函數是誰?memcpy_ssse3_back()，這個函數其實就是拷貝函數。這時我們已經找到了buffer y，但因為它是在commit時被觸發的，所以不是我要找的最終的大boss，還需要繼續往下找。

如何找?還是和剛才一樣，在buffer y的地址設置觀察點。

這里我們要使用一個GDB命令叫info registers，顯示寄存器。為什么要顯示寄存器呢?因為在64位系統中，rdi、rsi、rdx等等都是函數的參數，memcpy函數的第一個參數是目標，第二個參數是源，換句話說就是從第二個參數往第一個參數拷貝，代入到本例中， rdi就是buffer z，rsi就是buffer y。

仔細看，我們發現rdi顯然已經不是之前的rdi了，之前是3810B2，現在是 3810B4，為什么會這樣呢?這是因為watch觀察點是在被觀察內存位置被修改之后才觸發，它不是停在了memcpy函數的入口點。

rdi、rsi是memcpy函數入口點的第一個參數和第二個參數，但等到從入口點開始，已經執行了好多條代碼，內存已被修改。這時，rdi和rsi已被修改，嚴格來說已經不是memcpy的第一個和第二個參數了。

雖然rdi不是buffer z，但在buffer z附近。同理，rsi也在buffer y附近。Buffer z的準確地址是3810B22，當前rdi是3810B45，兩者相差23字節(16進制)，那么rsi減去0x23是否就是buffer y的準確地址。

下面我們來驗證一下。用X命令來顯示內存，其中后四位f0b9就是剛才rsi減去0x23的值，其內存值 0x61616108，也就是剛才Insert語句中的第二列，那么f0b9就是buffer y的準確地址了。

找到buffer y的準確地址之后，刪除原來的觀察點，在f0b9處再設置一個新的觀察點。

之后，繼續執行C命令，在MySQL客戶端執行一條類似的Insert語句，插入8個b，但這次在執行Insert的時候就被Hang住了，那么很有可能我們這次就找到了DML執行期間binlog的處理函數。

如何驗證新的斷點被觸發之后有沒有跟binlog的相關函數?很簡單，我們用一條GDB里的BT命令來顯示調用棧。

上面的輸出結果，#0是當前memcpy函數這一層，#1調用了#0，#2調用了#1的函數，以此類推。其中#8和#9是MySQL Insert函數，調用了THD里的binlog_query函數，我們一看這個函數名就應該知道這就是我們要找的DML執行期間binlog的處理函數了。

整個流程看起來還是蠻簡單的，順藤摸瓜，一路向上找，找到之后，使用BT檢測一下是否是我們的目標。

當然，雖然我們找到了目標，但它可能不是唯一的目標，在DML執行期間除了binlog_query，它可能還調用了其他函數去處理binlog。所以我們還需要依此方法繼續尋找。

總結一下，第一步確認buffer x，這個需要從rsi、rdi參數入手，然后在buffer x處設定觀察點，運行一條近似的SQL，等待觀察點被觸發，使用BT命令來觀察調用棧中是否有binlog字樣的處理函數。

找到什么時候為止呢?從右邊看到，我們已經進行了很多層的尋找，如果用BT調用堆棧，我們在里面看到了parse，解析是SQL執行最開始的步驟，證明我們已經找到源頭了，不需要接著往下找了。

除了binlog_query，binlog_log_row也是DML期間處理binlog的函數。如果你想要更一步的了解代碼，可以在代碼中設置斷點，單步跟蹤，看其是如何完成的。

我們也知道提交時binlog數據是用my_write函數寫到磁盤中，所以在my_write處設個端點，用BT顯示堆棧，就可以知道在binlog寫文件時哪個函數觸發IO。

應該是flush_cache_to_file函數最早觸發IO，并調用my_write完成了IO。為什么flush_cache_to_file是最早觸發的函數呢?因為在BT調用棧中可以看到它是在#3，但是在#4、5、6或者之后基本都沒有帶有IO的函數了。

如果想要更詳細的了解，可以在代碼中設置斷點，跟蹤函數是如何執行的。又或者可以做個腳本，統計一下時間、性能消耗等等。這正是前文所說的正向反饋，這樣做既有實際用途，同時又能讓自己得到成長。

統計binlog時間消耗的腳本很簡單，與邏輯讀時間消耗的腳本基本一樣。先執行腳本，begin出現之后，執行一條Insert的語句，時間輸出是80微秒，與之前邏輯讀的時間相比長了許多。不過，這也是正常現象，因為DML操作是遠比查詢更復雜的一種操作，它要處理redo、undo等等。

利用我們剛才找到binlog處理函數的方法，我們還可以找到解析、回滾等其他函數。在研究代碼的時候，我建議大家循序漸進，如果代碼量很大，可以先嘗試從比較小的操作入手，并輔助以動態跟蹤技術。

下面講一下這個腳本的重點部分。第一個就是定義了很多的全局變量，用來跨多個探針記錄時間;第二統計解析耗時，這里多了一個東西tid()==$1，其中$1是傳遞過來的參數——線程號，tid是SystemTap獲取當前線程號的函數，考慮到跟蹤的mysqld可能是多線程系統，而我們只需跟蹤目標線程，所以要把其它線程都過濾掉;第三time探針，括號中的1代表一秒鐘觸發一次。 每次觸發之后輸出時間指標，這里是模擬vmstat 1，一秒顯示一行。

在開始運行之前，我們需要知道線程號，使用tid過濾了目標線程，然后通過performance_schema.threads得到線程號，當前客戶端對應的線程號是3659。

3047是mysqld的線程號，3659是要跟蹤的線程號，運行腳本之后，每秒輸出一行，執行插入4000多行的Insert語句，就可以能看到時間輸出了。

腳本統計得到的耗時是50萬微秒，這和MySQL自己統計的時間0.5秒是吻合的，不過我的統計比MySQL客戶端詳細多了，其中包含了 redo for undo占了總時間的3.1%，頁redo占了總時間的4.6%，總redo的時間占了7.7%，而undo占了17.7%，binlog占了8.3%。把這些時間相加，就是InnoDB為了事務、更高的可靠性而額外需要付出的時間，總共占到總時間的33.7%。

以上是“如何使用動態跟蹤技術SystemTap監控MySQL、Oracle性能”這篇文章的所有內容，感謝各位的閱讀！希望分享的內容對大家有幫助，更多相關知識，歡迎關注億速云行業資訊頻道！