如何使用動態(tài)跟蹤技術SystemTap監(jiān)控MySQL、Oracle性能

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

為寧國等地區(qū)用戶提供了全套網(wǎng)頁設計制作服務，及寧國網(wǎng)站建設行業(yè)解決方案。主營業(yè)務為成都網(wǎng)站設計、成都網(wǎng)站制作、寧國網(wǎng)站設計，以傳統(tǒng)方式定制建設網(wǎng)站，并提供域名空間備案等一條龍服務，秉承以專業(yè)、用心的態(tài)度為用戶提供真誠的服務。我們深信只要達到每一位用戶的要求，就會得到認可，從而選擇與我們長期合作。這樣，我們也可以走得更遠！

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

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

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

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

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

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

動態(tài)跟蹤有一個很重要的概念叫探針，探針相當于數(shù)據(jù)庫里的觸發(fā)器，它是操作系統(tǒng)里的觸發(fā)器。我們可以利用SystemTap將腳本動態(tài)插入到內(nèi)存里，等到一定條件即探針，被觸發(fā)執(zhí)行。

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

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

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

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

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

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

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

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

下面我們看一下Oracle統(tǒng)計時間的結果，運行l(wèi)gr_o.stp腳本，跟蹤2630進程，該進程對應的SQL是select * from t1 where rowed=‘AAADs6AAEAAAACRAAB。當begin出現(xiàn)就證明腳本開始運行了，邏輯讀執(zhí)行完之后，我們看到時間是31微秒。

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

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

如何才能得知對應某個操作的函數(shù)名呢?例如，如何得知 buf_page_get_gen函數(shù)和buf_page_release_latch函數(shù)。這就需要我們?nèi)ピ嬷新l(fā)掘，花些時間研究源碼，或者寫個小腳本來統(tǒng)計耗時、性能等等，這也契合了我們前面講到的正向反饋。

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

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

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

如何開始呢?

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

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

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

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

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

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

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

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

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

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

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

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

之后執(zhí)行commit，再次被Hang住了，這時是斷點被觸發(fā)了。

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

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

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

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

3810B20內(nèi)存地址有一個61080000的數(shù)據(jù)，GDB做了一個自動轉(zhuǎn)換使其轉(zhuǎn)變?yōu)?0000861，在后面的一個字節(jié)是0x08616161，這不就是Insert語句的第二列，那么它的準確地址是什么呢?0x3810B20往后挪兩個字節(jié)0x3810B22。

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

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

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

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

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

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

仔細看，我們發(fā)現(xiàn)rdi顯然已經(jīng)不是之前的rdi了，之前是3810B2，現(xiàn)在是 3810B4，為什么會這樣呢?這是因為watch觀察點是在被觀察內(nèi)存位置被修改之后才觸發(fā)，它不是停在了memcpy函數(shù)的入口點。

rdi、rsi是memcpy函數(shù)入口點的第一個參數(shù)和第二個參數(shù)，但等到從入口點開始，已經(jīng)執(zhí)行了好多條代碼，內(nèi)存已被修改。這時，rdi和rsi已被修改，嚴格來說已經(jīng)不是memcpy的第一個和第二個參數(shù)了。

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

以上是“如何使用動態(tài)跟蹤技術SystemTap監(jiān)控MySQL、Oracle性能”這篇文章的所有內(nèi)容，感謝各位的閱讀！希望分享的內(nèi)容對大家有幫助，更多相關知識，歡迎關注創(chuàng)新互聯(lián)行業(yè)資訊頻道！

本文題目：如何使用動態(tài)跟蹤技術SystemTap監(jiān)控MySQL、Oracle性能
網(wǎng)頁網(wǎng)址：http://bm7419.com/article0/gijgio.html

成都網(wǎng)站建設公司_創(chuàng)新互聯(lián)，為您提供響應式網(wǎng)站、網(wǎng)頁設計公司、做網(wǎng)站、品牌網(wǎng)站制作、外貿(mào)建站、靜態(tài)網(wǎng)站

廣告

聲明：本網(wǎng)站發(fā)布的內(nèi)容（圖片、視頻和文字）以用戶投稿、用戶轉(zhuǎn)載內(nèi)容為主，如果涉及侵權請盡快告知，我們將會在第一時間刪除。文章觀點不代表本網(wǎng)站立場，如需處理請聯(lián)系客服。電話：028-86922220；郵箱：631063699@qq.com。內(nèi)容未經(jīng)允許不得轉(zhuǎn)載，或轉(zhuǎn)載時需注明來源： 創(chuàng)新互聯(lián)