邏輯讀時的cbc latch(二)

繼續驗證，使用solaris中的dtrace

session1:編寫dtrace腳本

more test.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;
}

session2:多執行幾次rowid查詢，使查詢走邏輯讀

create table a as select * from scott.emp;
create index ind_a on a(empno);
select c.sid,spid,pid,a.SERIAL# 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#
---------- ------------ ---------- ----------
       159 1154                 15          3
       
select * from a where rowid='AAAMjsAABAAAOs6AAA';

session1:運行dtrace腳本，并輸出到日志

./test.d 1154 > logic_read1.log

session2:再次執行一次，此時為邏輯讀

select * from a where rowid='AAAMjsAABAAAOs6AAA';

session1:查詢文件，文件內容為語句執行期間做的跟蹤

cat logic_read1.log|wc -l
1393

session2:

select dbms_rowid.ROWID_RELATIVE_FNO('AAAMjsAABAAAOs6AAA'),dbms_rowid.rowid_block_number('AAAMjsAABAAAOs6AAA') from dual;
1 60218

select file#,dbablk,tch,lower(HLADDR) from x$bh where file#=1 and dbablk=60218;
     FILE#     DBABLK        TCH LOWER(HL
---------- ---------- ---------- --------
         1      60218          8 5f0f596c

1號文件60218號塊，是受地址為5f0f596c的Latch保護

session1:

cat logic_read1.log|grep 5f0f596c
  1 113271                  sskgslcas:entry i=637 PID::entry:==pid1154:oracle:sskgslcas:entry 5f0f596c 0 2000000f fdc1a128 fdc1a0d0 fdc1a128
  1 113274                 sskgsldecr:entry i=646 PID::entry:==pid1154:oracle:sskgsldecr:entry 5f0f596c 2000000f fdc1a128 fdc1a0d0 fdc1a128 804534c
  1 113271                  sskgslcas:entry i=687 PID::entry:==pid1154:oracle:sskgslcas:entry 5f0f596c 0 2000000f 1 fdc1a0c0 5854e074
  1  59436                     kcbzar:entry i=692 PID::entry:==pid1154:oracle:kcbzar:entry 5f181bcc 5f0f596c 108000 8045268 1 fdc1a0c0
  1 103456                   slmxnoop:entry i=693 PID::entry:==pid1154:oracle:slmxnoop:entry 587ed578 fdc1a130 5f0f596c 8045238 a9ef965 c4a88d0
  1 103456                   slmxnoop:entry i=694 PID::entry:==pid1154:oracle:slmxnoop:entry 587ed578 fdc1a130 5f0f596c 8045238 a9ef965 c4a88d0
  1 103456                   slmxnoop:entry i=695 PID::entry:==pid1154:oracle:slmxnoop:entry 587ed578 fdc1a130 5f0f596c 8045238 a9ef965 c4a88d0
  1 103456                   slmxnoop:entry i=696 PID::entry:==pid1154:oracle:slmxnoop:entry 587ed578 fdc1a130 5f0f596c 8045238 a9ef965 c4a88d0
  1 103456                   slmxnoop:entry i=697 PID::entry:==pid1154:oracle:slmxnoop:entry 587ed578 fdc1a130 5f0f596c 8045238 a9ef965 c4a88d0
  1 103456                   slmxnoop:entry i=699 PID::entry:==pid1154:oracle:slmxnoop:entry 587ed578 fdc1a130 5f0f596c 8045238 a9ef965 c4a88d0
  1 113274                 sskgsldecr:entry i=701 PID::entry:==pid1154:oracle:sskgsldecr:entry 5f0f596c 2000000f 1 fdc1a0c0 5854e074 8045410
  1  54264                     k***mf:entry i=703 PID::entry:==pid1154:oracle:k***mf:entry 5f181ba8 5f0bcc2c 587ed578 2000000f 5f0f596c 5f181bcc

和這個地址(5f0f596c)相關的有這十幾行。在這里，有一點編程習慣再說一下，要申請某一個地址處的Latch，這個Latch的地址，是這個函數的最重要的參數，

因此，Oracle會把它排在第一位，也就是說，以上這十幾行中，第一個參數不是8ea1d750的，基本可以排除掉了。

所以，我們只剩這些行需要關注:

  1 113271                  sskgslcas:entry i=637 PID::entry:==pid1154:oracle:sskgslcas:entry 5f0f596c 0 2000000f fdc1a128 fdc1a0d0 fdc1a128
  1 113274                 sskgsldecr:entry i=646 PID::entry:==pid1154:oracle:sskgsldecr:entry 5f0f596c 2000000f fdc1a128 fdc1a0d0 fdc1a128 804534c
  1 113271                  sskgslcas:entry i=687 PID::entry:==pid1154:oracle:sskgslcas:entry 5f0f596c 0 2000000f 1 fdc1a0c0 5854e074
  1 113274                 sskgsldecr:entry i=701 PID::entry:==pid1154:oracle:sskgsldecr:entry 5f0f596c 2000000f 1 fdc1a0c0 5854e074 8045410

這四行，兩個函數調用，sskgslcas、sskgsldecr，

第一個參數都是Latch的地址：5f0f596c 我相信這不是巧合，它們肯定是申請、釋放Latch的函數。

i=637這行，Oracle調用sskgslcas持有Latch，在i=646這行，調用sskgsldecr釋放，

接下來在i=687又一次調用sskgslcas持有Latch，在i=701處調用sskgsldecr釋放。

一次邏輯讀對應兩次Latch調用。

結果是這樣嗎，讓我們繼續驗證，Oracle的Oradebug可以調用某個Oracle自身的函數，就有它來驗證吧：

session2:

SQL> oradebug setmypid
Statement processed.
SQL> oradebug call sskgslcas 0x5f0f596c 0 0x2000000f 0xfdc1a128
Function returned 1

SQL>select * from a where rowid='AAAMjsAABAAAOs6AAA';
Hang住了

session3:查看等等事件，并釋放latch

SQL> select sid,event,p1raw,p2 from v$session where sid=159;

       SID EVENT
---------- ----------------------------------------------------------------
P1RAW            P2
-------- ----------
       159 latch: cache buffers chains
5F0F596C        122

SQL> oradebug setospid 1154
Oracle pid: 15, Unix process pid: 1154, p_w_picpath: oracle@sol (TNS V1-V3)
SQL> oradebug call sskgsldecr 0x5f0f596c 0x2000000f
Function returned 2000000F

在session2中查看，此時結果出來了。說明被Hang的會話，已經可以順利執行下去了。說明Latch已經被釋放。

結論：一次邏輯讀，兩次cbc latch，cbc latch的申請函數為sskgslcas，釋放函數為sskgsldecr

邏輯讀時的cbc latch(一)：http://qhd2004.blog.51cto.com/629417/1576554

邏輯讀時的cbc latch(三): http://qhd2004.blog.51cto.com/629417/1577532

參考：http://blog.itpub.net/321157/viewspace-730936/