Article transferred from: http://m.bianceng.cn/database/Oracle/201407/42884.htm
Test environment: Version 11gr2
SQL> select * from V $ version where rownum = 1;
Banner
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0-64bit Production
I. Logical read Process
1. Oracle performs hash operations based on the file number, block number, and type of each block to obtain the hash value. Extracts the memory address of the specified block from the hash table based on the hash value.
2. Obtain CBC latch (key test part of the experiment)
3. Search for the CBC linked list based on the hash value
4. Find BH (buffer header) and buffer pin based on DBA
5. Immediately release the CBC latch after adding the buffer pin.
6. Access the buffer to start fetch data
7. Obtain CBC Latch
8. Release the buffer pin.
9. Release CBC Latch
2. Obtain the first row of data and rowid of table T1, and find the file number and block number of this row of data according to the dbms_rowid package.
SQL> select rowid, dbms_rowid.rowid_relative_fno (rowid) file #, dbms_rowid.rowid_block_number (rowid) block #, ID, name from gyj. T1 where rownum = 1;
Rowid file # block # ID name
----------------------------------------------------------
Aaasp9aagaaaachaaa 6 135 1 aaaaa
Here, DBA (data block address) is composed of file 6 and block 135.
3. Obtain the CBC latch address based on the file number block number
SQL & gt; select hladdr from x $ BH where file # = 6 and dbablk = 135;
Hladdr
----------------
20170003a4282a90
4. The number of times the CBC latch is obtained based on the CBC latch address.
1. The number of times to obtain the CBC latch is 245.
SQL> select ADDR, name, gets from V $ latch_children where ADDR = '00000003a4282a90 ';
ADDR name gets
------------------------------------------------------------------------------------------
20170003b09f7c58 cache buffers chains 245
2. Read the first data of table T1 again, that is, a logical read is generated.
SQL> select ID, name from gyj. T1 where rowid = 'aaasp9aagaaaachaa ';
ID name
--------------------
1 gyj1
3. The number of CBC latch requests has changed to 247, indicating that one logical read generates two CBC latch requests.
SQL> select ADDR, name, gets from V $ latch_children where ADDR = '00000003a4282a90 ';
ADDR name gets
------------------------------------------------------------------------------------------
20170003a4282a90 cache buffers chains 247
5. Check the process number in this session
SQL> select spid from V $ session S, V $ process B where S. paddr = B. ADDR and S. Sid in (select Sid from V $ mystat where rownum = 1 );
Spid
------------------------
2416
6. Use the dtrace tool for tracking
1. Write a simple dtrace script
VI dtrace. d
#! /Usr/sbin/dtrace-S-N
Dtrace: Begin
{
I = 1;
}
PID $1: Entry
{
Printf ("I = % d PID: Entry :=% S: % s: % S % x % d % x ", i, probeprov, probemod, probefunc, probename, arg0, arg1, arg2, arg3, arg4, arg5 );
I = I + 1;
}
2. Grant Permissions
Chmod 755 dtrace. d
3. Execute the dtrace command to generate the trace log
./Dtrace. D-x switchrate = 1Hz-B 32 m 2416> dtracecbc. log -- Use this command to increase the cache to avoid log loss
4. display some major dtrace logs. Search for latch address in dtracecbc. Log: 3a4282a90
Cpu id function: Name
-- Logical read start
1 63919 kcbgtcr: Entry I = 592 PID: Entry :== pid2416: oracle: kcbgtcr: Entry fffffd7ffc98bc00 0 2Fe 0 23dedede0 fffffd7fffdfa7a0
-- Obtain CBC Latch
1 128720 sskgslcas: Entry I = 593 PID: entry: = pid2416: oracle: sskgslcas: Entry 3a4282a90 0 0 0 0 3a4c953d0
1 60714 ktrexf: Entry I = 594 PID: Entry :== pid2416: oracle: ktrexf: Entry fffffd7fffdfa7a0 d7fcd60 0 15392235540 1fe8 23dc9f0
1 64185 kcbzgs: Entry I = 595 PID: entry: = pid2416: oracle: kcbzgs: Entry 1 d7fcd60 0 0 0 23dc9f0
1 53939 kssadf_numa_intl: Entry I = 596 PID: Entry :== pid2416: oracle: kssadf_numa_intl: entry 23 3a4145900 3a1_d9e8 0 0 1d
-- Find BH (buffer header) and buffer pin based on DBA
1 128720 sskgslcas: Entry I = 597 PID: entry: = pid2416: oracle: sskgslcas: Entry 3957f6280 0 1 0 3957f6238 3957f6238
-- Release the CBC latch immediately after adding the buffer pin.
1 128723 sskgsldecr: Entry I = 598 PID: entry: = pid2416: oracle: sskgsldecr: Entry 3a4282a90 1 1 0 1 2000000000000000
1 63951 kcbcge: Entry I = 599 PID: entry: = pid2416: oracle: kcbcge: Entry fffffd7ffc98bc00 0 77 0 fffffd7ffc98b7dc 0
1 64116 kcbds2pbh: Entry I = 600 PID: Entry :== pid2416: oracle: kcbds2pbh: Entry fffffd7ffc98bc00 0 77 0 fffffd7ffc98b7dc 0
1 60179 ktcckv: Entry I = 601 PID: Entry :== pid2416: oracle: ktcckv: Entry fffffd7ffc98bc00 fffffd7ffc98b7d4 77 0 3a3c935f0 0
1 104774 kafger: Entry I = 602 PID: entry: = pid2416: oracle: kafger: Entry 39572e064 fffffd7fffdfb200 39d84e4f0 2 1
1 83919 kpofcr: Entry I = 603 PID: Entry :== pid2416: oracle: kpofcr: Entry fffffd7fffdfb4b0 1 39d84e4f0 2 4c30d40 3a4fd3790
1 124023 ttcrxh: Entry I = 604 PID: entry: = pid2416: oracle: ttcrxh: Entry d8055e8 d7f58f0 fffffd7fffdfafe0 48 214 1
1 209006 memcpy: Entry I = 605 PID: Entry :== pid2416: libc. so.1: memcpy: Entry ddfa329 fffffd7fffdfafe0 30 30 48 ddfa359 d7f5a00
1 209006 memcpy: Entry I = 606 PID: entry: = pid2416: libc. so.1: memcpy: Entry ddfa35b 39572fff5 2 2 2 d7f5a00
1 123964 ttcc2u: Entry I = 607 PID: entry: = pid2416: oracle: ttcc2u: Entry d8055e8 d7f58f0 39572fff8 4 1
1 209006 memcpy: Entry I = 608 PID: entry: = pid2416: libc. so.1: memcpy: Entry ddfa35e 39572fff8 4 852 d7f5a00 d7f5a00
1 61112 ktsmg_max_query: Entry I = 609 PID: Entry :== pid2416: oracle: ktsmg_max_query: Entry 0 0 39572 fffc 0 d805250 2
1 211309 gethrtime: Entry I = 610 PID: entry: = pid2416: libc. so.1: gethrtime: Entry 92d 1A 39572 fffc 8 3a4447d80 39de97dc8
1 128314 slcpums: Entry I = 611 PID: entry: = pid2416: oracle: slcpums: Entry d805218 1A 494b3f016 8 3a443a460 39c252138
1 211401 times: Entry I = 612 PID: entry: = pid2416: libc. so.1: Times: Entry fffffd7fffdfb240 1A 494b3f016 8 3a443a460 39c252138
1 131260 kglhandleinvalidations: Entry I = 613 PID: Entry :== pid2416: oracle: kglhandleinvalidations: Entry d8055e8 39df04bb0 0 8 d7f1a10 39c2d1140
1 131261 kglhandleloads: Entry I = 614 PID: Entry :== pid2416: oracle: kglhandleloads: Entry d8055e8 39df04bb0 0 8 d7f1a10 39c2d1140
1 91756 kksgetstats: Entry I = 615 PID: Entry :== pid2416: oracle: kkksgetstats: Entry 39d738198 39df04bb0 0 8 d7f1a10 39c2d1140
1 72794 kews_sqlcol_end: Entry I = 616 PID: Entry :== pid2416: oracle: kews_sqlcol_end: Entry 3a4fd2210 fffffd7ffc9e1ad8 39d737e88 70 1
1 110094 qecrlssub: Entry I = 617 PID: Entry :== pid2416: oracle: qecrlssub: Entry 39d84ed10 fffffd7ffc9e1ad8 9 0 fffffd7ffc98ac58 0
1 108487 qertbrelease: Entry I = 618 PID: Entry :== pid2416: oracle: qertbrelease: Entry 39d84dea8 fffffd7ffc98bae0 9 0 4c0 dbb56b0
1 104779 kafcpy: Entry I = 619 PID: entry: = pid2416: oracle: kafcpy: Entry 39d84e4f0 2 9 0 fffffd7ffc987430 20
-- Access buffer to start fetch data
1 209006 memcpy: Entry I = 620 PID: entry: = pid2416: libc. so.1: memcpy: Entry fffffd7ffc9f49f8 39572fff8 4 0 30 20
1 209006 memcpy: Entry I = 621 PID: entry: = pid2416: libc. so.1: memcpy: Entry fffffd7ffc9f49e0 39572fff5 2 1 30 20
1 63927 kcbipnns: Entry I = 622 PID: Entry :== pid2416: oracle: kcbipnns: Entry fffffd7ffc98bc00 39572fff5 39572fff7 0 fffffd7ffc98bbe8 2C1