Author:  Lv, Haibo

摘要：除錯Oracle的意義 ---- 無限風光在險峰

我把用DTrace和mdb，分析、研究Oracle稱為“除錯Oracle”，這是一個新的領域。它比傳統DBA要求更高，除掌握Oracle內部原理外，它也要求更多的計算機底層知識，因為個別時候，我們需要到反彙編程式碼中，一探研究。那麼究竟除錯Oracle技術可以為DBA帶來什麼改變呢？本文想給各位讀者朋友一個基本的回答。

本文從DBA最常用的等待事件出發，以10G後新增的一個等待事件log file switch(private strand flush incomplete)為例，描述瞭如何使用DTrace和mdb，揭開這個等待事件的祕密。

不使用除錯Oracle技術，我們無法用測試獲得這個等待事件真正的意義。這就是除錯Oracle的意義之一。它還有更多的作用，有時間我們細細道來。

一句話總結一下，“除錯Oracle”需要很多基礎知識和極大的耐心，是一條崎嶇的山路，但它可以助你更快速的登上Oracle這做高峰，“無限風光在險峰”。

除錯Oracle  之二   進階篇

---- 解析log file switch(private strand flush incomplete)等待事件的意義

         在上一篇文章中，我大概講述了除錯Oracle的利器之一：DTrace的基本使用。本篇開始用一個簡單的例子，展示“除錯Oracle”的神奇之處。

       上一篇中我們主要使用了I/O提供器中的探針，其實這遠不是DTrace中最強大的功能。DTrace最強大的是PID提供器中的程序探針，它可以讓我們輕鬆進入Oracle內部，看到Oracle內部的函式呼叫關係，再輔以偵錯程式gdb或mdb，威力無窮。

本篇的例子是關於等待事件解析的，等待事件是DBA重要的判斷Oracle問題的依據。有一本書，中文書名《Oracle Wait Interface 效能診斷與調整實踐指南》，專門講述Oracle各種等待事件的意義，是我早年最重要的參考書。後來還有一個韓國人，也寫了一本有關等待事件的書，《高階OWI與ORACLE效能調整》，也有一定參考意義，有興趣的讀者可以找一下。

如果你理解錯了等待事件的意義，哪麼你判斷問題的方向，很可能偏離正確的軌道，這有可能會造成嚴重的後果。如果Oracle是你夢想中的女/男神，她告訴你她正在等待著什麼（就像Oracle用等待事件告訴你，它正在等待什麼），而你，卻理解錯了，……。

我想我已經不需要繼續說下去了，又是一場悲劇，說多了都是淚。

想懂“女人的心”很難，想懂Oracle的心，所幸有了“除錯Oracle”技術，這就方便多了。

下面我們以log file switch(private strand flush incomplete)等待事件為例，詳細分析下如何使用DTrace+Mdb挖掘等待事件的意義，我就不再講什麼授人以魚不如授人以漁這樣的空話，我力求本文是“漁”，如果大家只能看到“魚”，請告訴我，我會寫的再簡單寫。

log file switch(private strand flush incomplete)等待事件是10G後針對IMU特性新增的等待事件，如果你開啟了IMU，有時候就可能會遇到它。

在開始分析之前，你可以在網上搜索一下，看看大家都是如何解釋此等待事件的。我先貼上一段官方文件中關於此等待事件的描述：

User sessions trying to generate redo, wait on this event when LGWR waits for DBWR to complete flushing redo from IMU buffers into the log buffer. When DBWR is complete LGWR can then finish writing the current log, and then switch log files.

這段英文太簡單，不詳細解釋了。由於這段文件中涉及到了DBWR，“wait on this event when LGWR waits for DBWR to complete flushing redo from IMU buffers into the log buffer”。一些人這樣翻譯這句：LGWR等待DBWR完成重新整理Redo從IMU Buffer到Log Buffer。有一段時間，我曾經這樣翻譯：“LGWR等待DBWR，以便完成Redo從IMU Buffer到Log Buffer”。

但是，這面這兩種說法都是錯的。或者說，官方文件在這裡是錯誤的。

先別急著“拍”磚，我知道有很多老DBA一再強調，官方文件是如何如何的重要，甚至還會有人說一切與官方文件為準。

