You don’t understand anything until you learn it more than one way.
Marvin Minsky
Marvin Minsky
(I)-Tracing Methods (II)-Object Type(Part-1) (III)-Object Type(Part-2) (IV)-Sql Executions (IV) (V)-Contentions and Scalability
This small Oracle Row Cache Cookbook is made of a series of 5 Blogs:
Oracle row cache objects Event: 10222, Dtrace Script (I) Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-1) (II) Row Cache Objects, Row Cache Latch on Object Type: Plsql vs Java Call (Part-2) (III) Row Cache and Sql Executions (IV) Latch: row cache objects Contentions and Scalability (V)
This Blog will present two tracing methods of row cache objects Gets, which provide more deep insights than ordinary Oracle dynamic performance views (v$rowcache, v$latch, etc.).
At first we explore Event: 10222 to trace row cache objects Gets, and then create a PL/SQL script to import and analyse the generated trace files.
As a second approach, three Dtrace scripts are composed and tested:
-. rco_dtrace_cache: trace each Row Cache Object Get with its arguments. -. rco_dtrace_latch: printout each Row Cache Latch Get call stack. -. rco_dtrace_std: draw a State Transition Diagram for Object and Latch Gets.The difference of three methods are their precision of perceiving granularity.
(1). dynamic performance views: statement (2). 10222 trace: row cache (3). dtrace: latch (atomic locking mechanism)Note: all tests are done in Oracle 12cR1 (12.1.0.2.0), and 12cR2 (12.2.0.1.0).
1. Trace Event: 10222
Perform the tracing on the same query as Blog: nls_database_parameters, dc_props, latch: row cache objects, and compare with the output of dynamic performance views in that Blog.
More details are revealed by increasing the tracing Level.
1.1. Level 4
alter session set max_dump_file_size = UNLIMITED;
alter session set tracefile_identifier = 'row_cache_10222_4';
alter session set events '10222 trace name context forever, level 4';
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
alter session set events '10222 trace name context off';
---------------------- Output ----------------------
kqrpre1 : found po=18f058b68 flg=2 hash=5b42c02e .
kqrpre1 : done po=18f058b68 cid=15 flg=2 hash=5b42c02e 0 eq=13feab2b0 .
kqrpre1 : found po=142020320 flg=2 hash=2155f5c0 .
kqrpre1 : done po=142020320 cid=15 flg=2 hash=2155f5c0 0 eq=13feab2b0 .
1.2. Level 255
alter session set tracefile_identifier = 'row_cache_10222_255';
alter session set events '10222 trace name context forever, level 255';
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
alter session set events '10222 trace name context off';
---------------------- Output ----------------------
kqrpre1 : found po=18f058b68 flg=2 hash=5b42c02e time=2235042744
kqrmpin : kqrLockAndPinPo Pin po 18f058b68 cid=15 flg=2 hash=5b42c02e time=2235042857
kqrpre1 : done po=18f058b68 cid=15 flg=2 hash=5b42c02e 0 eq=13fea3cd0 time=2235042872
kqrmupin : kqrpspr2 Unpin po 18f058b68 cid=15 flg=2 hash=5b42c02e time=2235042890
kqrpre1 : found po=142020320 flg=2 hash=2155f5c0 time=2235042919
kqrmpin : kqrLockAndPinPo Pin po 142020320 cid=15 flg=2 hash=2155f5c0 time=2235042945
kqrpre1 : done po=142020320 cid=15 flg=2 hash=2155f5c0 0 eq=13fea3cd0 time=2235043046
kqrmupin : kqrpspr2 Unpin po 142020320 cid=15 flg=2 hash=2155f5c0 time=2235043061
1.3. Level 4294967295
alter session set tracefile_identifier = 'row_cache_10222_4294967295';
alter session set events '10222 trace name context forever, level 4294967295';
select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
alter session set events '10222 trace name context off';
---------------------- Output ----------------------
kqrpre1 : found po=18f058b68 flg=2 hash=5b42c02e time=2271264535
kqrmpin : kqrLockAndPinPo Pin po 18f058b68 cid=15 flg=2 hash=5b42c02e
time=2271264669
kqrpre1 : done po=18f058b68 cid=15 flg=2 hash=5b42c02e 0 eq=13fea57f8 SQL=select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET' time=2271264687
kqrmupin : kqrpspr2 Unpin po 18f058b68 cid=15 flg=2 hash=5b42c02e time=2271264704
kqrmupin : free po=18f058b68 flg=2
kqrfrpo: Free po 18f058b68
KQR Parent Cache Object:
pob = 18f058b68 flg = 00000002 cid = 15 xcb = 0 hbk = 18f05ac38
hbk=[f84f96e8,151186580]
own=18f058c38[18f058c38,18f058c38] wat=18f058c48[18f058c48,18f058c48] mod=0
kqrfrpo : freed to heap po=18f058b68 time=2271264814
kqrpre1 : found po=142020320 flg=2 hash=2155f5c0 time=2271264844
kqrmpin : kqrLockAndPinPo Pin po 142020320 cid=15 flg=2 hash=2155f5c0
time=2271264871
kqrpre1 : done po=142020320 cid=15 flg=2 hash=2155f5c0 0 eq=13fea57f8 SQL=select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET' time=2271264885
kqrmupin : kqrpspr2 Unpin po 142020320 cid=15 flg=2 hash=2155f5c0 time=2271264904
kqrmupin : free po=142020320 flg=2
kqrfrpo: Free po 142020320
KQR Parent Cache Object:
pob = 142020320 flg = 00000002 cid = 15 xcb = 0 hbk = 1420223f0
hbk=[1511862a0,18f077dd0]
own=1420203f0[1420203f0,1420203f0] wat=142020400[142020400,142020400] mod=0
kqrfrpo : freed to heap po=142020320 time=2271264992
1.4. Trace Level Discussion
Tests showed:
Level 4 (5, 7, 15 are same) prints only kqrpre1 subroutine call. Level 255 prints kqrpre1, kqrmpin, kqrmupin. Level 4294967295 prints kqrpre1, kqrmpin, kqrpre1, kqrmupin, kqrmupin, kqrfrpo, kqrfrpo.where 4294967295 (2^32-1) seems the maximum tracing level with most details, including SQL statements.
"cid" denotes Cache ID; "kqrpre1" is for row cache object Read; "po" is for Parent Object.
There is also Event: 10205 which says:
10205, 00000, "row cache debugging"
// *Cause:
// *Action:
/ At level 1, KQR will dump out latch clean-up debugging traces.
/ At level 2, KQR will dump out bootstrap debugging traces.
/ At level 3, KQR will invalidate, remove from the cache and put 0xff's
/ in row cache objects that are not currently locked.
1.5. Are trace levels always bitmap additive ?
A common belief of trace levels is bitmap additive (all binary numbers are positive, different, power of 2).
If we run following Plsql, Level 516 output includes SQL statements. Since 516 is bitmap additive of 4 and 512:
516 = 4 + 512 = 2^2 + 2^9Level 4 or Level 512 should contain SQL statements. But the test shows that Level 4 contains only "kqrpre1" in 12cR1 (and "kqreqd" in 12cR2); Level 512 does not generate any trace file. So Level 516 is not bitmap additive in this case, probably some hard-coded logic
(Level 513, 514 and 515 also not generate any trace file).
create or replace procedure test10222_trace_level as
type t_level_tab is table of pls_integer;
l_level_tab t_level_tab := new t_level_tab(4, 512, 513, 514, 515, 516);
l_trc_prefix varchar2(256) := 'row_cache_10222_Level_';
l_val varchar2(256);
begin
for i in 1..l_level_tab.count loop
execute immediate q'[alter session set tracefile_identifier = ']' ||l_trc_prefix||l_level_tab(i)||q'[']';
execute immediate q'[alter session set events '10222 trace name context forever, level ]'||l_level_tab(i)||q'[']';
select value into l_val from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
execute immediate q'[alter session set events '10222 trace name context off']';
end loop;
end;
/
exec test10222_trace_level;
2. 10222 Trace Import and Analyse
2.1. Import
Import the trace files into DB via external files (see appended PL/SQL Script)
set serveroutput on
exec import_10222_trc_proc(1, 'testdb_ora_7920_row_cache_10222_4.trc');
exec import_10222_trc_proc(2, 'testdb_ora_7920_row_cache_10222_255.trc');
exec import_10222_trc_proc(3, 'testdb_ora_7920_row_cache_10222_4294967295.trc');
2.2. Analyze
Here a list of queries to analyze Trace Level 4294967295 (RUN=3).
select rownum line_nbr, text1 from raw_10222_trc_ext;
select * from import_10222_trc
where run=3
order by run, line_nbr;
select cid, cid_type, cid_subordinate#, cid_parameter, count(*) cnt
from import_10222_trc
where run=3
group by cid, cid_type, cid_subordinate#, cid_parameter
order by cnt desc;
CID CID_TYPE CID_SUBORDINATE# CID_PARAMETER CNT
--- ----------- ---------------- ------------- ---
15 PARENT dc_props 63
7 SUBORDINATE 0 dc_users 14
17 PARENT dc_global_oids 4
11 4
8 PARENT dc_objects 1
1
select ts_us - lag(ts_us) over(partition by run order by line_nbr) elapsed_us, t.*
from import_10222_trc t
where run=3
order by run, line_nbr;
select cid, cid_type, cid_subordinate#, cid_parameter, count(*) cnt, sum(elapsed_us) elapsed_us from (
select ts_us - lag(ts_us) over(partition by run order by line_nbr) elapsed_us, t.*
from import_10222_trc t
where run=3 order by run, line_nbr)
group by cid, cid_type, cid_subordinate#, cid_parameter order by cnt desc;
-- only tested on Solaris (x86-64)
select * from import_10222_trc t, v$rowcache_parent r
where t.run=3 and '0000000'||t.po_address = r.address(+)
order by run, line_nbr;
3. Dtrace Script
3.1 Row Cache Object Gets
Run the same query in one Sqlplus Session (SID: 123, SPID: 7890), and at the same time, trace it by following trace Script (see appended Dtrace Script: rco_dtrace_cache).
SQL (123, 456) > select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
sudo dtrace -n \
'pid$target::kqrLockAndPinPo:entry /execname == "oracle"/ {
@CID_ADDR_CNT[arg0, arg1] = count();
@CID_CNT[arg0] = count();
printf("\nCID = %-4d ADDR = %-16X\n", arg0, arg1);}
END {
printf("\n----- CID_ADDR CNT -----\n"); printa("CID = %-4d ADDR = %-16X CNT = %-10@d\n", @CID_ADDR_CNT);
printf("\n----- CID CNT -----\n"); printa("CID = %-4d CNT = %-10@d\n", @CID_CNT);
printf("\n*** all except 1st counting doubled ***\n");}
' -p 7890
CPU ID FUNCTION:NAME
...
5 80618 kqrLockAndPinPo:entry
CID = 15 ADDR = 18F058B68
...
5 80618 kqrLockAndPinPo:entry
CID = 15 ADDR = 142020320
...
----- CID_ADDR CNT -----
CID = 15 ADDR = 18F058B68 CNT = 1
CID = 15 ADDR = 142020320 CNT = 1
...
----- CID CNT -----
CID = 11 CNT = 3
CID = 17 CNT = 3
CID = 15 CNT = 60
3.2 State Transition Diagram
Run Dtrace Script: rco_dtrace_std to draw a State Transition Diagram of latch Get (kslgetl) and Latch Free (kslfre) for each Row Cache Object GET. (Note: kslgetl is exClusive latch get, whereas ksl_get_shared_latch is Shared latch get(in S or X Mode))
Here the output for one Row Cache Object GET. It shows 3 kslgetl Calls at 3 different Locations ("where"), all are prefixed with "Transition", followed by one kslfre
(note the indented function entry and return).
Those are probably the 3 unclear "latch: row cache objects" GETs, discussed in Oracle Core: Essential Internals for DBAs and Developers Page 167. (see Blog: nls_database_parameters, dc_props, latch: row cache objects )
-> kqrpre1
---------Step 1 at 2018 Oct 18 08:50:25 (Elapsed-ns=1491587737)---------
-> kslgetl
---------Step 2 at 2018 Oct 18 08:50:25 (Elapsed-ns=104489)---------
Entry State(nproc_pid=>0x0, flag=>0x0, gets=>0x4A04F, latch=>0x19B, level=>0x4, where=>0x1171)
Transition > kslgetl:entry(Addr=>0x182D98958, Immed_Get=>1, Why=>0, Where=>4441(0x1159))
<- kslgetl
---------Step 3 at 2018 Oct 18 08:50:25 (Elapsed-ns=32606)---------
Return State(nproc_pid=>0x1B, flag=>0x0, gets=>0x4A050, latch=>0x19B, level=>0x4, where=>0x1159)
-> kqrLockAndPinPo
---------Step 4 at 2018 Oct 18 08:50:25 (Elapsed-ns=36536)---------
CID = 15 ADDR = 171999DD8
<- kqrLockAndPinPo
---------Step 5 at 2018 Oct 18 08:50:25 (Elapsed-ns=24430)---------
-> kslfre
---------Step 6 at 2018 Oct 18 08:50:25 (Elapsed-ns=8813)---------
Transition > kslfre:entry(Addr=>0x182D98958) ===Latch freed===
<- kslfre
---------Step 7 at 2018 Oct 18 08:50:25 (Elapsed-ns=14267)---------
<- kqrpre1
---------Step 8 at 2018 Oct 18 08:50:25 (Elapsed-ns=11490)---------
-> kslgetl
---------Step 9 at 2018 Oct 18 08:50:25 (Elapsed-ns=6415)---------
Entry State(nproc_pid=>0x0, flag=>0x0, gets=>0x4A050, latch=>0x19B, level=>0x4, where=>0x1159)
Transition > kslgetl:entry(Addr=>0x182D98958, Immed_Get=>1, Why=>0, Where=>4464(0x1170))
<- kslgetl
---------Step 10 at 2018 Oct 18 08:50:25 (Elapsed-ns=6092)---------
Return State(nproc_pid=>0x1B, flag=>0x0, gets=>0x4A051, latch=>0x19B, level=>0x4, where=>0x1170)
-> kslfre
---------Step 11 at 2018 Oct 18 08:50:25 (Elapsed-ns=10545)---------
Transition > kslfre:entry(Addr=>0x60164110) ===Latch freed===
<- kslfre
---------Step 12 at 2018 Oct 18 08:50:25 (Elapsed-ns=4733)---------
-> kslgetl
---------Step 13 at 2018 Oct 18 08:50:25 (Elapsed-ns=4412)---------
Entry State(nproc_pid=>0x0, flag=>0x0, gets=>0x4A051, latch=>0x19B, level=>0x4, where=>0x1170)
Transition > kslgetl:entry(Addr=>0x182D98958, Immed_Get=>1, Why=>0, Where=>4465(0x1171))
<- kslgetl
---------Step 14 at 2018 Oct 18 08:50:25 (Elapsed-ns=5110)---------
Return State(nproc_pid=>0x1B, flag=>0x0, gets=>0x4A052, latch=>0x19B, level=>0x4, where=>0x1171)
-> kslfre
---------Step 15 at 2018 Oct 18 08:50:25 (Elapsed-ns=4445)---------
Transition > kslfre:entry(Addr=>0x182D98958) ===Latch freed===
<- kslfre
Where=>4441(0x1159): kqrpre: find obj -- latch Get at 1st Location Where=>4464(0x1170): kqreqd -- latch Get at 2nd Location Where=>4465(0x1171): kqreqd: reget -- latch Get at 3rd Locationwhich can be found by sql below:
CREATE OR REPLACE FORCE VIEW X_GV$LATCH_MISSES as
SELECT t1.indx INDX,
t1.inst_id INST_ID,
t1.ksllasnam PARENT_NAME,
t2.ksllwnam "WHERE",
t1.kslnowtf NWFAIL_COUNT,
t1.kslsleep SLEEP_COUNT,
t1.kslwscwsl WTR_SLP_COUNT,
t1.kslwsclthg LONGHOLD_COUNT,
t2.ksllwnam LOCATION,
t1.con_id CON_ID
FROM x$ksllw t2, x$kslwsc t1
WHERE t2.indx = t1.indx;
select * from sys.X_GV$LATCH_MISSES
where parent_name in ('row cache objects')
and indx in (4441, 4464, 4465);
INDX PARENT_NAME WHERE NWFAIL_COUNT SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT LOCATION
----- ---------------------- ----------------------------- ------------ ----------- ------------- --------------
4441 row cache objects kqrpre: find obj 0 2 8 0 kqrpre: find obj
4464 row cache objects kqreqd 0 0 0 0 kqreqd
4465 row cache objects kqreqd: reget 0 6 0 0 kqreqd: reget
3.3 Call Stack and Call Sequence (Update 2020-Aug-03)
There are 3 latch gets, the first call is from kqrpre1 with Call Stack:
kslgetl ()
kqrpre1 ()
kkdlpftld ()
qerfxFetch ()
opifch2 ()
kslgetl ()
kqreqd ()
kqrprl ()
kkdlpftld ()
qerfxFetch ()
<kgghash>
<kslgetl> -- Where=>4441(0x1159)
<kqrCacheHit>
<kqrLockAndPinPo>
<kslfre>
<kslgetl> -- Where=>4464(0x1170)
<KGHISPIR> -- "pin recreatable"
<kghupr> -- "unpin recreatable"
<kslfre>
<kslgetl> -- Where=>4465(0x1171)
<kglFreeSO> -- "free state object"
<kslfre>
kqrpre1 : found po=0x9675c390 flg=2 hash=819e131 pso=0x9511def8 dur=CALL
4. 12cR2 10222 Trace Event
Make the same trace in Oracle 12cR2 for 3 different Levels, here the output:
4.1. Level 4
kqrpre1 : found po=0x9675c390 flg=2 hash=819e131 pso=0x9511def8 dur=CALL .
kqrpre1 : done po=0x9675c390 cid=15 flg=2 hash=819e131 0 eq=0x63dfbd98 pso=0x9511def8 dur=CALL .
kqreqd: eq: 0x63dfbd98
kqreqd freeing enqeue: eq: 0x63dfbd98
4.2. Level 255
kqrmpin : kqrpre: found po Pin po 0x9675c390 cid=15 flg=2 hash=819e131
time=1980227738
kqrpre1 : found po=0x9675c390 flg=2 hash=819e131 pso=0x9511def8 dur=CALL time=1980227746
kqrpre1 : done po=0x9675c390 cid=15 flg=2 hash=819e131 0 eq=0x63dfc580 pso=0x9511def8 dur=CALL time=1980227754
kqrprl: eq=0x63dfc580 fpInUse=FALSE
ksedsts()+346<-kqrprl()+1221<-kkdlpExecSqlCbk()+570<-kkdlpExecSql()+114<-kkdlpGet()+317<-kkdlpftld()+229<-qerfxFetch()+6519<-opifch2()+3267<-kpoal8()+3436<-opiodr()+1229<-ttcpip()+1257<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021<-sou2o()+145
<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+256.
kqreqd: eq: 0x63dfc580
kqrmupin : kqrReleaseLock Unpin po 0x9675c390 cid=15 flg=2 hash=819e131 time=1980227875
kqreqd freeing enqeue: eq: 0x63dfc580
4.3. Level 4294967295
kqrmpin : kqrpre: found po Pin po 0x9675c390 cid=15 flg=2 hash=819e131
time=1845554855
kqrpre1 : found po=0x9675c390 flg=2 hash=819e131 pso=0x9511def8 dur=CALL time=1845554916
found stack: ksedsts()+346<-kqrpre1()+4784<-kkdlpExecSqlCbk()+418<-kkdlpExecSql()+114<-kkdlpGet()+317<-kkdlpftld()+229<-qerfxFetch()+6519<-opifch2()+3267<-kpoal8()+3436<-opiodr()+1229<-ttcpip()+1257<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021
<-sou2o()+145<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+256.
kqrpre1 : done po=0x9675c390 cid=15 flg=2 hash=819e131 0 eq=0x63dfc0e0 pso=0x9511def8 dur=CALL SQL=select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET' time=1845564279
done stack: ksedsts()+346<-kqrpre1()+2566<-kkdlpExecSqlCbk()+418<-kkdlpExecSql()+114<-kkdlpGet()+317<-kkdlpftld()+229<-qerfxFetch()+6519<-opifch2()+3267<-kpoal8()+3436<-opiodr()+1229<-ttcpip()+1257<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021
<-sou2o()+145<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+256.
kqrprl: eq=0x63dfc0e0 fpInUse=FALSE
ksedsts()+346<-kqrprl()+1221<-kkdlpExecSqlCbk()+570<-kkdlpExecSql()+114<-kkdlpGet()+317<-kkdlpftld()+229<-qerfxFetch()+6519<-opifch2()+3267<-kpoal8()+3436<-opiodr()+1229<-ttcpip()+1257<-opitsk()+1940<-opiino()+941<-opiodr()+1229<-opidrv()+1021<-sou2o()+145
<-opimai_real()+455<-ssthrdmain()+417<-main()+262<-__libc_start_main()+256.
kqreqd: eq: 0x63dfc0e0
kqrmupin : kqrReleaseLock Unpin po 0x9675c390 cid=15 flg=2 hash=819e131 time=1845566287
kqreqd freeing enqeue: eq: 0x63dfc0e0
4.4. 12cR2 vs. 12cR1
Note that in Oracle 12.2.0.1.0 (12cR2), "row cache mutex" replaced 12.1.0.2.0 (12cR1) "latch: row cache objects". (See Blog: row cache mutex in Oracle 12.2.0.1.0 )
It seems that 10222 Trace event still generates similar output with more information, for example, call stacks.
Comparing the function calling sequence of Level 255 between 12cR1 and 12cR2:
12cR1: kqrpre1(found) -> kqrmpin -> kqrpre1(done) -> kqrmupin
12cR2: kqrmpin -> kqrpre1(found) -> kqrpre1(done) -> kqrmupin
5. Row Cache Internals: kqrpre1 and kqrfrpo
Pick one Row Cache Object GET from the output of above 10222 Level 4294967295, it shows that Row Cache is not able to cache it. Each time it needs to invoke "kqrpre1" (Row Cache Parent Read) to create a new DC row, use it, and then release it by "kqrfrpo : freed to heap". It took 279 us (2271264814-2271264535) for one such Read.
kqrpre1 : found po=18f058b68 flg=2 hash=5b42c02e time=2271264535
kqrmpin : kqrLockAndPinPo Pin po 18f058b68 cid=15 flg=2 hash=5b42c02e
time=2271264669
kqrpre1 : done po=18f058b68 cid=15 flg=2 hash=5b42c02e 0 eq=13fea57f8 SQL=select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET' time=2271264687
kqrmupin : kqrpspr2 Unpin po 18f058b68 cid=15 flg=2 hash=5b42c02e time=2271264704
kqrmupin : free po=18f058b68 flg=2
kqrfrpo: Free po 18f058b68
KQR Parent Cache Object:
pob = 18f058b68 flg = 00000002 cid = 15 xcb = 0 hbk = 18f05ac38
hbk=[f84f96e8,151186580]
own=18f058c38[18f058c38,18f058c38] wat=18f058c48[18f058c48,18f058c48] mod=0
kqrfrpo : freed to heap po=18f058b68 time=2271264814
6. Discussions
Row Cache is a mechanisms analogue to CPU Cache:
"CPU Cache" transfer "cache lines" between "Main Memory" and "L1 Cache". "Row Cache" transfer "DC rows" between "Buffer Cache" and "DC Cache".Row Cache is more like a "software" cache because "Row Cache" and its hidden "Buffer Cache" are in SGA memory,
whereas "CPU Cache (L1)" and its underlying "Main Memory" are located in separate hardware.
Any cache miss results in a "Main Memory/Buffer" with much longer latency. The cache hit rate plays an important role in determining the performance.
Section 3.2 State Transition Diagram showed that each Row Cache Object GET is a cache miss.
7. 10222 Trace Import and Analyse Script
drop table raw_10222_trc_ext;
create table raw_10222_trc_ext
( text1 varchar2(1000)
)
organization external
(type oracle_loader
default directory PLSHPROF_DIR
access parameters
(
records delimited by newline CHARACTERSET AL32UTF8
badfile aaa_db_io:'trc_ext.bad'
logfile aaa_db_io:'trc_ext.log'
discardfile aaa_db_io:'trc_ext.dsc'
fields terminated by ',' OPTIONALLY ENCLOSED BY '"'
missing field values are null
( text1 position(1:1000)
)
)
location ('testdb_ksun_trc_row_cache_10222_15.trc')
) reject limit unlimited;
select rownum line_nbr, text1 from raw_10222_trc_ext;
drop table import_10222_trc;
create table import_10222_trc (run number, line_nbr number, cid number, ts_us number, po_address varchar2(32),
cid_type varchar2(12), cid_subordinate# number, cid_parameter varchar2(40),
obobn number, obname varchar2(100), sql varchar2(100), raw_lines varchar2(4000));
create or replace procedure import_10222_trc_proc (p_run number, p_trc_file varchar2, p_delete_old boolean := true) as
l_line_sep varchar2(3) := '###';
l_pos_1 number;
l_pos_2 number;
l_raw_lines varchar2(32000);
l_line_nbr number := 1;
l_cid number;
l_ts_us number;
l_po_address varchar2(32000);
l_obobn number;
l_obname varchar2(32000);
l_sql varchar2(32000);
begin
-- setup trace file location
execute immediate 'alter table raw_10222_trc_ext location (''' || p_trc_file || ''')';
-- delete old RUN
if p_delete_old then
delete from import_10222_trc where run = p_run;
commit;
end if;
-- concatenate same PO lines into one line
for c in (select rownum line_nbr, text1 from raw_10222_trc_ext) loop
dbms_output.put_line('Raw line_nbr: '||c.line_nbr ||'--text1: '||c.text1);
if l_raw_lines is null then
l_raw_lines := c.text1;
else
l_raw_lines := l_raw_lines ||l_line_sep||c.text1;
end if;
if c.text1 like 'kqrpre1 : found po=%' or c.text1 like 'kqrpad: new po%' then
l_raw_lines := substr(l_raw_lines, 1, 4000);
insert into import_10222_trc(run, line_nbr, raw_lines) values(p_run, l_line_nbr, l_raw_lines);
commit;
l_line_nbr := c.line_nbr;
l_raw_lines := c.text1;
end if;
end loop;
-- insert last line
if length(l_raw_lines) > 0 then
l_raw_lines := substr(l_raw_lines, 1, 4000);
insert into import_10222_trc(run, line_nbr, raw_lines) values(p_run, l_line_nbr, l_raw_lines);
commit;
end if;
-- parse raw_lines
for c in (select line_nbr, raw_lines from import_10222_trc
where raw_lines like 'kqrpre1 : found po=%' or raw_lines like 'kqrpad: new po%') loop
dbms_output.put_line('Parsing line_nbr: '||c.line_nbr||'--text1: '||c.raw_lines);
l_cid := regexp_substr(c.raw_lines, 'cid=(\d*)', 1, 1, 'i', 1);
l_pos_1 := instr(c.raw_lines, 'time=', -1);
if l_pos_1 > 0 then
l_ts_us := regexp_substr(c.raw_lines, 'time=(\d*)', l_pos_1, 1, 'i', 1);
end if;
l_po_address := substr(upper(regexp_substr(c.raw_lines, 'po=(\S*)', 1, 1, 'i', 1)), 1, 32);
l_obobn := regexp_substr(c.raw_lines, 'obobn=(\d*)', 1, 1, 'i', 1);
l_obname := substr(regexp_substr(c.raw_lines, 'obname=(\S*)', 1, 1, 'i', 1), 1, 100);
l_pos_2 := instr(c.raw_lines, 'SQL=', 1) + 4;
if (l_pos_2 > 4) then
l_pos_1 := instr(c.raw_lines, 'time=', l_pos_2);
if l_pos_1 = 0 then l_pos_1 := l_pos_2 + 100; end if;
l_sql := substr(substr(c.raw_lines, l_pos_2, l_pos_1 - l_pos_2), 1, 100);
else
l_sql := null;
end if;
update import_10222_trc
set cid = l_cid
,ts_us = l_ts_us
,po_address = l_po_address
,obobn = l_obobn
,obname = l_obname
,sql = l_sql
where run = p_run and line_nbr = c.line_nbr;
commit;
end loop;
-- add v$rowcache info
update import_10222_trc t
set (cid_type, cid_subordinate#, cid_parameter) =
(select type, subordinate#, parameter from v$rowcache r where r.cache# = t.cid and rownum=1)
where run = p_run;
commit;
end;
/
8. Dtrace Scripts
8.1. rco_dtrace_cache
sudo dtrace -n \
'pid$target::kqrLockAndPinPo:entry /execname == "oracle"/ {
@cid_addr_cnt[arg0, arg1] = count();
@cid_cnt[arg0] = count();
@cid_cnt_total = count();
ustack(5, 0);
printf("\nCID = %-4d ADDR = %-16X\n", arg0, arg1);}
END {
/** Only first call in new opened Sqlplus has not double counting **/
printf("\n\n*************** CID Stats with Address (double counting) ****************");
printa("\nCID = %-4d ADDR = %-16X CNT = %-10@d", @cid_addr_cnt);
printf("\n*************** CID Stats ****************");
printa("\nCID = %-4d CNT = %-10@d", @cid_cnt);
printf("\n*************** CID Stats Summary ****************");
printa("\nCNT = %-10@d", @cid_cnt_total); }
' -p $1
Update (30-May-2021)
Nenad (All-round Database Topics) found that double counting user calls can be avoided by specifying the module name, like
pid$target:oracle:kqrLockAndPinPo:entry
pid$target::kqrLockAndPinPo:entry
(Note: Oracle 12.2.0.1.0 (12cR2), "row cache mutex" replaced 12.1.0.2.0 (12cR1) "latch: row cache objects". See Blog: row cache mutex in Oracle 12.2.0.1.0 )
At first we list all kqr* functions:
SQL > select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
$ sudo dtrace -n 'pid$target::kqr*:entry { @[probefunc] = count(); }' -p 25986
dtrace: description 'pid$target::kqr*:entry ' matched 310 probes
kqrAllocateEnqueue 194
kqrCacheHit 194
kqrFreeEnqueue 194
kqrGetPOMutexInt 194
kqrLockPo 194
kqrReleaseLock 194
kqreqd 194
kqrget 194
kqrhsh 194
kqrmpin 194
kqrmupin 194
kqrpre1 194
kqrpre2 194
kqrprl 194
kqrpspr 194
*Note: kqrLockAndPinPo not listed, probably it is an Oracle 12.1 function
$ sudo dtrace -l -f kqrLockPo
ID PROVIDER MODULE FUNCTION NAME
90031 pid25986 a.out kqrLockPo entry
90032 pid25986 oracle kqrLockPo entry
$ sudo dtrace -l -f kqrpre1
ID PROVIDER MODULE FUNCTION NAME
90029 pid25986 a.out kqrpre1 entry
90030 pid25986 oracle kqrpre1 entry
$ sudo dtrace -n 'pid$target:oracle:kqrpre1:entry {@[probefunc] = count();}' -p 25986
$ sudo dtrace -n 'pid$target:a.out:kqrpre1:entry {@[probefunc] = count();}' -p 25986
$ sudo dtrace -i '90029 {@[probefunc] = count();}'
$ sudo dtrace -i '90030 {@ = count(); }'
SQL >select value from nls_database_parameters where parameter = 'NLS_CHARACTERSET';
$ sudo dtrace -n 'pid$target::kqr*:entry {@[probefunc, probemod] = count();}' -p 25986
dtrace: description 'pid$target::kqr*:entry ' matched 310 probes
kqrAllocateEnqueue a.out 97
kqrAllocateEnqueue oracle 97
......
kqrpre1 a.out 97
kqrpre1 oracle 97
......
kqrpspr a.out 97
kqrpspr oracle 97
8.2. rco_dtrace_latch
sudo dtrace -F -n \
'
BEGIN {roread = 0; step = 1; self->func = "ne"; self->name = "na"; prev_ts = timestamp;}
pid$target::kqrpre1:entry /execname == "oracle" && self->func != probefunc / {roread = 1;
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
@cnt[probefunc] = count();}
pid$target::kqrpre1:return /roread ==1/ {roread = 0;
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
pid$target::kslgetl:entry /step > 1 && self->func != probefunc / {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
@cnt[probefunc] = count();}
pid$target::kslgetl:return /self->func == probefunc && self->name != probename/{
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
pid$target::kslfre:entry /step > 1 && self->func != probefunc / {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
@cnt[probefunc] = count();}
pid$target::kslfre:return /self->func == probefunc && self->name != probename/{
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
pid$target::kqrLockAndPinPo:entry /step > 1 && self->func != probefunc / {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
@cnt[probefunc] = count();}
pid$target::kqrLockAndPinPo:return /self->func == probefunc && self->name != probename/{
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
' -p $1
8.3. rco_dtrace_std (@TODO improve it)
sudo dtrace -F -n \
'
typedef unsigned int ub4;
typedef struct latchstate /* latch state */ {
ub4 nproc_pid; /* Nproc or pid */
ub4 flag; /* blocking flag */
ub4 gets; /* number of gets */
ub4 latch; /* latch number */
ub4 level; /* latch level */
ub4 where; } latchstate;
BEGIN {step = 1; self->func = "na"; self->name = "na"; prev_ts = timestamp;}
pid$target::kqrpre1:entry /execname == "oracle" && self->func != probefunc / {self->roread = 1;
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
@cnt_func[probefunc] = count();}
pid$target::kqrpre1:return /self->roread ==1/ {self->roread = 0;
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = "na"; self->name = probename; step = step + 1; prev_ts = timestamp;}
pid$target::kslgetl:entry /step > 1 && self->func != probefunc / {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
@cnt_func[probefunc] = count();
ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
printf("\n Entry State(nproc_pid=>0x%X, flag=>0x%X, gets=>0x%X, latch=>0x%X, level=>0x%X, where=>0x%X)"
,ls->nproc_pid, ls->flag, ls->gets, ls->latch, ls->level, ls->where);
printf("\n Transition > %s:%s(Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X))",
probefunc, probename, arg0, arg1, arg2, arg3, arg3);
self->addr = arg0; self->loc = arg3;}
pid$target::kslgetl:return /self->func == probefunc && self->name != probename/{
@sum[self->addr, self->loc] = sum(timestamp - prev_ts);
@avg[self->addr, self->loc] = avg(timestamp - prev_ts);
@max[self->addr, self->loc] = max(timestamp - prev_ts);
@cnt[self->addr, self->loc] = count();
@sum_total = sum(timestamp - prev_ts);
@cnt_total = count();
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
ls = ((latchstate *) copyin(self->addr, sizeof(latchstate)));
printf("\n Return State(nproc_pid=>0x%X, flag=>0x%X, gets=>0x%X, latch=>0x%X, level=>0x%X, where=>0x%X)"
,ls->nproc_pid, ls->flag, ls->gets, ls->latch, ls->level, ls->where);}
pid$target::kslfre:entry /step > 1 && self->func != probefunc / {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
@cnt_func[probefunc] = count();
printf("\n Transition > %s:%s(Addr=>0x%-X) ===Latch freed===", probefunc, probename, arg0);}
pid$target::kslfre:return /self->func == probefunc && self->name != probename/{
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
pid$target::kqrLockAndPinPo:entry /step > 1 && self->func != probefunc / {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;
@cnt_func[probefunc] = count();
@cid_addr_cnt[arg0, arg1] = count();
@cid_cnt[arg0] = count();
@cid_cnt_total = count();
printf("\n CID = %-4d ADDR = %-16X", arg0, arg1);}
pid$target::kqrLockAndPinPo:return /self->func == probefunc && self->name != probename/{
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
self->func = probefunc; self->name = probename; step = step + 1; prev_ts = timestamp;}
END {
trunc(@sum, 10); trunc(@avg, 10); trunc(@max, 10); trunc(@cnt, 10);
printf("\n\n*************** Latch Stats (time in ns) ****************");
printf("\nAddr Where");
printa("\n0x%-10X %6d sum = %10@d", @sum); printf("\n----------------------");
printa("\n0x%-10X %6d avg = %10@d", @avg); printf("\n----------------------");
printa("\n0x%-10X %6d max = %10@d", @max); printf("\n----------------------");
printa("\n0x%-10X %6d cnt = %10@d", @cnt); printf("\n----------------------");
printa("\nsum_total = %10@d", @sum_total);
printa("\ncnt_total = %10@d", @cnt_total);
/** @TODO not exact **/
printf("\n\n*************** CID Stats with Address ****************");
printa("\nCID = %-4d ADDR = %-16X CNT = %-10@d", @cid_addr_cnt);
printf("\n*************** CID Stats ****************");
printa("\nCID = %-4d CNT = %-10@d", @cid_cnt);
printf("\n*************** CID Stats Summary ****************");
printa("\nCNT = %-10@d", @cid_cnt_total);
printf("\n\n*************** probefunc Stats ****************");
printa("\n%-20s cnt = %10@d", @cnt_func);}
' -p $1
