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等待了。”

       福尔摩斯点了点头，说：“嗯，有可能。但还要最后确认下，查一下等待事件。”

       华生说：“IMU Latch还被持有着，这时触发日志切换，肯定是IMU Latch等待了。”虽然不太情愿，但还是按福尔摩斯吩咐，查询了当前的等待事件：

SQL> select sid,seq#,event, state ,program from v$session where wait_class<>'Idle' order by event;

SQL> select sid,event, state ,program from v$session where wait_class<>'Idle' order by event;

SID EVENT      STATE               PROGRAM

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

23 SQL*Net message to client                     WAITED SHORT TIME   sqlplus@H1 (TNS V1-V3)

22 log file switch (private strand flush incompl WAITING             sqlplus@H1 (TNS V1-V3)

       “啊！”，看到查询结果，华生惊的说不出话来，“这，这，……。”

       福尔摩斯对着屏幕缓缓说道：“log file switch (private strand flush incomplete)，我们终于见面了。”

       华生半天才说出话来：“怎么会这样。应该是IMU Latch的等待才对啊，为什么变成了它。”

       福尔摩斯说道：“对，是IMU Latch。我们的1206进程一直持有着IMU Latch，这时22号Session产生大量Redo，触发日志切换。22号Session的进程首先要获得所有的IMU Latch，然后刷新所有IMU区和Private Redo Area，然后通知LGWR日志切换。22号Session在申请获得某一个IMU Latch时，被1206进程阻塞，因为它被mdb定住，一直在持有着IMU Latch。这时，22号Session本应该等IMU Latch，但估计Oracle觉得此处显示一个Latch等待，不能很好的说明当前遇到的问题。而log file switch (private strand flush incomplete)，则明确告诉用户，当前的等待是由于日志切换被阻塞，而被阻塞的原因，是Private Redo Area不能被刷新所致。”

       华生楞了一下，他需要时间消化这一大段话。过了一会儿，他才缓过劲来，说：“的确，如果v$session中显示latch: In memory undo latch等待，的确不如显示成log file switch (private strand flush incomplete)更加可读、直观。那也就是说，所谓的log file switch (private strand flush incomplete)等待，根本就是进程在等待申请IMU Latch，不像官方文档中所说，‘wait on this event when LGWR waits for DBWR to complete flushing redo from IMU buffers into the log buffer’。”

       福尔摩斯点头回答道：“看来是这样的。”

       华生又迟疑的问道：“为什么官方文档中写的有问题呢？”

       福尔摩斯说：“要么写文档的人也不知道，要么Oracle想闪烁其词。不过，这都于我们没有关系，我们读文档，参考性的去读就行，东方有句古话，尽信书不如无书。”

       案件终于告破，但我想肯定还有人不明所以。别担心，这篇文章只是简单展示一下“调试Oracle的作用”，如果想全面了解调试Oracle的技术方法，只看这篇文章一定是不够的，

       最后一句话总结一下，“调试Oracle”很难，需要很多基础知识和极大的耐心，是一条崎岖的山路，但它可以助你更快速的登上高峰，“无限风光在险峰”。

* 本文版权和/或知识产权归eBay Inc所有。如需引述，请和联系我们DL-eBay-CCOE-Tech@ebay.com。本文旨在进行学术探讨交流，如您认为某些信息侵犯您的合法权益，请联系我们DL-eBay-CCOE-Tech@ebay.com，并在通知中列明国家法律法规要求的必要信息，我们在收到您的通知后将根据国家法律法规尽快采取措施。