我只想說，“盡信書不如無書”，我們在前程序過程中，千萬不能有“半部論語治天下”這樣的想法。我不否認官方文件的重要性，但我還是要說，有時，它可能有錯誤。

好了，下面用實際的測試，來解析log file switch(private strand flush incomplete)的產生原因。

第一節  福爾摩斯登場

在許多偵探故事中，作為主角的偵探，總會做很多假設，故事的發展，當然無一例外證明了主角的假設。下面，為了全面展現我的分析過程，我們不妨把自己也相像成大偵探福爾摩斯，就讓福大偵探為我們分析log file switch(private strand flush incomplete)事件的原理吧。當然，也少不了他的助手華生。

好，現在切換到罪案現場。

華生：“Sir，凶案現場只能看到log file switch(private strand flush incomplete)，它是我們的唯一線索，它的原因會是什麼呢？”。

福爾摩斯：“你說呢，華生，先不要急，東方古國中有一句俗語，紙包不住火。真相一定會水落石出。你再仔細看看，我覺得你應該可以看出來點什麼。”

華生：“嗯，我只知道，log file switch(private strand flush incomplete)和日誌切換有關，這點從名字就能看出來”。

福爾摩斯：“還有呢，這也是線索啊。繼續說。private strand flush incomplete也包含了很多資訊啊”

華生：“還有的話，private strand，這個是10G後的新特性吧。有關IMU的。”

福爾摩斯讚許的點了點頭，受到鼓勵的華生頓了一頓，繼續說道：“private strand flush incomplete，也就是private strand 這塊記憶體快取區中的資料沒有被重新整理完成。再加上前面的log file switch，這個等待事件意思是LGWR在切換日誌的時候，發現private strand記憶體區中的資料還沒有重新整理完成。”

福爾摩斯高興的說：“perfect，大體上已經差不多了，但這個案子還有很多疑點。Private strand中的資料要被重新整理到哪兒？為什麼它重新整理沒有完成時，LGWR要等待？”。

華生想了想，說：“這個我就不太清楚了。”

福爾摩斯：“回憶一下IMU的原理。在IMU下，DML執行時，後映像資料先存放在哪兒？後存放在哪兒？從哪兒寫磁碟？”

華生：“這些我知道，我瞭解過IMU方面的基礎知識。DML在執行時，後映像先被存放到private strand中，在提交時被寫到Public Log Buffer中，也就是通常所說的Log Buffer，再由LGWR從Log Buffer中寫到磁碟中Redo File中。”

“啊！”華生驚叫道：“我明白了，這裡的‘private strand flush incomplete’，應該是把Private strand中的後映像寫到Log Buffer中。”

福爾摩斯肯定的答道：“是的，在這個重新整理操作沒有完成時，LGWR開始日誌切換，切換操作被重新整理操作阻塞，因此就產生了這個等待事件。”

華生：“是啊，Sir，最終情況應該就是這樣。”

福爾摩斯說：“還有些問題，……”

福爾摩斯還沒有說完，華生就搶著說道：“我知道還有什麼問題，是誰在完成‘flush private strand to public log buffer’。”

福爾摩斯說：“你變聰明瞭，華生。”

華生說：“Of cause，只有找到這個元凶，我們才能‘除錯’它。”

福爾摩斯說：“對的，我們的案犯嫌疑人，有可能是誰？”

華生說：“DML執行時，後映像資料是由Server Process產生的。在IMU方式下，後映像資料會先被Server Process放到Private Stand Area。”

福爾摩斯說：“是的，這是大家都知道的常識。還有後映像資料到達Log Buffer後，一定是由LGWR寫進磁碟中的Redo File。這一點也是大家都知道的常識。關鍵是中間呢？後映像資料到達Private Strand Area後，由誰傳送到Public Log Buffer？”

華生說：“我猜，嫌疑人只可能是兩個，Server Process或LGWR。”

福爾摩斯：“Yes，I think so.”

頓了一頓，福爾摩斯接著說：“我猜嫌疑人更有可能是Server Process。LGWR是核心人物，他負責很重要的事務，他未必有時間作案。”

