SQL(64) > select * from v$sgastat where name like '%Result Cache%';
POOL NAME BYTES
------------ -------------------------- ----------
shared pool Result Cache: Cache Mgr 256
shared pool Result Cache: Memory Mgr 208
shared pool Result Cache: State Objs 69920
shared pool Result Cache 159880
SQL(854) > select * from v$latch where name = 'Result Cache: RC Latch';
1. Build
Run:
SQL(64) > exec dbms_result_cache.flush;
SQL(64) > exec run_test;
select scn_to_timestamp(scn) scn_time, ro.*
from v$result_cache_objects ro
where 1=1
-- and type = 'Dependency'
-- and status = 'Invalid'
order by scn_time, scn;
select count(*) from v$result_cache_dependency;
COUNT(*)
---------
51
select distinct
from_obj.name from_name, from_obj.type, from_obj.status, from_obj.namespace,
from_obj.scn, scn_to_timestamp(from_obj.scn) scn_time,
to_obj.name to_name, to_obj.type to_type, to_obj.status to_status, to_obj.namespace to_namespace,
to_obj.scn to_scn, scn_to_timestamp(to_obj.scn) to_scn_time
from v$result_cache_objects from_obj,
v$result_cache_dependency dep,
v$result_cache_objects to_obj
where from_obj.id = dep.result_id
and to_obj.id = dep.depend_id
-- and to_obj.name in ('K.RC_TAB_DEP', 'K.RC_TAB')
-- and from_obj.name like '%"K"."%GET_VAL"%'
order by from_obj.scn;
2. Invalidate
SQL(64) > update rc_tab_dep set dval=33 where did = 3;
SQL(64) > select s.sid, t.used_urec from v$transaction t, v$session s
where t.ses_addr=s.saddr and s.sid=sys.dbms_support.mysid;
SID USED_UREC
---- ----------
64 1
SQL(64) > select * from v$result_cache_statistics
where lower(name) like '%invalid%';
ID NAME VALUE
--- ---------------------- -----
8 Invalidation Count 0
9 Delete Count Invalid 0
SQL(64) > select count(*) from v$result_cache_dependency;
COUNT(*)
---------
51
SQL(64) > commit;
SQL(64) > select * from v$result_cache_statistics
where lower(name) like '%invalid%';
ID NAME VALUE
--- ---------------------- -----
8 Invalidation Count 17
9 Delete Count Invalid 0
SQL(64) > select count(*) from v$result_cache_dependency;
COUNT(*)
---------
0
3. Invalidate: select for update
Rebuild Cache, and then run a "select for update" for one row:
SQL(64) > exec dbms_result_cache.flush;
SQL(64) > exec run_test;
SQL(64) > select * from rc_tab_dep where did = 3 for update;
SQL(64) > select s.sid, t.used_urec from v$transaction t, v$session s
where t.ses_addr=s.saddr and s.sid=sys.dbms_support.mysid;
SID USED_UREC
---- ----------
64 1
$ dtrace -w -n 'pid$target::qesrcRO_Invalidate:entry {@[pid, ustack(10, 0)] = count(); stop(); exit(0);}' -p 13699
SQL(64) > commit;
Solaris window prints out Stack Trace:
oracle`qesrcRO_Invalidate
oracle`qesrcDO_Invalidate+0x9c8
oracle`qesrcCM_PreCmt_+0xd81
oracle`ktcCommitTxn_new+0x2a7
oracle`ktcCommitTxn+0x59
oracle`ktdcmt+0x8b
oracle`k2lcom+0x94
oracle`k2send+0x4f3
oracle`xctctl+0x62
oracle`xctCommitTxn+0x2b8
SQL(512) > exec run_test_2;
-- spid 10502 of test session (SID 512), check callstack:
$ pstack 10502
fffffd7ffc9d3e3b semsys (2, c00000f, fffffd7fffdf4968, 1, d0)
0000000001ab90f5 sskgpwwait () + 1e5
0000000001ab8c95 skgpwwait () + c5
0000000001ab7ab0 kslgess () + 980
0000000001ab6cef ksl_get_shared_latch () + 39f
0000000005ab76ab qesrcPin_Get () + 8cb
0000000005aa8ff4 qesrcCM_Acquire () + 354
000000000bd2287d psdfrcLookup () + 12d
000000000e001883 pevm_ENTERX () + 143
000000000dfc2907 pfrinstr_ENTERX () + 47
0000000001a435ca pfrrun_no_tool () + 12a
$ ipcs -as
T ID KEY MODE OWNER GROUP CREATOR CGROUP NSEMS OTIME CTIME
Semaphores:
s 201326607 0x375d691c --ra-r----- oracle dba oracle dba 704 13:14:45 15:52:33
We can see:
semid = 201326607 = 0xc00000f
and "0xc00000f" is
semsys (2, c00000f, fffffd7fffdf4968, 1, d0)
in pstack output, and 2 is semop defined in syscall.h:
semop (...) :: semsys(2, ...)
int semop(int semid, struct sembuf *sops, size_t nsops);
If we truss the blocking session, we can also see the same semid with semnum begin 34 and 16.
One thing we noticed is that truss de-blocks (unlock) the blocking session (like prun).
$ truss -dp 13699
/1: 833.5393 semctl(201326607, 34, SETVAL, 1) = 0
/1: 833.5395 semctl(201326607, 16, SETVAL, 1) = 0
/1: 833.5395 lwp_info(0xFFFFFD7FFFDF7440) = 0
It hangs on Result Cache: RC Latch.
On a third SQL Window, watch the blocking:
SQL(1024) > select sid, blocker_sid, blocker_is_valid, wait_event_text, p2 from v$wait_chains;
SID BLOCKER_SID BLOCK WAIT_EVENT_TEXT P2
----- ----------- ----- --------------- -----
512 64 TRUE latch free 559
64 FALSE
SQL(1024) > select * from v$latchholder;
PID SID LADDR NAME GETS
---- ---- ---------------- ---------------------- --------
25 64 00000000600572B0 Result Cache: RC Latch 15564353
SQL(768) > select * from rc_tab_dep where did = 5 for update;
DID DVAL
---------- ----------
5 50
1 row selected.
SQL(768) > commit;
And all other sessions which are accessing or updating Result Cache are waiting for the same latch free (ksl_get_shared_latch).
In this test, we started one transaction by "select for update", but did not update any row, however, "commit" triggered a call to "qesrcRO_Invalidate", hence held "RC Latch". Any other later session which requires this latch is waiting for "latch free".
Furthermore, query on any one of
v$result_cache_objects
v$result_cache_dependency
v$result_cache_statistics
is also pending on "RC Latch" "latch free".
The above Stack Trace shows that when a transaction user session calls commit command, commit takes a detour to visit Result Cache along its code path in order to perform the invalidation before publishing the confirmed and consistent news to the world. Therefore, Function Result Cache is not free of charge. It demands the resources to maintain the database wide consistence, and thus PL/SQL Function Result Cache (in Oracle Database PL/SQL Language Reference) said:
Oracle Database automatically detects all data sources (tables and views) that are queried while a result-cached function is running. If changes to any of these data sources are committed, the cached result becomes invalid and must be recomputed. The best candidates for result-caching are functions that are invoked frequently but depend on information that changes infrequently or never.
This behavior of "SELECT FOR UPDATE" is described in Oracle MOS
Bug 17855824 : PLSQL RESULT CACHE WRONGLY INVALIDATED BY A SELECT FOR UPDATE STATEMENT
4. RC Latch "ksl_get_shared_latch" tracing
For each RC Latch Get, the call stack looks like:
0000000001ab696b ksl_get_shared_latch () + 1b
0000000005ab76ab qesrcPin_Get () + 8cb
0000000005aa8ff4 qesrcCM_Acquire () + 354
000000000bd2287d psdfrcLookup () + 12d
000000000e001883 pevm_ENTERX () + 143
In case of Latch Miss, the process yields the CPU and goes to sleep:
fffffd7ffc9d396a yield () + a
0000000005ab78d6 qesrcPin_Get () + af6
0000000005aa8ff4 qesrcCM_Acquire () + 354
000000000bd2287d psdfrcLookup () + 12d
000000000e001883 pevm_ENTERX () + 143
Run the same test, and measure Latch Get time in qesrcCM_Acquire (CM: Cache Manager) by dtrace:
SQL > exec run_test;
$ dtrace -n \
'BEGIN {self->start_wts = walltimestamp; self->start_ts = timestamp;}
pid$target::qesrcCM_Acquire:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry /execname == "oracle" && self->rc == 1/ { self->ts = timestamp; }
pid$target::ksl_get_shared_latch:return /self->ts > 0/ {
@lquant["ns"] = lquantize(timestamp - self->ts, 0, 10000, 1000);
@avgs["AVG_ns"] = avg(timestamp - self->ts);
@mins["MIN_ns"] = min(timestamp - self->ts);
@maxs["MAX_ns"] = max(timestamp - self->ts);
@sums["SUM_ms"] = sum((timestamp - self->ts)/1000000);
@counts[ustack(10, 0)] = count();
self->rc = 0; self->ts = 0;}
END { printf("Start: %Y, End: %Y, Elapsed_ms: %d\n", self->start_wts, walltimestamp, (timestamp - self->start_ts)/1000000);}
' -p 13699
Start: 2017 Sep 4 14:54:02, End: 2017 Sep 4 14:54:06, Elapsed_ms: 3939
ns
value ------------- Distribution ------------- count
0 | 0
1000 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15
2000 |@@ 1
3000 | 0
4000 | 0
5000 | 0
6000 |@@ 1
7000 | 0
AVG_ns 1605
MIN_ns 1140
MAX_ns 6891
SUM_ms 0
oracle`ksl_get_shared_latch+0x17a
oracle`qesrcCM_Acquire+0x34b
oracle`psdfrcLookup+0x119
oracle`pevm_ENTERX+0x142
oracle`pfrinstr_ENTERX+0x3e
oracle`pfrrun_no_tool+0xc2
oracle`pfrrun+0x4a2
oracle`plsql_run+0x278
oracle`peicnt+0x14d
oracle`kkxexe+0x205
17
5. Causal Analysis of Result Cache
V$RESULT_CACHE_OBJECTS provides 4 time related columns:
(a). CREATION_TIMESTAMP:
Time when the object was first time created in Result Cache, and never changed for both TYPE: Result and Dependency.
(b). SCN:
For TYPE = Result, it is the SCN of first time created in Result Cache, same as CREATION_TIMESTAMP;
Its STATUS is 'Published' if valid; 'Invalid' if invalidated (for example, due to Dependency).
Its OBJECT_NO is always 0.
For TYPE = Dependency, when first time inserted, it is the SCN of time created in Result Cache, same as CREATION_TIMESTAMP.
Its STATUS is always 'Published', never 'Invalid'. Therefore for Dependency, there is no 'Invalid'.
Once changed, it is the last Commit SCN (Getting Oracle Transaction Commit SCN).
SCN timestamp minus CREATION_TIMESTAMP gives us the time span from time Created to time Changed.
Any existence of this time difference indicates the Change of Dependency,
hence it can be used to track Result Invalidation caused by its Dependencies.
Its OBJECT_NO is Dictionary object number (DBA_OBJECTS.object_id).
(c). LRU_NUMBER and SCAN_COUNT:
LRU list position, the bigger the value, the more recent the usage.
(Oracle Docu wrote "the smaller the value, the more recent the usage". It seems not the case.)
LRU_NUMBER is monotonic and increases one for each access of Result Cache.
To maintain this ordering, LRU_NUMBERs are shifted by increasing 1 to reflect RC access.
It is not clear if there exist multiple LRU Chains because each LRU_NUMBER can have multiple rows.
(select lru_number, count(*) from v$result_cache_objects where lru_number > 0 group by lru_number order by 2 desc;)
Following test shows that SCAN_COUNT is the number of calls for one Result Cache item;
LRU_NUMBER is the total number of calls over entire Result Cache.
create or replace function test_scan_lru (p_id number) return number result_cache as
begin
return p_id;
end;
/
exec dbms_result_cache.flush;
select name, scan_count, lru_number
from v$result_cache_objects
where type = 'Result' and name like '%TEST_SCAN_LRU%';
-- no rows selected
declare
l_ret number;
begin
for i in 1..1e6 loop
l_ret := test_scan_lru(123);
end loop;
end;
/
select name, scan_count, lru_number
from v$result_cache_objects
where type = 'Result' and name like '%TEST_SCAN_LRU%';
-- NAME SCAN_COUNT LRU_NUMBER
-- ---- ---------------------------------------------- ------------ ------------
-- "S". "GET_VAL_3"::8."GET_VAL_3"#3048d2af80817a01 #1 999,999 48,007,056
declare
l_ret number;
begin
for i in 1..1e6 loop
l_ret := test_scan_lru(123);
end loop;
end;
/
select name, scan_count, lru_number
from v$result_cache_objects
where type = 'Result' and name like '%TEST_SCAN_LRU%';
-- NAME SCAN_COUNT LRU_NUMBER
-- -------------------------------------------------- ------------ ------------
-- "S"."GET_VAL_3"::8."GET_VAL_3"#3048d2af80817a01 #1 1,999,999 49,007,056
-- Last invalidated Dependencies
select * from rc_scn_view;
-- last invalidated Dependencies and Result
select * from rc_scn_dep_view;
-- RC usage
select * from rc_lru_number_view;
-- RC memory
select * from rc_memory_view;
-- RC stats
select * from rc_stats_view;
6. Result Cache: RC Latch S mode and X mode Blocking Chains
We will make S mode and X mode blocking test based on the calling API revealed in Blog Oracle 12 and latches:
The kslgetl and ksl_get_shared_latch functions take the following arguments:
1-latch address
2-immediate get (0 means yes, 1 means no)
3-where (X$KSLLW.INDX)
4-why (X$KSLWSC.INDX)
5-mode (8=shared,16=exclusive; only for ksl_get_shared_latch function)
The above text needs two corrections. We will have a look later.
(1). arguments why (arg2) comes before where(arg3)
(2). X$KSLLW.INDX and X$KSLWSC.INDX are the same (equal join columns), both point to the where (location).
X$KSLLW is parent table, X$KSLWSC is child table.
If Mode=16, arg5 is 20000000 00000000 | <PID>.It seems that Oracle calls different subroutines for different Latches. ksl_get_shared_latch is C subroutine to get shared Latch (in S Mode or X Mode), for example, result_cache Latch; whereas kslgetl is used to get exclusive Latch, for example, row cache objects Latch.
Following documents have a deep investigation of Latches and Mutexes:
New features of Latches and Mutexes in Oracle 12c
[Oracle] Researching internal latch implementation (ksl_get_shared_latch, kslfre, kslgetsl_w) and crashing PMON
The missing argument of ksl_get_shared_latch : the power of disassembly in action
6.1. S mode Blocking
--------------------- Setup ---------------------
create or replace function rc_s_x_mode_blocking_func (p_x number) return number result_cache as
begin
return p_x;
end;
/
create or replace procedure rc_s_x_mode_blocking_proc (p_x number) as
l_x number;
begin
l_x := rc_s_x_mode_blocking_func(p_x);
end;
/
--------------------- Prepare Test ---------------------
-- Open 3 Test Sessions (SID): S1(4335), S2(6122), S3(7497) with Process (SPID): P1(6114), P2(26548), P3(26550);
-- and one monitoring Sessions (SID): S4.
-- S1 and S2 request S Mode to get already built Items, where S3 requests X Mode to add a new Item.
-- Build 2 Items in Result Cache.
SQL (S4) > exec dbms_result_cache.flush;
SQL (S4) > exec rc_s_x_mode_blocking_proc(1);
SQL (S4) > exec rc_s_x_mode_blocking_proc(2);
--------------------- Test Steps ---------------------
--==== @T1: S1 requets S Mode, stop at Return (stop at Entry has no blocking). Launch Dtrace at first, then run plsql.
SQL (S1)> exec rc_s_x_mode_blocking_proc(1);
P1$ sudo dtrace -w -n \
'pid$target::qesrcCM*:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry /execname == "oracle" && self->rc == 1 && arg4 == 8 / {
printf("\n--------Calling %s:%s(Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X)",
probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
self->rc = 2;}
pid$target::ksl_get_shared_latch:return /self->rc == 2/ {
printf("\n--------Stopped at %s:%s", probefunc, probename);
printf("\n--------ustack(5, 0)--------"); ustack(5, 0);
stop(); exit(0);}
' -p 6114
CPU ID FUNCTION:NAME
1 80660 ksl_get_shared_latch:entry
--------Calling ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>8, PID=>0x1)
1 80661 ksl_get_shared_latch:return
--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
oracle`ksl_get_shared_latch+0x1b8
oracle`qesrcCM_Acquire+0x354
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
oracle`pfrinstr_ENTERX+0x47
-- oradebug peek RC Latch address
SQL> oradebug setmypid
Statement processed.
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000001 00000000 0C56FEFC 0000022F 00000002 000014EE
Nproc ˆX flag gets latch# level# where
SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
ADDR GETS MISSES SLEEPS IMMEDIATE_GETS SPIN_GETS WAIT_TIME
---------------- --------- ------- ------ -------------- --------- ----------
00000000600572B0 207027964 1011584 508174 0 797961 4975709595
SQL (S4)> select * from v$latchholder;
PID SID LADDR NAME GETS
---- ---- ---------------- ---------------------- ---------
33 4335 00000000600572B0 Result Cache: RC Latch 207027964
--==== @T2: S2 requets S Mode, not blocked
SQL (S2)> exec rc_s_x_mode_blocking_proc(2);
SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
ADDR GETS MISSES SLEEPS IMMEDIATE_GETS SPIN_GETS WAIT_TIME
---------------- --------- ------- ------ -------------- --------- ----------
00000000600572B0 207027965 1011584 508174 0 797961 4975709595
SQL (S4)> select * from v$latchholder;
PID SID LADDR NAME GETS
---- ---- ---------------- ---------------------- ---------
33 4335 00000000600572B0 Result Cache: RC Latch 207027965
--==== @T3: S3 requets X Mode Request, blocked by S1, Wait: latch free. Launch Dtrace at first, then run plsql.
SQL (S3)> exec rc_s_x_mode_blocking_proc(3);
P3$ sudo dtrace -n \
'pid$target::qesrcCM*:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry /execname == "oracle" && self->rc == 1 && arg4 == 16 / {
printf("\n--------Calling %s:%s(Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X))",
probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
printf("\n--------ustack(5, 0)--------"); ustack(5, 0); self->rc = 0;}
' -p 26550
CPU ID FUNCTION:NAME
1 80816 ksl_get_shared_latch:entry
--------Calling ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5347(0x14E3), Mode=>16, PID=>0x2000000000000023))
--------ustack(5, 0)--------
oracle`ksl_get_shared_latch
oracle`qesrcCM_AddDO_+0x43b5
oracle`qesrcCM_AddDO+0xf3
oracle`qesrcCM_Acquire+0x702
oracle`psdfrcLookup+0x12d
-- oradebug peek RC Latch address
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000001 40000000 0C56FEFE 0000022F 00000002 000014EE
Nproc ˆX flag gets latch# level# where
--******** S3 stopped here, resumed when S1 is set run ********--
1 80816 ksl_get_shared_latch:entry
--------Calling ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>16, PID=>0x2000000000000023))
--------ustack(5, 0)--------
oracle`ksl_get_shared_latch
oracle`qesrcPin_Get+0x959
oracle`qesrcCM_Acquire+0x354
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
1 80816 ksl_get_shared_latch:entry
--------Calling ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5374(0x14FE), Mode=>16, PID=>0x2000000000000023))
--------ustack(5, 0)--------
oracle`ksl_get_shared_latch
oracle`qesrcCM_Release+0x293
oracle`psdfrcWriteResult+0x213
oracle`pevm_RET+0x3d9
oracle`pfrinstr_RET+0x26
P4$ pstack 26550
------------ lwp# 1 / thread# 1 ---------------
ffff80ffbdba36eb semsys (2, 33, ffff80ffbfff2f68, 1, 29d)
000000000578adc5 sskgpwwait () + 1e5
000000000578a965 skgpwwait () + c5
000000000578972d kslgess () + 92d
00000000057889bf ksl_get_shared_latch () + 39f
00000000097a4145 qesrcCM_AddDO_ () + 43b5
00000000097a4d03 qesrcCM_AddDO () + f3
00000000097aa772 qesrcCM_Acquire () + 702
000000000fa4e10d psdfrcLookup () + 12d
0000000011d2e163 pevm_ENTERX () + 143
SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
ADDR GETS MISSES SLEEPS IMMEDIATE_GETS SPIN_GETS WAIT_TIME
---------------- --------- ------- ------ -------------- --------- ----------
00000000600572B0 207027966 1011584 508174 0 797961 4975709595
SQL (S4)> select * from v$latchholder;
PID SID LADDR NAME GETS
---- ---- ---------------- ---------------------- ---------
33 4335 00000000600572B0 Result Cache: RC Latch 207027966
SQL (S4)> select sid, blocker_sid, blocker_is_valid, chain_signature, in_wait wait_event_text, p1, p2, p3, in_wait_secs, num_waiters from v$wait_chains;
SID OSID BLOCKER_SID BLOCKER_OSID BLOCKER_IS_VALID CHAIN_SIGNATURE IN_WAIT WAIT_EVENT_TEXT P1 P2 P3 IN_WAIT_SECS NUM_WAITERS
---- ----- ----------- ------------ ---------------- ----------------------------- ------- --------------- ---------- --- -- ------------ -----------
4335 6114 FALSE <='latch free' FALSE 1
7497 26550 4335 6114 TRUE <='latch free' TRUE latch free 1610969776 559 0 406 0
--==== @T4: S2 requets S Mode again, blocked by S1. Wait Event: latch free. But the real Blocking is caused by S3.
SQL (S2)> exec rc_s_x_mode_blocking_proc(2);
P2$ pstack 26548
ffff80ffbdba36eb semsys (2, 33, ffff80ffbfff3948, 1, 11d)
000000000578adc5 sskgpwwait () + 1e5
000000000578a965 skgpwwait () + c5
000000000578972d kslgess () + 92d
00000000057889bf ksl_get_shared_latch () + 39f
00000000097b8a7b qesrcPin_Get () + 8cb
00000000097aa3c4 qesrcCM_Acquire () + 354
000000000fa4e10d psdfrcLookup () + 12d
0000000011d2e163 pevm_ENTERX () + 143
SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
ADDR GETS MISSES SLEEPS IMMEDIATE_GETS SPIN_GETS WAIT_TIME
---------------- --------- ------- ------ -------------- --------- ----------
00000000600572B0 207027966 1011584 508174 0 797961 4975709595
SQL (S4)> select * from v$latchholder;
PID SID LADDR NAME GETS
---- ---- ---------------- ---------------------- ---------
33 4335 00000000600572B0 Result Cache: RC Latch 207027966
SQL (S4)> select sid, osid, blocker_sid, blocker_osid, blocker_is_valid, chain_signature, in_wait, wait_event_text, p1, p2, p3, in_wait_secs, num_waiters from v$wait_chains;
SID OSID BLOCKER_SID BLOCKER_OSID BLOCKER_IS_VALID CHAIN_SIGNATURE IN_WAIT WAIT_EVENT_TEXT P1 P2 P3 IN_WAIT_SECS NUM_WAITERS
---- ----- ----------- ------------ ---------------- ----------------------------- ------- --------------- ---------- --- -- ------------ -----------
4335 6114 FALSE <='latch free' FALSE 2
7497 26550 4335 6114 TRUE <='latch free' TRUE latch free 1610969776 559 0 1403 0
6122 26548 4335 6114 TRUE <='latch free' TRUE latch free 1610969776 559 0 803 0
--==== @T5: resumne S1 running
P1$ prun 6114
SQL (S4)> select addr, gets, misses, sleeps, immediate_gets, spin_gets, wait_time from v$latch where latch# in (559) or name in ('Result Cache: RC Latch');
ADDR GETS MISSES SLEEPS IMMEDIATE_GETS SPIN_GETS WAIT_TIME
---------------- --------- ------- ------ -------------- --------- ----------
00000000600572B0 207027970 1011586 508177 0 797961 6975739595
Probably this is the behaviour pointed out in Presentation: New features of Latches and Mutexes in Oracle 12c (Andrey Nikolaev) Page 28:
If the latch is being held in S mode, the X mode waiter will block all further requests.
At T2, V$LATCHHOLDER shows S1 is a RC Latch Holder, but there are not yet any blocked sessions. So the existence of Latch Holder does not necessarily mean blockings.
From T3 (or T4) to T5, V$LATCH shows there are 4 (207027970-207027966) Gets, 2 (1011586-1011584) Misses, 3 (508177-508174) Sleeps. Among them,
S3 made 3 X Mode (16) Gets, 1 Miss and 2 Sleeps.
S2 made 1 S Mode (8) Get, 1 Miss and 1 Sleep.
S3 made 3 X Mode Gets for:
qesrcCM_AddDO
qesrcCM_Acquire
psdfrcWriteResult
It also demonstrated that 1 Miss can provoke more Sleeps.
If we expand GV$LATCH_MISSES definition by adding column: INDX:
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 ('Result Cache: RC Latch')
and indx in (5347, 5358, 5374, 5359);
INDX INST_ID PARENT_NAME WHERE NWFAIL_COUNT SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT LOCATION
----- ------- ---------------------- ----------------------------- ------------ ----------- ------------- -------------- -----------------------------
5347 1 Result Cache: RC Latch Result Cache: Serialization01 0 9633 119281 712 Result Cache: Serialization01
5358 1 Result Cache: RC Latch Result Cache: Serialization12 0 1303643 1036967 79711 Result Cache: Serialization12
5359 1 Result Cache: RC Latch Result Cache: Serialization13 0 1776 116077 176 Result Cache: Serialization13
5374 1 Result Cache: RC Latch Result Cache: Serialization28 0 2300 53438 474 Result Cache: Serialization28
In AWR Section: Latch Miss Sources, only gv$latch_misses (nwfail_count, sleep_count, wtr_slp_count) are visible. Unfortunately longhold_count is not reported, but longhold_count often signifies the X Mode Requests, which caused RC Latch longhold.
oradebug peek shows S Mode Blocking state transition. Flag 40000000 denotes S Mode Blocking.
--==== @T1: S1 requets S Mode. Get RC item at 1st Session, then Stop
[0600572B0, 0600572C8) = 00000001 00000000 0C56FEFC 0000022F 00000002 000014EE
Nproc ˆX flag gets latch# level# where
--==== @T3: S3 requets X Mode Request. Add RC item at 3rd Session, blocked
[0600572B0, 0600572C8) = 00000001 40000000 0C56FEFE 0000022F 00000002 000014EE
Nproc ˆX flag gets latch# level# where
SQL> oradebug peek 0x0700000000055978 24;
SQL> [700000000055978, 700000000055990) = 00000000 00000001 0D298B4B 022F0000 00000002 000014EE
SQL> [700000000055978, 700000000055990) = 40000000 00000001 0D298B4F 022F0000 00000002 000014EE
SQL> [700000000055978, 700000000055990) = 40000000 00000000 0D298B50 022F0000 00000002 000014EE
ˆX flag Nproc gets latch# level# where
SQL> [700000000055978, 700000000055990) = 20000000 00000058 0D2984B2 022F0000 00000002 000014FE
ˆX flag pidˆ gets latch# level# where
6.2. X mode Blocking
The approach we picked out to study Oracle RC Latch activity is trying to depict its State-Transition Diagrams.
dtrace to show Transition Event (Call Stack), paused to view State. oradebug Peek to display State. prun to resume Transition.
--------------------- Test X Mode Blocking ---------------------
-- Open 2 Solaris Windows, and one Sqlplus session.
-- In first Solaris Windows, run dtrace; in second Solaris Windows, run oradebug and host prun.
-- Launch Dtrace at first, then run plsql.
SQL > exec rc_s_x_mode_blocking_proc(6);
sudo dtrace -w -n \
'BEGIN {self->seq = 1; }
pid$target::qesrcCM*:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry / self->rc > 0 && arg0 == 0x600572B0 && (arg4 == 8 || arg4 == 16) / {
printf("\nStep %d at %Y--------Calling %s:%s(Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X)",
self->seq, walltimestamp, probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
self->rc = 2; self->seq = self->seq + 1; }
pid$target::ksl_get_shared_latch:return /self->rc > 1/ {
printf("\nStep %d at %Y--------Stopped at %s:%s", self->seq, walltimestamp, probefunc, probename);
printf("\n--------ustack(5, 0)--------"); ustack(5, 0); self->seq = self->seq + 1;
stop();}
pid$target::kslfre:entry /self->rc > 1 && arg0 == 0x600572B0/ {
printf("\nStep %d at %Y--------Stopped at %s:%s(Addr=>0x%-X)", self->seq, walltimestamp, probefunc, probename, arg0);
printf("\n--------ustack(5, 0)--------"); ustack(5, 0); self->seq = self->seq + 1; self->rc = 3;
stop();}
pid$target::kslfre:return /self->rc == 3/ {
printf("\nStep %d at %Y--------Stopped at %s:%s(Addr=>0x%-X)", self->seq, walltimestamp, probefunc, probename, arg0);
printf("\n--------ustack(5, 0)--------"); ustack(5, 0); self->seq = self->seq + 1; self->rc = 2;
stop();}
' -p 24559
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000000 00000000 84BD178B 0000022F 00000002 000014FE
SQL> host prun 24559
dtrace: allowing destructive actions
CPU ID FUNCTION:NAME
1 81838 ksl_get_shared_latch:entry
Step 1 at 2017 Sep 21 12:04:56--------Calling ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>8, PID=>0x1)
1 81839 ksl_get_shared_latch:return
Step 3 at 2017 Sep 21 12:04:56--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
oracle`ksl_get_shared_latch+0x1b8
oracle`qesrcCM_Acquire+0x354
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
oracle`pfrinstr_ENTERX+0x47
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000001 00000000 84BD178C 0000022F 00000002 000014EE
SQL> host prun 24559
1 81838 ksl_get_shared_latch:entry
Step 5 at 2017 Sep 21 12:06:05--------Calling ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5347(0x14E3), Mode=>16, PID=>0x2000000000000023)
1 81839 ksl_get_shared_latch:return
Step 7 at 2017 Sep 21 12:06:05--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
oracle`ksl_get_shared_latch+0x1b8
oracle`qesrcCM_AddDO+0xf3
oracle`qesrcCM_Acquire+0x702
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000023 20000000 84BD178D 0000022F 00000002 000014E3
SQL> host prun 24559
1 81838 ksl_get_shared_latch:entry
Step 9 at 2017 Sep 21 12:08:07--------Calling ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>16, PID=>0x2000000000000023)
1 81839 ksl_get_shared_latch:return
Step 11 at 2017 Sep 21 12:08:07--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
oracle`ksl_get_shared_latch+0x1b8
oracle`qesrcCM_Acquire+0x354
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
oracle`pfrinstr_ENTERX+0x47
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000023 20000000 84BD178E 0000022F 00000002 000014EE
SQL> host prun 24559
1 81838 ksl_get_shared_latch:entry
Step 13 at 2017 Sep 21 12:08:51--------Calling ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5374(0x14FE), Mode=>16, PID=>0x2000000000000023)
1 81839 ksl_get_shared_latch:return
Step 15 at 2017 Sep 21 12:08:51--------Stopped at ksl_get_shared_latch:return
--------ustack(5, 0)--------
oracle`ksl_get_shared_latch+0x1b8
oracle`psdfrcWriteResult+0x213
oracle`pevm_RET+0x3d9
oracle`pfrinstr_RET+0x26
oracle`pfrrun_no_tool+0x12a
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000023 20000000 84BD178F 0000022F 00000002 000014FE
SQL> host prun 24559
1 81840 kslfre:entry
Step 16 at 2017 Sep 21 12:09:27--------Stopped at kslfre:entry(Addr=>0x600572B0)
--------ustack(5, 0)--------
oracle`kslfre
oracle`qesrcCM_Release+0x22d
oracle`psdfrcWriteResult+0x213
oracle`pevm_RET+0x3d9
oracle`pfrinstr_RET+0x26
1 81841 kslfre:entry
Step 17 at 2017 Sep 21 12:09:27--------Stopped at kslfre:entry(Addr=>0x600572B0)
--------ustack(5, 0)--------
oracle`kslfre
oracle`qesrcCM_Release+0x22d
oracle`psdfrcWriteResult+0x213
oracle`pevm_RET+0x3d9
oracle`pfrinstr_RET+0x26
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000023 20000000 84BD178F 0000022F 00000002 000014FE
SQL> host prun 24559
0 81842 kslfre:return
Step 18 at 2017 Sep 21 12:10:25--------Stopped at kslfre:return(Addr=>0x172)
--------ustack(5, 0)--------
oracle`kslfre+0x172
oracle`psdfrcWriteResult+0x213
oracle`pevm_RET+0x3d9
oracle`pfrinstr_RET+0x26
oracle`pfrrun_no_tool+0x12a
SQL> oradebug peek 0x600572B0 24
[0600572B0, 0600572C8) = 00000000 00000000 84BD178F 0000022F 00000002 000014FE
SQL> oradebug peek 0x600572B0 24 --S0: initial
[0600572B0, 0600572C8) = 00000000 00000000 84BD178B 0000022F 00000002 000014FE
pidˆ ˆX flag gets latch# level# where
SQL> oradebug peek 0x600572B0 24 --S1: Mode=>8 qesrcCM_Acquire+0x354
[0600572B0, 0600572C8) = 00000001 00000000 84BD178C 0000022F 00000002 000014EE
SQL> host prun 24559
SQL> oradebug peek 0x600572B0 24 --S2: Mode=>16 qesrcCM_AddDO+0xf3
[0600572B0, 0600572C8) = 00000023 20000000 84BD178D 0000022F 00000002 000014E3
SQL> host prun 24559
SQL> oradebug peek 0x600572B0 24 --S3: Mode=>16 qesrcCM_Acquire+0x354
[0600572B0, 0600572C8) = 00000023 20000000 84BD178E 0000022F 00000002 000014EE
SQL> host prun 24559
SQL> oradebug peek 0x600572B0 24 --S4: Mode=>16 psdfrcWriteResult+0x213
[0600572B0, 0600572C8) = 00000023 20000000 84BD178F 0000022F 00000002 000014FE
SQL> host prun 24559
SQL> oradebug peek 0x600572B0 24 --S5: psdfrcWriteResult -> qesrcCM_Release -> kslfre:entry
[0600572B0, 0600572C8) = 00000023 20000000 84BD178F 0000022F 00000002 000014FE
SQL> host prun 24559
SQL> oradebug peek 0x600572B0 24 --S6: psdfrcWriteResult -> qesrcCM_Release -> kslfre:return
[0600572B0, 0600572C8) = 00000000 00000000 84BD178F 0000022F 00000002 000014FE
If after the first dtrace stop (Step S1), we also open 3 Sqlplus Sesssions to fetch already existed Result Cache Item (S Mode Get):
SQL > exec rc_s_x_mode_blocking_proc(1);
From S0 -> S1: S Mode get.
From S2 -> S3 and S3 -> S4: one single blocked S Mode Session(the 1st wating Session) can get RC Latch (deblocked);
other Sessions are still blocked (kslfre called ???).
From S4 -> S5: no S Mode Sessions can get RC Latch, all S Mode Sessions are still blocked.
From S5 -> S6: all S Mode Sessions get RC Latch.
It looks like that during each X Mode state transition in that X Mode session,
maximum one S Mode Session can occasionally get RC Latch,
all other S Mode Sessions have to wait till "kslfre" called by that X Mode Session
(of course, other X Mode Sessions are also blocked.
And first RC Latch Get by each X Mode Session is a S Mode Get).Above oradebug peek also shows that S Mode and X Mode Blockings are marked by different flags:
S Mode Blocking: Blocking is achieved by flag 0x40000000 bit in the latch value. X Mode Blocking: Blocking is achieved by flag 0x20000000 bit in the latch value.In S Mode Blocking, first position (4 bytes) stores Nproc; whereas in X Mode Blocking, first position stores blocking session PID.
[0600572B0, 0600572C8) = 00000001 40000000 0C56FEFE 0000022F 00000002 000014EE
Nproc ˆX flag gets latch# level# where
[0600572B0, 0600572C8) = 00000023 20000000 84BD178D 0000022F 00000002 000014E3
pidˆ ˆX flag gets latch# level# where
5347 (0x14E3) -> Result Cache: Serialization01 5358 (0x14EE) -> Result Cache: Serialization12 5360 (0x14F0) -> Result Cache: Serialization14 5374 (0x14FE) -> Result Cache: Serialization28Cross-checking with V$RESULT_CACHE_OBJECTS:
V$RESULT_CACHE_OBJECTS.creation_timestamp = timestamp of psdfrcWriteResult+0x213 Call
V$RESULT_CACHE_OBJECTS.build_time =
from timestamp of psdfrcWriteResult+0x213 Call
to timestamp of (psdfrcWriteResult -> qesrcCM_Release ->) kslfre:entry Call
Look further two Addresses, they contain Misses: 0x70C257=7389783, and Sleeps: 0xAC913=706835
SQL> oradebug peek 0x0600572C8 24
[0600572C8, 0600572E0) = 00000001 00000000 00000000 0070C257 00000000 00000000
SQL> oradebug peek 0x0600572E0 24
[0600572E0, 0600572F8) = 5CA280DF 00000005 000AC913 00000000 00000000 00000000
6.3. X mode Blocking: Dtrace
With following Dtrace script, we will draw a State Transition Diagram to demonstrate 4 RC Latch Gets (1 S Mode and successive 3 X Mode) when adding a new RC item (only one S Mode when fetching an existed item). For each Transition, we show State Entry and State Return. We can see that there is a kslfre call between two Transitions. That is probably why occasionally other S Mode Sessions (fetching an existed item) can still get RC Latch during this X Mode Session (adding a new item) as discussed in the last section.
-- Launch Dtrace at first, then run plsql to add a new RC item.
SQL > exec rc_s_x_mode_blocking_proc(7);
sudo dtrace -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 {laddr = 0x600572B0; step = 1; begin_gets = 0, end_gets = 0; prev_ts = timestamp;
self->evt = "begin"; self->loc = 0x0;}
pid$target::qesrcCM*:entry /execname == "oracle"/ { self->rc = 1; }
pid$target::ksl_get_shared_latch:entry /self->rc > 0 && arg0 == laddr && (self->evt != probefunc || self->loc != arg3)/ {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
begin_gets = (begin_gets == 0 ? ls->gets: begin_gets); end_gets = ls->gets;
printf("\n***State Entry>>>(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\n (Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X)",
probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
self->evt = probefunc; self->loc = arg3;
ustack(5, 0);
step = step + 1; self->entry = 1; prev_ts = timestamp;}
pid$target::ksl_get_shared_latch:return /self->rc > 0 && self->entry == 1/ {
ls = ((latchstate *) copyin(laddr, sizeof(latchstate)));
printf("\n>>>State Return***(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);
self->entry = 0;}
pid$target::kslfre:entry /self->rc > 0 && arg0 == laddr && self->evt != probefunc/ {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
end_gets = ls->gets;
printf("\n>>>Transition>>>%s:%s(Addr=>0x%-X)", probefunc, probename, arg0);
self->evt = probefunc; self->loc = 0x0;
printf("\n===Latch freed===");
ustack(5, 0); step = step + 1; prev_ts = timestamp;}
END {
printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
printf("\nLatch Gets = %d (%d - %d)", (end_gets - begin_gets), (unsigned long)begin_gets, (unsigned long)end_gets); }
' -p 18118
CPU ID FUNCTION:NAME
4 81846 ksl_get_shared_latch:entry
---------Step 1 at 2017 Sep 25 08:14:15 (Elapsed-ns=2668662103)---------
***State Entry>>>(nproc_pid=>0x0, flag=>0x0, gets=>0x84BD1DBE, latch=>0x22F, level=>0x2, where=>0x14EE)
>>>Transition>>>ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>8, PID=>0x1)
oracle`ksl_get_shared_latch
oracle`qesrcPin_Get+0x8cb
oracle`qesrcCM_Acquire+0x354
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
4 128142 ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>0x1, flag=>0x0, gets=>0x84BD1DBF, latch=>0x22F, level=>0x2, where=>0x14EE)
4 89490 kslfre:entry
---------Step 2 at 2017 Sep 25 08:14:15 (Elapsed-ns=48752)---------
>>>Transition>>>kslfre:entry(Addr=>0x600572B0)
===Latch freed===
oracle`kslfre
oracle`qesrcPin_Get+0xaf6
oracle`qesrcCM_Acquire+0x354
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
4 81846 ksl_get_shared_latch:entry
---------Step 3 at 2017 Sep 25 08:14:15 (Elapsed-ns=19989)---------
***State Entry>>>(nproc_pid=>0x0, flag=>0x0, gets=>0x84BD1DBF, latch=>0x22F, level=>0x2, where=>0x14EE)
>>>Transition>>>ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5347(0x14E3), Mode=>16, PID=>0x2000000000000024)
oracle`ksl_get_shared_latch
oracle`qesrcCM_AddDO_+0x43b5
oracle`qesrcCM_AddDO+0xf3
oracle`qesrcCM_Acquire+0x702
oracle`psdfrcLookup+0x12d
4 128142 ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>0x24, flag=>0x20000000, gets=>0x84BD1DC0, latch=>0x22F, level=>0x2, where=>0x14E3)
4 89490 kslfre:entry
---------Step 4 at 2017 Sep 25 08:14:15 (Elapsed-ns=11792)---------
>>>Transition>>>kslfre:entry(Addr=>0x600572B0)
===Latch freed===
oracle`kslfre
oracle`qesrcCM_AddDO_+0x2e0
oracle`qesrcCM_AddDO+0xf3
oracle`qesrcCM_Acquire+0x702
oracle`psdfrcLookup+0x12d
4 81846 ksl_get_shared_latch:entry
---------Step 5 at 2017 Sep 25 08:14:15 (Elapsed-ns=9352)---------
***State Entry>>>(nproc_pid=>0x0, flag=>0x0, gets=>0x84BD1DC0, latch=>0x22F, level=>0x2, where=>0x14E3)
>>>Transition>>>ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5358(0x14EE), Mode=>16, PID=>0x2000000000000024)
oracle`ksl_get_shared_latch
oracle`qesrcPin_Get+0x959
oracle`qesrcCM_Acquire+0x354
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
4 128142 ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>0x24, flag=>0x20000000, gets=>0x84BD1DC1, latch=>0x22F, level=>0x2, where=>0x14EE)
4 89490 kslfre:entry
---------Step 6 at 2017 Sep 25 08:14:15 (Elapsed-ns=25046)---------
>>>Transition>>>kslfre:entry(Addr=>0x600572B0)
===Latch freed===
oracle`kslfre
oracle`qesrcPin_Get+0xaf6
oracle`qesrcCM_Acquire+0x354
oracle`psdfrcLookup+0x12d
oracle`pevm_ENTERX+0x143
4 81846 ksl_get_shared_latch:entry
---------Step 7 at 2017 Sep 25 08:14:15 (Elapsed-ns=25170)---------
***State Entry>>>(nproc_pid=>0x0, flag=>0x0, gets=>0x84BD1DC1, latch=>0x22F, level=>0x2, where=>0x14EE)
>>>Transition>>>ksl_get_shared_latch:entry
(Addr=>0x600572B0, Immed_Get=>1, Why=>1, Where=>5374(0x14FE), Mode=>16, PID=>0x2000000000000024)
oracle`ksl_get_shared_latch
oracle`qesrcCM_Release+0x293
oracle`psdfrcWriteResult+0x213
oracle`pevm_RET+0x3d9
oracle`pfrinstr_RET+0x26
4 128142 ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>0x24, flag=>0x20000000, gets=>0x84BD1DC2, latch=>0x22F, level=>0x2, where=>0x14FE)
4 89490 kslfre:entry
---------Step 8 at 2017 Sep 25 08:14:15 (Elapsed-ns=9845)---------
>>>Transition>>>kslfre:entry(Addr=>0x600572B0)
===Latch freed===
oracle`kslfre
oracle`qesrcCM_Release+0x22d
oracle`psdfrcWriteResult+0x213
oracle`pevm_RET+0x3d9
oracle`pfrinstr_RET+0x26
^C
1 2 :END
---------Step 9 at 2017 Sep 25 08:14:17 (Elapsed-ns=2254749376)---------
Latch Gets = 4 (2226986430 - 2226986434)
7. RESULT_CACHE Object Status Transition
SQL RESULT_CACHE hint has an option of SNAPSHOT. which specifies the Expired time interval. In the following test, we set "snapshot=5" (5 seconds) to track status transition of RESULT_CACHE Object:
New -> Published -> Expired -> Invalid
As the test shows, SNAPSHOT option turns off usual RESULT_CACHE invalidation of DML statement, and allows stale Read (dirty Read, non Consistency Read) of RESULT_CACHE.
We observed this usage in Oracle dynamic sampling (SNAPSHOT=3600). In real application, this undocumented feature can be used to make RESULT_CACHE as a database-wide provider of periodically sampling data.
----------------- Test Code -----------------
exec dbms_result_cache.flush;
select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
select status, name from v$result_cache_objects;
exec dbms_lock.sleep(2);
update rc_tab set val = -val where id = 3;
commit;
select id, val from rc_tab where id = 3;
--stale Read
select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
select status, name from v$result_cache_objects;
exec dbms_lock.sleep(3);
select status, name from v$result_cache_objects;
exec dbms_lock.sleep(1);
select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
select status, name from v$result_cache_objects;
----------------- Test Output -----------------
07:11:00 > exec dbms_result_cache.flush;
07:11:00 > select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
ID VAL
---------- ----------
3 30
07:11:00 > select status, name from v$result_cache_objects;
STATUS NAME
--------- -----------------------------------------------------------------------
Published select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3
07:11:00 > exec dbms_lock.sleep(2);
07:11:02 > update rc_tab set val = -val where id = 3;
1 row updated.
07:11:02 > commit;
07:11:02 > select id, val from rc_tab where id = 3;
ID VAL
---------- ----------
3 -30
07:11:02 > --stale Read
07:11:02 > select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
ID VAL
---------- ----------
3 30
07:11:02 > select status, name from v$result_cache_objects;
STATUS NAME
--------- -----------------------------------------------------------------------
Published select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3
07:11:02 > exec dbms_lock.sleep(3);
07:11:05 > select status, name from v$result_cache_objects;
STATUS NAME
--------- -----------------------------------------------------------------------
Expired select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3
07:11:05 > exec dbms_lock.sleep(1);
07:11:06 > select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3;
ID VAL
---------- ----------
3 -30
07:11:06 > select status, name from v$result_cache_objects;
STATUS NAME
--------- -----------------------------------------------------------------------
Published select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3
Invalid select /*+ RESULT_CACHE(snapshot=5) */ id, val from rc_tab where id = 3
2 rows selected.
8. Result Cache History Recording
There exist no DBA_HIST_* views to display the RC history of active sessions. We can create a small utility to record RC history usages (see appended code).
For example, we record 10 snaps in an interval of 1 second for top 5 rows, and then check the created history.
exec rc_scn_record_hist(p_snaps => 10, p_interval=> 1, p_rows => 5);
select * from hist_rc_scn
order by ts, sign(extract(minute from(scn_diff))*60 + extract(second from(scn_diff))) desc
,scn desc, scn_diff desc, status, name, id;
select * from hist_rc_scn_dep
order by ts, sign(extract(minute from(f_scn_diff))*60 + extract(second from(f_scn_diff))) desc
,f_scn desc, f_scn_diff desc, f_status, f_name;
select * from hist_rc_lru_number t
order by ts, name;
select * from hist_rc_memory t
order by ts, free;
select * from hist_rc_stats t
order by name, ts;
9. Result Cache Hidden Parameters
Here a list of RC hidden parameters in Oracle 12.1.0.2.0:
Name Description Default ------------------------------------------ ------------------------------------------------------- ------- _result_cache_auto_size_threshold result cache auto max size allowed 100 _result_cache_auto_time_threshold result cache auto time threshold 1000 _result_cache_auto_execution_threshold result cache auto execution threshold 1 _result_cache_deterministic_plsql result cache deterministic PLSQL functions FALSE _result_cache_block_size result cache block size 1024 _result_cache_copy_block_count blocks to copy instead of pinning the result 1 _result_cache_global Are results available globally across RAC? TRUE _result_cache_timeout maximum time (sec) a session waits for a result 10 _result_cache_auto_time_distance result cache auto time distance 300 _result_cache_auto_dml_monitoring_slots result cache auto dml monitoring slot 4 _result_cache_auto_dml_monitoring_duration result cache auto dml monitoring duration 15 _result_cache_auto_dml_threshold result cache auto dml threshold 16 _result_cache_auto_dml_trend_threshold result cache auto dml trend threshold 20 _optimizer_ads_result_cache_life result cache shelf life for ADS queries 3600 _client_result_cache_bypass bypass the client result cache FALSE _re_result_cache_keysiz defines max number key for result cache hash table 20 _re_result_cache_size defines max number of cached elements for result cache 20In verbatim text, they sound like something to regulate the refresh of Result Cache or its Dynamic Performance Views. But it is not clear how to make the test cases to detect their usage.
10. Test Code
drop table rc_tab;
drop table rc_tab_dep;
drop table rc_tab_2;
create table rc_tab (id number, val number);
create table rc_tab_dep (did number, dval number);
create table rc_tab_2 (id number, val number);
insert into rc_tab select level, level*10 from dual connect by level <= 17;
insert into rc_tab_dep select level, level*10 from dual connect by level <= 17;
insert into rc_tab_2 select level, level*10 from dual connect by level <= 13;
commit;
create or replace function get_val_dep (p_did number) return number as
l_dval_dep number;
begin
select dval into l_dval_dep from rc_tab_dep where did = p_did;
return l_dval_dep;
end;
/
create or replace function get_val (p_id number) return number result_cache as
l_val number;
l_val_dep number;
begin
select val into l_val from rc_tab where id = p_id;
l_val_dep := get_val_dep(p_id);
return l_val + l_val_dep;
end;
/
create or replace procedure run_test as
l_val number;
begin
-- SQL RESULT_CACHE
--for c in (select /*+ RESULT_CACHE */ * from rc_tab) loop
-- null;
--end loop;
for i in 1 .. 17 loop
l_val := get_val(i);
end loop;
end;
/
create or replace function get_val_2 (p_id number) return number result_cache as
l_val number;
l_val_dep number;
begin
select val into l_val from rc_tab_2 where id = p_id;
return l_val;
end;
/
create or replace procedure run_test_2 as
l_val number;
begin
for i in 1 .. 13 loop
l_val := get_val_2(i);
end loop;
end;
/
11. Result Cache Monitoring Views
drop view rc_scn_view;
create view rc_scn_view as
select systimestamp ts, scn_to_timestamp(t.scn) scn_time, (scn_to_timestamp(scn) - creation_timestamp) scn_diff, t.*
from v$result_cache_objects t
order by sign(extract(minute from(scn_diff))*60 + extract(second from(scn_diff))) desc
,scn desc, scn_diff desc, status, name, id;
drop view rc_scn_dep_view;
create view rc_scn_dep_view as
with rs_scn as
(select scn_to_timestamp(t.scn) scn_time, (scn_to_timestamp(scn) - creation_timestamp) scn_diff,
id, type, status, name, namespace, creation_timestamp, scn, object_no, invalidations, row_count
from v$result_cache_objects t)
select systimestamp ts,
f.scn_time f_scn_time, f.scn_diff f_scn_diff, f.id f_id, f.type f_type, f.status f_status, f.name f_name, f.namespace f_namespace,
f.creation_timestamp f_creation_timestamp, f.scn f_scn, f.object_no f_object_no, f.invalidations f_invalidations, f.row_count f_row_count,
t.scn_time t_scn_time, t.scn_diff t_scn_diff, t.id t_id, t.type t_type, t.status t_status, t.name t_name, t.namespace t_namespace,
t.creation_timestamp t_creation_timestamp, t.scn t_scn, t.object_no t_object_no, t.invalidations t_invalidations, t.row_count t_row_count
from rs_scn f,
v$result_cache_dependency d,
rs_scn t
where f.id = d.result_id(+)
and t.id(+) = d.depend_id
-- and t.name in ('K.RC_TAB_DEP', 'K.RC_TAB')
-- and f.name like '%"K"."%GET_VAL"%'
order by sign(extract(minute from(f.scn_diff))*60 + extract(second from(f.scn_diff))) desc
,f.scn desc, f.scn_diff desc, f.status, f.name;
drop view rc_lru_number_view;
create view rc_lru_number_view as
select systimestamp ts, name, cache_id, type, status, namespace
,min(lru_number) min_lru, max(lru_number) max_lru, max(lru_number) - min(lru_number) lru_diff
,count(*) rc_count, sum(block_count) blocks, sum(ceil(row_count*row_size_avg/1024)) est_blocks
,sum(row_count) row_cnt, min(row_size_min) row_size_min, max(row_size_max) row_size_max, round(avg(row_size_avg)) row_size_avg
,sum(pin_count) pin_count, round(avg(scan_count)) avg_scan_cnt
,sum(build_time*10) build_time_ms, round(avg(build_time*10), 3) avg_build_time, min(build_time*10) min_build_time, max(build_time*10) max_build_time
,sum(invalidations) invalidations
from v$result_cache_objects t
where lru_number > 0
group by name, cache_id, type, status, namespace
order by rc_count desc, avg_scan_cnt desc;
drop view rc_memory_view;
create view rc_memory_view as
select systimestamp ts, v.* from
(select free, count(*) cnt, min(offset) min_offset, max(offset) max_offset from v$result_cache_memory group by free) v;
drop view rc_stats_view;
create view rc_stats_view as
select systimestamp ts, v.* from v$result_cache_statistics v;
12. Result Cache History Recording
drop table hist_rc_scn;
create table hist_rc_scn as select 123456 snap_id, v.* from rc_scn_view v where 1=2;
drop table hist_rc_scn_dep;
create table hist_rc_scn_dep as select 123456 snap_id, v.* from rc_scn_dep_view v where 1=2;
drop table hist_rc_lru_number;
create table hist_rc_lru_number as select 123456 snap_id, v.* from rc_lru_number_view v where 1=2;
drop table hist_rc_memory;
create table hist_rc_memory as select 123456 snap_id, v.* from rc_memory_view v where 1=2;
drop table hist_rc_stats;
create table hist_rc_stats as select 123456 snap_id, v.* from rc_stats_view v where 1=2;
create or replace procedure rc_scn_record_hist(p_snaps number := 10, p_interval number := 1, p_rows number := 10) as
begin
for i in 1..p_snaps loop
insert into hist_rc_scn
select i snap_id, c.* from
(select v.* from rc_scn_view v
order by sign(extract(minute from(scn_diff))*60 + extract(second from(scn_diff))) desc
,scn desc, scn_diff desc, status, name, id) c
where rownum <= p_rows;
insert into hist_rc_scn_dep
select i snap_id, c.* from
(select v.* from rc_scn_dep_view v
order by sign(extract(minute from(f_scn_diff))*60 + extract(second from(f_scn_diff))) desc
,f_scn desc, f_scn_diff desc, f_status, f_name) c
where rownum <= p_rows;
insert into hist_rc_lru_number
select i snap_id, c.* from rc_lru_number_view c;
insert into hist_rc_memory
select i snap_id, c.* from rc_memory_view c;
insert into hist_rc_stats
select i snap_id, c.* from rc_stats_view c;
commit;
dbms_lock.sleep(p_interval);
end loop;
end;
/
truncate table hist_rc_scn;
truncate table hist_rc_scn_dep;
truncate table hist_rc_lru_number;
truncate table hist_rc_memory;
truncate table hist_rc_stats;
exec rc_scn_record_hist(p_snaps => 10, p_interval=> 1, p_rows => 5);
select * from hist_rc_scn
order by ts, sign(extract(minute from(scn_diff))*60 + extract(second from(scn_diff))) desc
,scn desc, scn_diff desc, status, name, id;
select * from hist_rc_scn_dep
order by ts, sign(extract(minute from(f_scn_diff))*60 + extract(second from(f_scn_diff))) desc
,f_scn desc, f_scn_diff desc, f_status, f_name;
select * from hist_rc_lru_number t
order by ts, name;
select * from hist_rc_memory t
order by ts, free;
select * from hist_rc_stats t
order by name, ts;