“Yes，I think so.”華生學著福爾摩斯剛才的語氣說。

“哪麼，接下來，”福爾摩斯頓了頓。華生接著說：“開始跟蹤嫌疑人Server Process。”

第 二 節  跟蹤Server Process

必須要先從案發現場回來了，因為我們要說說我們的跟蹤指令碼：

bash-3.2# cat case1.d

#!/usr/sbin/dtrace -s -n

dtrace:::BEGIN

{

        i=1;

}

pid$1:::entry

{

        printf("i=%d PID::entry:==%s:%s:%s:%s %x %x %x %x %x %x",i, probeprov, probemod, probefunc, probename,arg0,arg1,arg2,arg3,arg4,arg5);

        i=i+1;

}

dtrace:::END

{

        trace(i);

}

它很簡單，dtrace:::BEGIN和dtrace:::END前一篇已經有過介紹。上面新增的探針是pid$1:::entry。

先解釋一下它吧。$1是第一個引數，如果我這樣呼叫指令碼：

./case1.d 1234

1234將是$1。在這裡，1234將代表程序號，pid1234就是說，我要跟蹤1234號程序，開啟1234程序的“程序探針”。

開啟這個探針有什麼用。

程序探針會在程序呼叫自有的函式前、後被觸發。

簡單點說，在Intel平臺下，如果程式要呼叫某一個子程式，要使用匯編指令“call 子程式地址”。Pid探針在call指令開始執行時觸發。

Call指令開始後，第一部分指令是要將子程式會修改的暫存器入棧。Pid探針就在第一條入棧命令前觸發。

更準確點說，“pid123:::entry”將在call指令被執行，pc暫存器已經指向新的位置後，子程式將一些暫存器值入棧前被觸發。

其實你完全不需要了解這麼多，我們只需要知道，Oracle每調一次函式，都會觸發一次pid123:::entry探針。

我打個這個探針的目的很簡單，顯示出Oracle呼叫的所有函式。這是通過printf語句實現的。語句中使用了很多DTrace內建變數，如：probeprov, probemod, probefunc, probename。

Probeprov：探針提供器名

Probemod：探針模型名

Probefunc：探針函式名

Probename：探針名

這些東西的意義先不管它，待會用一個實際的例子描述更好。除了這些內建變數，還有arg0,arg1,……。它們是函式呼叫時的引數。

好了，先簡單瞭解下這個探針，我們根據實際例子，會更容易理解它的意義。下面來實驗一下它。

下面切換回案發現場。

華生：“Sir，跟蹤指令碼已經準備好了：”

bash-3.2# cat case1.d

#!/usr/sbin/dtrace -s -n

dtrace:::BEGIN

{

        i=1;

}

pid$1:::entry

{

        printf("i=%d PID::entry:==%s:%s:%s:%s %x %x %x %x %x %x",i, probeprov, probemod, probefunc, probename,arg0,arg1,arg2,arg3,arg4,arg5);

        i=i+1;

}

dtrace:::END

{

        trace(i);

}

福爾摩斯：“Cool。 哪就開始吧。”

華生：“可是我們要跟蹤什麼啊？”

“這你不記得了”，福爾摩斯說，“從最基本開始。”

“從最基本開始？” 華生遲疑的重複道，“有多基礎。”

福爾摩斯說：“你不是說過IMU下DML的執行流程嗎，還記得嗎！”

華生：“說得，後映像先被存放到private strand中，在提交時被寫到Public Log Buffer中，也就是通常所說的Log Buffer，再由LGWR從Log Buffer中寫到磁碟中Redo File中。”

福爾摩斯：“是的，就是這個流程，但這都只是我們的猜測，跟蹤一下這個過程，驗證一下我們的猜測先。”

華生說：“明白了。先跟蹤一下隨便一條DML的執行，這樣就可以觀察到後映像是不是像我們說的哪樣。”

福爾摩斯：“對，開始吧。讓我們去開始尋找真相。”

不待福爾摩斯說完，華生已經開始動手跟蹤。他先隨變找了個Session，查到對應的Server Process程序號是1206，查詢命令如下：

SQL> select c.sid,spid,pid,a.SERIAL#,a.server from (select sid from v$mystat where rownum<=1) c,v$session a,v$process b where c.sid=a.sid and a.paddr=b.addr;

       SID SPID                            PID    SERIAL# SERVER

---------- ------------------------ ---------- ---------- ---------

        20 1206                             40          6 DEDICATED

SQL>

1206就是要跟蹤的試驗Session的程序了。

接著，在root使用者下，華生用vi建立了case1.d指令碼，並用chmod 755給了它掃行許可權。

在要執行跟蹤命令前，福爾摩斯突然叫住他，說：“等等，華生。先把你的測試DML語句在1206對應的Session中執行個幾次。”

華生說：“哦，對了。這樣我們的測試語句就不是硬解析了。跟蹤出來的結果會更少，更容易檢視。”

華生邊說邊把這條命令執行了4、5次。

SQL> update vage set name='AAAAA' where rowid='AAADLMAAEAAAACDAAA';

1 row updated.

SQL> rollback;

Rollback complete.

福爾摩斯說：“也不用這麼多次，三次就夠了，三次後就是軟軟解析了。”

華生嘿嘿笑著說：“多多益善。”

福爾摩斯說：“快點，開始跟蹤吧。”

華生說：“開始，開始，這就開始。”

邊說邊在root下，敲了如下的跟蹤命令：

bash-3.2# ./case1.d -x switchrate=10hz -b 16m 1206 > c1.log

dtrace: script './case1.d' matched 152979 probes  <---（注意，看到這行出現後，跟蹤命令才正式執行成功。）

（switchrate是提高輸出跟蹤結果頻率的選項，-b 16m是為了讓Dtrace指令碼可以使用更多的記憶體。> c1.log，跟蹤結果太多，重定向輸出到檔案中，方便以後檢視。）

跟蹤命令執行完後，華生在1206程序的Session中，又一次的執行測試Session：

SQL> update vage set name='AAAAA' where rowid='AAADLMAAEAAAACDAAA';

1 row updated.

然後，他熟練的到root哪邊，Ctrl+C中斷了case1.d指令碼的執行。接下來，他開始用cat c1.log察看結果。

華生還記得，福爾摩斯第一次向他展示pid探針時的情景。各種Oracle的內部函式顯示在螢幕上，他歡呼雀躍，“我終於真正進入Oracle內部”。但冷靜下來後，再看螢幕上像符咒一樣的各種函式名，他又覺得很無力。

“我們又不知道這些函式名的意義，跟蹤出來這些又有什麼用呢？”他問福爾摩斯。

“找到突破點，重點突破。”福爾摩斯以堅毅的聲音回答他。

後來，福爾摩斯終於找到了很多內部函式的意義。而且總結出了一套發掘內部函式意義的方法。這已經不是本案的範圍，華生心想，以後他會向福爾摩斯學習如何發掘內部函式，然後總結出來，寫給其他偵探參考。

隨著cat c1.log命令的執行，跟蹤結果出來了：

第三節  謎一樣的跟蹤結果

跟蹤的結果一共700多行，也就是說，一次以rowid為準的update，軟軟解析，一共需要700多次函式呼叫。圖片中列出的是前40多行。

以第一行為例，pid1206:libc.so.1:memcpy:entry fffffd7fffdfc93b d4bd870 1 1 d4bd9bc 14c。pid1206是提供器名，libc.so.1是模組名，memcpy是函式名，entry是探針名。

在跟蹤結果中，可以看到很多的memcpy函式。華生記得福爾摩斯說過，這是非常重要的一個函式呼叫，也是我們的重要突破點。資料在記憶體中來回傳遞，主要就靠這個函數了。

華生查看了跟蹤結果，什麼也沒有發現。於是說道：“Sir，我看我們應該再加上針對memcpy的處理，將memcpy拷貝的內容顯示出來。”

福爾摩斯說：“是的，我覺得也是。否則沒有突破點，什麼也看不出來。”

得到福爾摩斯的同意，華生快速的將case1.d指令碼修改為：

#!/usr/sbin/dtrace -s -n

char * memnr;

dtrace:::BEGIN

{

        i=1;

}

pid$1:::entry

{

        printf("i=%d PID::entry:==%s:%s:%s:%s %x %x %x %x %x %x",i, probeprov, probemod, probefunc, probename,arg0,arg1,arg2,arg3,arg4,arg5);

        i=i+1;

}

pid$1::memcpy:entry

{

        memnr=copyin(arg1,arg2);

        printf("%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x%2x",

                memnr[0],memnr[1],memnr[2],memnr[3],memnr[4],memnr[5],memnr[6],memnr[7],memnr[8],memnr[9],

                memnr[10],memnr[11],memnr[12],memnr[13],memnr[14],memnr[15],memnr[16],memnr[17],memnr[18],memnr[19]);

        printf("i=%d PID::entry:==%s:%s:%s:%s %x %x %d(END)",i, probeprov, probemod, probefunc, probename,arg0,arg1,arg2);

        i=i+1;

}

dtrace:::END

{

        trace(i);

}

這裡主要增加了對memcpy的跟蹤。最上面“char *memnr;”，這個非常等，宣告指令碼自己的指標變數。

而“pid$1::memcpy:entry”，是專門開啟memcpy函式的探針，當它被呼叫時觸發。“memnr=copyin(arg1,arg2)”是這裡的核心操作，arg1,arg2是memcpy的第二、三個引數。可以參考man中關於memcpy的說明。它的第二個引數是要複製記憶體的源地址。它的第三個引數是要複製多少個位元組。這裡的copyin將arg1，也就是源地址處的arg2個位元組複製到DTrace指令碼自己的記憶體空間，然後將地址賦給指標變數memnr。

“pid$1::memcpy:entry”接下來的操作，是呼叫printf顯示要複製的記憶體前二十個位元組。以16進位制形式顯示。

指令碼改變完成後，華生馬上又用將測試跑了一遍。這次的測試語句有點變化：“update vage set name='BBBBB' where rowid='AAADLMAAEAAAACDAAA';”。

原來是將此行的name列改為AAAAA，這次是改為5個BBBBB。

測試完畢，兩個人開啟測試結果，不待福爾摩斯催促，華生執行如下命令：

SQL> select dump('update vage set name',16) from dual;

DUMP('UPDATEVAGESETNAME',16)

--------------------------------------------------------------------------

Typ=96 Len=20: 75,70,64,61,74,65,20,76,61,67,65,20,73,65,74,20,6e,61,6d,65

將測試語句的字元文字，轉化成ASCII碼。然後在跟蹤結果中搜索“757064617465”。這串ASCII碼就是Update。搜尋到如下結果：

memcpy:entry 757064617465207661676520736574206e616d65i=113 PID::entry:==pid1577:libc.so.1:memcpy:entry fffffd7fffdfc7c8 d4bd94b 61(END)

可以看到Oracle把使用者發出的語句從d4bd94b，傳送到fffffd7fffdfc7c8處。

d4bd94b，可以理解為網絡卡快取。而fffffd7fffdfc7c8，則是1206程序的PGA。這一步，相當於從網絡卡快取中接收使用者傳送過來的命令。

接著，華生在其中搜索“4242424242”。在其中搜索到好幾處，第一處：

memcpy:entry 4242424242 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0i=625 PID::entry:==pid1577:libc.so.1:memcpy:entry fffffd7ffc9f90a0 3a5b7cae8 5(END)

       這是搜尋到的第一處結果。為什麼要搜尋“4242424242”，因為字母B的ASCII碼65，十六進位制值是42。

       這裡顯示，Oracle把“BBBBB”從3a5b7cae8處，拷貝到fffffd7ffc9f90a0。

3a5b7cae8是資料庫共享池中的一個地址，而fffffd7ffc9f90a0，是1206程序PGA中的地址。如何確定這兩個地址在哪個記憶體池中，已經超出本文範圍，會在以後的章節中詳細描述。

再接著，繼續搜尋4242424242：

memcpy:entry 4242424242 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0i=647 PID::entry:==pid1577:libc.so.1:memcpy:entry 3acde1249 fffffd7ffc9f90a0 5(END)

從fffffd7ffc9f90a0，拷貝到3acde1249，這是共享池的另一處地址。華生和福爾摩斯都沒有說話，兩人等著搜尋結束，總的一起來判斷問題。再接著搜尋：

memcpy:entry  54242424242 0 0 0 0 0 0 0 0 0 0 0 0 0 0i=742 PID::entry:==pid1577:libc.so.1:memcpy:entry 397541b52 3acde1248 6(END)

這裡，BBBBB被從剛才的共享池中，拷貝到397541b52，這是Buffer Cache中的地址。

再向後搜尋4242424242，沒有了。就這麼多了。搜尋完成。

華生看著福爾摩斯，福爾摩斯低頭思索了一下，說：“我們第一次搜尋到從網絡卡快取，向PGA拷貝SQL，這是1206程序在接收使用者語句。”

華生道到：“是的。”

福爾摩斯接著說：“測試SQL你已經執行了好幾遍，它已經是軟軟解析，也就是它已經被快取到PGA中。在接到SQL後，Oracle會進行判斷，找到PGA中快取的SQL資訊，也就是Shared SQL Area地址。然後，到共享池中找到SQL資訊。”

華生說：“是的，對這一部分東西，我們在另一個案件中，對這塊程式碼進行過測試。Oracle還會呼叫kgscComputeHash函式計算HASH值，然後在PGA中根據HASH值定位被快取SQL資訊的地址。”

福爾摩斯說：“是的。然後，它從共享池中的Shared SQL Area中，將SQL語句文字中的‘BBBBB’拷貝到PGA中，這一步的目的，應該是在PGA中，對後映像進行一些判斷。再然後呢，從PGA中拷貝到共享池的另一位置，這一位置，應該就是共享池中的Private Redo Area區。”

“是的”，華生答道，“最後一次拷貝BBBBB，是從這裡拷貝到Buffer Cache，這一步完成真正的修改，資料塊在Buffer Cache中被修改，變成髒塊，等待DBWR寫回磁碟，是嗎？”

華生仍不能十分確定自己的分析是否正確。

“沒錯，”福爾摩斯馬上給出了肯定的答案，“正是這樣。”他繼續分析道：“也就是說倒數第二次拷貝BBBBB，是向Private Redo Area中拷貝。”

華生說：“是的，看來是這樣。那麼，”華生遲疑了一下，“接下來呢？”

第 四 節  水落石出

“接下來，”福爾摩斯說，“我們需要另一個突破點 ---- Latch。我們需要知道，Oracle都在哪裡獲得了In memory undo latch”

獲得Latch的函式，有兩個：ksl_get_shared_latch和kslgetl。前者是獲得共享Lathc，後者只針對獨佔Latch。在而跟蹤結果中找這兩個函式，比如：

ksl_get_shared_latch:entry i=283 PID::entry:==pid1577:oracle:ksl_get_shared_latch:entry 3aca69a18 0 0 c3c 10 200000000000001f

用如下語句，可以從它的第四個引數，c3c，得到Latch的資訊：

select a.addr,b.addr,a.KSLLWNAM,a.KSLLWLBL,b.KSLLASNAM from x$ksllw a,x$kslwsc b where a.indx=b.indx and a.indx=to_number('&aa','xxxxxxxx');

這裡的查詢結果是：

看，這裡它是一個in memory undo latch。使用這個語句，我們就可以知道程式碼中什麼地方持有什麼Latch。

釋放Latch的話，無論是共享還是獨佔，都是用kslfre釋放。它的第一個引數是要釋放Latch的地址。

在第283次函式呼叫時，程序持有了IMU Latch，到第290次呼叫時釋放。這一次持有IMU Latch的目的，是為了獲得IMU區、Private Redo Area。

然後，在714次函式呼叫時，程序又一次申請IMU Latch，這一次持有很久，一直到767次呼叫時才釋放。

其中，包含了最後一次BBBBB拷貝。從共享池的Private Redo Area拷貝到Buffer Cache中。

福爾摩斯看到這裡時，多次除錯Oracle的直覺，讓他覺得這裡應該和本案有關聯，他問華生，但更像是自言自語道：“這裡程序要持有這麼久的IMU Latch，你說，如果程序還沒有來得急釋放Latch時，發生了日誌切換，會有什麼情況呢？”

華生說：“程序沒有釋放Latch，日誌切換時需要獲得IMU Latch的，這時，LGWR會產生IMU Latch等待唄，這點應該沒啥疑問。”

福爾摩斯說：“嗯，看起來是這樣。但還要試一試才知道。使用mdb，讓程序的執行流程到第714次函式呼叫處。”

華生說：“好的，在714次ksl_get_shared_latch處的上面，第713次呼叫是ktichg函式。它的下一次函式呼叫就是ksl_get_shared_latch了。而且在第713呼叫前，ktichg沒被呼叫過。”

福爾摩斯說：“好，就在它這裡設定斷點。”

華生馬上動手，輸入如下命令：

bash-3.2# mdb -p 1206

Loading modules: [ ld.so.1 libc.so.1 ]

> 

等到出現>提示符時，他又輸入了：

> ktichg:b

> :c

在ktichg函式處設定斷點，然後用:c讓程序繼續執行。然後，他回到1206對應的Session中，又一次執行了測試SQL：

SQL> update vage set name='BBBBB' where rowid='AAADLMAAEAAAACDAAA';

測試SQL被HANG住了，因為MDB已經開始對它進行除錯，可以檢視mdb這邊的結果：

bash-3.2# mdb -p 1958

Loading modules: [ ld.so.1 libc.so.1 ]

> ktichg:b

> :c

mdb: stop at ktichg

mdb: target stopped at:

ktichg:         pushq  %rbp

>

執行流程已經停在了ktichg處。然後，再在ksl_get_shared_latch處設定斷點，並讓程序執行到ksl_get_shared_latch處：

> ksl_get_shared_latch:b

> :c

mdb: stop at ksl_get_shared_latch

mdb: target stopped at:

ksl_get_shared_latch:   pushq  %rbp

> 

然後，我們需要使用$r命令，檢視一下暫存器：

> $r

%rax = 0x0000000000000c2b       %r8  = 0x0000000000000010

%rbx = 0x0000000000000020       %r9  = 0x2000000000000027

%rcx = 0x0000000000000c2b       %r10 = 0x00000003af112860

%rdx = 0x0000000000000000       %r11 = 0x0020007500c00a4b

%rsi = 0x0000000000000001       %r12 = 0x00000003acd32d38

%rdi = 0x00000003aca69ab8       %r13 = 0x00000003aca7c318

                                %r14 = 0x000000038002a0f8

                                %r15 = 0x000000000ceed2b0

%cs = 0x004b    %fs = 0x0000    %gs = 0x0000

%ds = 0x0000    %es = 0x0000    %ss = 0x0043

%rip = 0x0000000001594460 ksl_get_shared_latch

%rbp = 0xfffffd7fffdf7d60

%rsp = 0xfffffd7fffdf7bc8

%rflags = 0x00000246

  id=0 vip=0 vif=0 ac=0 vm=0 rf=0 nt=0 iopl=0x0

  status=<of,df,IF,tf,sf,ZF,af,PF,cf>

%gsbase = 0x0000000000000000

%fsbase = 0xfffffd7ffcbc0200

%trapno = 0x3

   %err = 0x0

> 

       其中，rcx暫存器是ksl_get_shared_latch函式的第四個引數的值，此處它的值為：

%rcx = 0x0000000000000c2b

       C2b，這證明此處的ksl_get_shared_latch，就是要審請IMU Latch。

       好，再下一步，讓流程停到kslfre處：

> kslfre:b

> :c

mdb: stop at kslfre

mdb: target stopped at:

kslfre:         pushq  %rbp

> 

       此時，1206程序已經持有了IMU Latch，但還沒有釋放。因為我們停在了釋放函式的入口處。然後，在另外一個Session，發出一條日誌切換命令：

SQL> update iotest1 set name=lower(name) where rownum<=16000;

       Name列是2000位元組的大列，因此這條語句將產生很多Redo，將會導致日誌切換。當華生執行完這條語句後，它果然被Hang住了。也就是說，日誌切換操作會去持有IMU Latch。

       看到這裡，華生說：“Sir，日誌切換操作被Hang住了，我看應該是有IMU Latch等待了。”

相關推薦