[20250523]生产系统表没有分析统计信息出现的问题(11g).txt
[20250523]生产系统表没有分析统计信息出现的问题(11g).txt
--//前几天在21c下测试表没有分析统计信息大量执行没有使用绑定变量sql语句遇到的情况，导致大量sql语句动态取样，出现等待事件
--//enq: RC - Result Cache: Contention靠前的情况，主要原因是动态执行的sql语句加入了R提示ESULT_CACHE(SNAPSHOT=3600)，
--//oracle的本意开始result cache的处理方式加快动态取样的执行，结果如果大量的文字变量语句将问题集中在其争用上，测试看看
--//以前11g会出现什么情况。
1.环境：
SCOTT@book> @ ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
2.测试环境建立：
SCOTT@book01p> create table t1 as select mod(rownum,1e4) id ,'test' vc from dual connect by level<=1e6;
Table created.
SCOTT@book01p> create index i_t1_id on t1(id);
Index created.
--//注意不分析表，建立索引不能唯一，否则不会执行动态取样。这样的情况仅仅索引有统计信息。
$ cat loope.txt
set verify off
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
--EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t1 where id = :j ' INTO l_count using i;
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t1 where id = ' || i INTO l_count ;
END LOOP;
END;
/
--//注：语句使用文字变量，如果参数2每个会话不同，导致执行的sql语句都是硬解析。
--//create table job_times (sid number, time_ela number,method varchar2(20));
$ cat record.txt
--// arg1 = loop counts ， arg2 = method ， arg3= test scirpt
set verify off
variable v_method varchar2(20)
exec :v_method := (case when '&2' >= '1' and '&2'<='9999' then 'QQQQ' else '&2' end);
define t=&&1;
column 3 new_value 3;
select decode('&3',null,'loop.txt','&&3') "3" from dual;
@@ &&3 5 &&2
--//insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
--//commit ;
@@ &&3 &&t &&2
--//update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method= :v_method;
--//commit;
quit
3.测试：
$ zzdate ; seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @record.txt 1e6 Q loope.txt > /dev/null ; zzdate
trunc(sysdate)+09/24+58/1440+13/86400 1747965493.102152219
--//参数2使用Q代替，这样每个会话执行的sql语句都不同，相当于产生大量的文字变量的sql语句。
4.不等执行完成开始分析：
SYS@book> host sleep 300
SYS@book> @ ashtop event 1=1 trunc(sysdate)+09/24+58/1440+13/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- --------------------------- ------------------- ------------------- ---------- -------- -----------
2423 7.0 70% | 2025-05-23 09:58:14 2025-05-23 10:03:58 29 343 371
967 2.8 28% | latch: shared pool 2025-05-23 09:58:17 2025-05-23 10:03:57 5 292 281
44 .1 1% | library cache: mutex X 2025-05-23 09:58:16 2025-05-23 10:03:56 2 29 27
20 .1 1% | latch: row cache objects 2025-05-23 09:58:14 2025-05-23 10:03:45 1 12 12
5 .0 0% | library cache load lock 2025-05-23 10:00:37 2025-05-23 10:03:38 1 4 4
3 .0 0% | control file parallel write 2025-05-23 09:58:21 2025-05-23 10:03:33 1 3 3
3 .0 0% | cursor: pin S 2025-05-23 10:02:07 2025-05-23 10:02:07 1 1 1
2 .0 0% | db file sequential read 2025-05-23 10:01:06 2025-05-23 10:02:10 2 2 2
1 .0 0% | db file scattered read 2025-05-23 10:02:13 2025-05-23 10:02:13 1 1 1
1 .0 0% | latch: enqueue hash chains 2025-05-23 10:03:47 2025-05-23 10:03:47 1 1 1
10 rows selected.
--//可以发现开始等待事件latch: shared pool排在第一，与21c下的测试enq: RC - Result Cache: Contention排第一不同。
--//如果扫描共享池按执行次数倒排序可以发现：
SCOTT@book> @ sql_id cuzphgv557zkj
-- SQL_ID = cuzphgv557zkj come from shared pool
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS opt_param('parallel_execution_enabled', 'false') NO_PARALLEL(SAMPLESUB) NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1"), NVL(SUM(C3),:"SYS_B_2") FROM (SELECT /*+ NO_PARALLEL("T1") INDEX("T1" I_T1_ID) NO_PARALLEL_INDEX("T1") */ :"SYS_B_3" AS C1, :"SYS_B_4" AS C2, :"SYS_B_5" AS C3 FROM "SCOTT"."T1" "T1" WHERE "T1"."ID"=:"SYS_B_6" AND ROWNUM <= :"SYS_B_7") SAMPLESUB;
SCOTT@book> @ sql_id 2dsmw1hvdhbds
-- SQL_ID = 2dsmw1hvdhbds come from shared pool
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("T1") FULL("T1") NO_PARALLEL_INDEX("T1") */ :"SYS_B_2" AS C1, CASE WHEN "T1"."ID"=:"SYS_B_3" THEN :"SYS_B_4" ELSE :"SYS_B_5" END AS C2 FROM "SCOTT"."T1" SAMPLE BLOCK (:"SYS_B_6" , :"SYS_B_7") SEED (:"SYS_B_8") "T1") SAMPLESUB;
--//可以发现与21c不同，没有RESULT_CACHE(SNAPSHOT=3600)提示。
--//还可以发现出现另外1个等待事件latch: row cache objects，先放一放，看看library cache: mutex X。
SYS@book> @ ashtop event,p1raw,p1 "event='library cache: mutex X'" trunc(sysdate)+09/24+58/1440+13/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
37 .0 35% | library cache: mutex X 00000000D4387380 3560469376 2025-05-23 09:58:34 2025-05-23 10:11:05 1 22 22
17 .0 16% | library cache: mutex X 00000000DE8BA781 3733694337 2025-05-23 10:00:21 2025-05-23 10:11:03 1 6 6
5 .0 5% | library cache: mutex X 0000000036D82DB8 920137144 2025-05-23 09:58:37 2025-05-23 10:09:42 1 3 3
3 .0 3% | library cache: mutex X 0000000000017CF2 97522 2025-05-23 09:59:01 2025-05-23 09:59:01 1 1 1
3 .0 3% | library cache: mutex X 000000001D5F7CF2 492797170 2025-05-23 10:00:53 2025-05-23 10:07:36 2 3 2
2 .0 2% | library cache: mutex X 00000000CA53FE51 3394502225 2025-05-23 10:11:15 2025-05-23 10:11:15 1 1 1
1 .0 1% | library cache: mutex X 000000000000169E 5790 2025-05-23 10:05:38 2025-05-23 10:05:38 1 1 1
1 .0 1% | library cache: mutex X 000000000000242E 9262 2025-05-23 10:02:03 2025-05-23 10:02:03 1 1 1
1 .0 1% | library cache: mutex X 0000000000006C39 27705 2025-05-23 09:59:31 2025-05-23 09:59:31 1 1 1
1 .0 1% | library cache: mutex X 000000000000A998 43416 2025-05-23 10:05:51 2025-05-23 10:05:51 1 1 1
1 .0 1% | library cache: mutex X 000000000000AC9F 44191 2025-05-23 10:02:51 2025-05-23 10:02:51 1 1 1
1 .0 1% | library cache: mutex X 000000000000B498 46232 2025-05-23 10:09:58 2025-05-23 10:09:58 1 1 1
1 .0 1% | library cache: mutex X 000000000000B55F 46431 2025-05-23 10:09:22 2025-05-23 10:09:22 1 1 1
1 .0 1% | library cache: mutex X 000000000000BBF1 48113 2025-05-23 10:10:10 2025-05-23 10:10:10 1 1 1
1 .0 1% | library cache: mutex X 0000000000013BB0 80816 2025-05-23 10:10:04 2025-05-23 10:10:04 1 1 1
1 .0 1% | library cache: mutex X 00000000000164C1 91329 2025-05-23 10:07:05 2025-05-23 10:07:05 1 1 1
1 .0 1% | library cache: mutex X 0000000000019863 104547 2025-05-23 10:01:29 2025-05-23 10:01:29 1 1 1
1 .0 1% | library cache: mutex X 000000000001CDF0 118256 2025-05-23 10:02:15 2025-05-23 10:02:15 1 1 1
1 .0 1% | library cache: mutex X 000000000001ED78 126328 2025-05-23 10:08:06 2025-05-23 10:08:06 1 1 1
1 .0 1% | library cache: mutex X 00000000186C474C 409749324 2025-05-23 09:58:20 2025-05-23 09:58:20 1 1 1
1 .0 1% | library cache: mutex X 0000000022117ABB 571570875 2025-05-23 10:03:56 2025-05-23 10:03:56 1 1 1
1 .0 1% | library cache: mutex X 00000000466F59BF 1181702591 2025-05-23 10:07:14 2025-05-23 10:07:14 1 1 1
1 .0 1% | library cache: mutex X 0000000046951B7B 1184177019 2025-05-23 10:01:11 2025-05-23 10:01:11 1 1 1
1 .0 1% | library cache: mutex X 00000000597C2F8B 1501310859 2025-05-23 10:09:19 2025-05-23 10:09:19 1 1 1
1 .0 1% | library cache: mutex X 000000005E34F93D 1580529981 2025-05-23 10:07:02 2025-05-23 10:07:02 1 1 1
1 .0 1% | library cache: mutex X 0000000070331D5D 1882398045 2025-05-23 10:01:09 2025-05-23 10:01:09 1 1 1
1 .0 1% | library cache: mutex X 0000000072DEB715 1927198485 2025-05-23 10:06:20 2025-05-23 10:06:20 1 1 1
1 .0 1% | library cache: mutex X 00000000754F6B8C 1968139148 2025-05-23 10:06:36 2025-05-23 10:06:36 1 1 1
1 .0 1% | library cache: mutex X 000000007AA89CD0 2057870544 2025-05-23 10:06:38 2025-05-23 10:06:38 1 1 1
1 .0 1% | library cache: mutex X 00000000967A9FFD 2524618749 2025-05-23 09:59:58 2025-05-23 09:59:58 1 1 1
30 rows selected.
--//前面已经提到11g无法区分在library cache bucket出现的mutex，还是library cache出现的mutex，唯一的线索看看p1是否小于
--//2^17= 131072. 小于131072的大概率是发生在bucket上的mutex。
--//11g这类情况大部分等待还是集中在latch: shared pool。
--//比如 p1raw = 0000000000017CF2 ,000000001D5F7CF2,注意看后4位两者相同。看看是什么对象。
SYS@book> @ kglob '' 492797170 '' ''
==============================
INST_ID : 1
OWNER : SYS
NAME : book
DB_LINK :
NAMESPACE_NUM : DBINSTANCE
NAMESPACE_HEX : 4a
TYPE : CURSOR
SHARABLE_MEM : 0
PERSISTENT_MEM : 0
RUNTIME_MEM : 0
LOADS : 0
EXECUTIONS : 0
LOCKS : 8
PINS : 0
KEPT : NO
CHILD_LATCH : 97522
INVALIDATIONS : 0
HASH_VALUE : 492797170
HASH_HEX : 1d5f7cf2
LOCK_MODE : SHARED
PIN_MODE : NONE
STATUS : UNKOWN
TIMESTAMP :
PREVIOUS_TIMESTAMP :
LOCKED_TOTAL : 4478187
PINNED_TOTAL : 0
PROPERTY :
FULL_HASH_VALUE : d5a4dd9a32c90ace3b8391181d5f7cf2
ADDR : 000000008F980A30
PAR_ADDR : 000000008F980A30
HANDLE_TYPE : parent handle address
KGLOBHD0 : 00
KGLOBHD6 : 00
SQL_ID :
OBJECT_STR : book.SYS.\x4a\0\0\0
PL/SQL procedure successfully completed.
--//我的测试也许会话不多，大部分应该集中的表,实例，schema对象上。那些抓到1次大部分执行的文字变量的sql语句。
5.看看latch: row cache objects等待事件：
SYS@book> @ ashtop event,p1raw,p1 "event='latch: row cache objects'" trunc(sysdate)+09/24+58/1440+13/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
85 .0 38% | latch: row cache objects 000000008C235E48 2351128136 2025-05-23 09:58:25 2025-05-23 10:53:51 1 38 38
58 .0 26% | latch: row cache objects 000000008C135C88 2350079112 2025-05-23 09:58:14 2025-05-23 10:50:54 1 22 22
49 .0 22% | latch: row cache objects 000000008C741568 2356417896 2025-05-23 09:58:56 2025-05-23 10:51:23 1 22 22
24 .0 11% | latch: row cache objects 000000008C339D48 2352192840 2025-05-23 10:03:45 2025-05-23 10:47:16 1 10 10
10 .0 4% | latch: row cache objects 000000008C134140 2350072128 2025-05-23 10:06:47 2025-05-23 10:44:16 1 4 4
SYS@book> @ la 000000008C235E48
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SPINGETS SLEEPS WAIT_TIME
---------------- ---------- ------ ----------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000008C235E48 309 9 row cache objects 21805392 5485 38876 20 36060 2865 35280395
SYS@book> @ la 000000008C741568
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SPINGETS SLEEPS WAIT_TIME
---------------- ---------- ------ ----------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000008C741568 309 4 row cache objects 32460101 729 23794 2 22634 1173 13767705
SYS@book> @ la 000000008C135C88
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SPINGETS SLEEPS WAIT_TIME
---------------- ---------- ------ ----------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000008C135C88 309 8 row cache objects 16422143 451 12115 1 10777 1342 17042941
--//只能看出name='row cache objects'对象的latch，到底什么还是不清楚。
SYS@book> @latchprofx func,laddr % "row cache objects" 400000
-- LatchProfX 2.11 by Tanel Poder ( https://tanelpoder.com )
FUNC LADDR Held Gets Held % Held ms Avg hold ms
---------------------------------------- ---------------- ---------- ---------- ------- ----------- -----------
kqrpre: find obj 000000008C235E48 1156 934 .29 14.566 .016
kqrpre: find obj 000000008C135C88 318 316 .08 4.007 .013
kqrpre: find obj 000000008C741568 294 294 .07 3.704 .013
kqreqd: reget 000000008C235E48 239 214 .06 3.011 .014
kqrpre: find obj 000000008C339D48 227 194 .06 2.860 .015
kqreqd: reget 000000008C135C88 209 209 .05 2.633 .013
kqreqd 000000008C235E48 207 206 .05 2.608 .013
kqreqd 000000008C135C88 192 190 .05 2.419 .013
kqreqd 000000008C741568 174 152 .04 2.192 .014
kqrpre: find obj 000000008C134140 160 160 .04 2.016 .013
kqreqd: reget 000000008C741568 116 116 .03 1.462 .013
kqrso 000000008C339D48 58 44 .01 .731 .017
kqreqd: reget 000000008C134140 53 53 .01 .668 .013
kqreqd 000000008C134140 51 51 .01 .643 .013
kqreqd: reget 000000008C339D48 42 42 .01 .529 .013
kqreqd 000000008C339D48 37 37 .01 .466 .013
kghfrunp: clatch: nowait 000000008C339D48 18 18 .00 .227 .013
kqrsrd 000000008C339D48 3 3 .00 .038 .013
kqrpre: init complete 000000008C339D48 3 3 .00 .038 .013
kqrpre: init complete 000000008C235E48 1 1 .00 .013 .013
20 rows selected.
$ ./lookup.awk kqrpre
kqrpre : kernel query dictionary/row cache read a parent cache object
$ ./lookup.awk kqreqd
kqreqd : kernel query dictionary/row cache enqueue delete
SYS@book> select * from v$latch_misses where parent_name='row cache objects' and WTR_SLP_COUNT>1 order by 4;
PARENT_NAME WHERE NWFAIL_COUNT SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT LOCATION
----------------- --------------------- ------------ ----------- ------------- -------------- ------------------------------
row cache objects kqrsrd 0 2 3 0 kqrsrd
row cache objects kqrpre: init complete 0 19 4 0 kqrpre: init complete
row cache objects kqreqd 0 121 62 0 kqreqd
row cache objects kqrpre: find obj 0 549 18341 0 kqrpre: find obj
row cache objects kqreqd: reget 0 17358 4 0 kqreqd: reget
--//具体是那些对象的细节，还是无法知道。
SYS@book> @latchprofx laddr % "row cache objects" 400000
-- LatchProfX 2.11 by Tanel Poder ( https://tanelpoder.com )
LADDR Held Gets Held % Held ms Avg hold ms
---------------- ---------- ---------- ------- ----------- -----------
000000008C235E48 1507 1267 .38 19.779 .016
000000008C135C88 1265 764 .32 16.603 .022
000000008C741568 848 606 .21 11.130 .018
000000008C134140 325 311 .08 4.266 .014
000000008C339D48 239 236 .06 3.137 .013
SYS@book> select * from x$kqrst where kqrstcln in (9,4,8) and KQRSTGRQ>1000;
ADDR INDX INST_ID KQRSTCID KQRSTSNO KQRSTTYP KQRSTTXT KQRSTCSZ KQRSTOSZ KQRSTFCS KQRSTUSG KQRSTGRQ KQRSTFASTGRQ KQRSTGMI KQRSTSRQ KQRSTSMI KQRSTSCO KQRSTMRQ KQRSTMFL KQRSTCLN KQRSTILR KQRSTIFR KQRSTISR
---------------- ---------- ---------- ---------- ---------- ---------- -------------------- ---------- ---------- ---------- ---------- ---------- ------------ ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000008C63DE70 3 1 2 0 1 dc_segments 2 0 0 2 35108187 0 1478 0 0 0 28 28 4 0 0 0
000000008C63DF90 7 1 10 0 1 dc_users 3 0 0 3 17621959 0 1072 0 0 0 0 0 8 0 0 0
000000008C63DFD8 8 1 8 0 1 dc_objects 167 0 116 167 23650121 0 18621 0 0 0 156 39 9 0 0 0
--//主要还是硬解析导致问题。
6.继续测试：
--//中断前面的测试，分析表后重复测试：
$ zzdate ; seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @record.txt 1e6 Q loope.txt > /dev/null ; zzdate
trunc(sysdate)+11/24+10/1440+22/86400 1747969822.286993725
....
SYS@book> host sleep 300
SYS@book> @ ashtop event 1=1 trunc(sysdate)+11/24+10/1440+22/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
1536 6.4 64% | latch: shared pool 2025-05-23 11:10:23 2025-05-23 11:14:22 2 235 235
760 3.2 32% | 2025-05-23 11:10:23 2025-05-23 11:14:22 30 236 263
92 .4 4% | library cache: mutex X 2025-05-23 11:10:27 2025-05-23 11:14:19 2 27 28
18 .1 1% | latch: row cache objects 2025-05-23 11:10:50 2025-05-23 11:11:56 1 5 5
1 .0 0% | os thread startup 2025-05-23 11:11:22 2025-05-23 11:11:22 1 1 1
SYS@book> @ ashtop event,p1raw,p1 "event='library cache: mutex X'" trunc(sysdate)+11/24+10/1440+22/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
53 .2 55% | library cache: mutex X 0000000000017CF2 97522 2025-05-23 11:10:27 2025-05-23 11:14:57 2 12 10
27 .1 28% | library cache: mutex X 00000000D4387380 3560469376 2025-05-23 11:11:10 2025-05-23 11:14:14 1 14 14
8 .0 8% | library cache: mutex X 000000001D5F7CF2 492797170 2025-05-23 11:10:44 2025-05-23 11:14:14 2 6 6
6 .0 6% | library cache: mutex X 00000000DE8BA781 3733694337 2025-05-23 11:10:58 2025-05-23 11:13:38 1 5 5
3 .0 3% | library cache: mutex X 0000000000007380 29568 2025-05-23 11:13:19 2025-05-23 11:13:19 1 1 1
SYS@book> @ kglob '' 00000000D4387380 '' ''
==============================
INST_ID : 1
OWNER : SCOTT
NAME : T1
DB_LINK :
NAMESPACE_NUM : TABLE/PROCEDURE
NAMESPACE_HEX : 1
TYPE : TABLE
SHARABLE_MEM : 4696
PERSISTENT_MEM : 0
RUNTIME_MEM : 0
LOADS : 4
EXECUTIONS : 0
LOCKS : 5
PINS : 5
KEPT : NO
CHILD_LATCH : 29568
INVALIDATIONS : 0
HASH_VALUE : 3560469376
HASH_HEX : d4387380
LOCK_MODE : SHARED
PIN_MODE : SHARED
STATUS : VALID
TIMESTAMP : 2025-05-23/09:52:30
PREVIOUS_TIMESTAMP :
LOCKED_TOTAL : 7911108
PINNED_TOTAL : 7911105
PROPERTY :
FULL_HASH_VALUE : f1cd2b1c8166d406fc4e5e0fd4387380
ADDR : 0000000087ADDCA0
PAR_ADDR : 0000000087ADDCA0
HANDLE_TYPE : parent handle address
KGLOBHD0 : 000000008885B7C0
KGLOBHD6 : 00
SQL_ID :
OBJECT_STR : T1.SCOTT.\x1\0\0\0
PL/SQL procedure successfully completed.
SYS@book> @ ashtop event,p1raw,p1 "event='latch: row cache objects'" trunc(sysdate)+11/24+10/1440+22/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
13 .0 54% | latch: row cache objects 000000008C135C88 2350079112 2025-05-23 11:10:50 2025-05-23 11:11:56 1 4 4
6 .0 25% | latch: row cache objects 000000008C235E48 2351128136 2025-05-23 11:15:15 2025-05-23 11:16:21 1 2 2
5 .0 21% | latch: row cache objects 000000008C741568 2356417896 2025-05-23 11:11:52 2025-05-23 11:11:52 1 1 1
--//仔细对比发现比前面少2行。
SYS@book> @latchprofx func,laddr % "row cache objects" 400000
-- LatchProfX 2.11 by Tanel Poder ( https://tanelpoder.com )
FUNC LADDR Held Gets Held % Held ms Avg hold ms
---------------------------------------- ---------------- ---------- ---------- ------- ----------- -----------
kqrpre: find obj 000000008C235E48 4473 4382 1.12 33.436 .008
kqrpre: find obj 000000008C135C88 1812 1791 .45 13.545 .008
kqrpre: find obj 000000008C741568 1189 1164 .30 8.888 .008
kqreqd 000000008C235E48 1106 1095 .28 8.267 .008
kqreqd 000000008C135C88 1030 987 .26 7.699 .008
kqreqd: reget 000000008C235E48 861 858 .22 6.436 .008
kqreqd: reget 000000008C135C88 649 646 .16 4.851 .008
kqrpre: find obj 000000008C339D48 631 630 .16 4.717 .007
kqreqd 000000008C741568 421 421 .11 3.147 .007
kqreqd: reget 000000008C741568 350 323 .09 2.616 .008
kqreqd 000000008C339D48 154 154 .04 1.151 .007
kqreqd: reget 000000008C339D48 97 97 .02 .725 .007
kghfrunp: clatch: nowait 000000008C339D48 2 2 .00 .015 .007
kqrpre: init complete 000000008C235E48 1 1 .00 .007 .007
14 rows selected.
7.测试cursor_sharing=force的情况。
--//在执行脚本record.txt 开头加入 alter session set cursor_sharing=force;
$ zzdate ; seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @record.txt 1e6 BBBB loope.txt > /dev/null ; zzdate
trunc(sysdate)+11/24+24/1440+50/86400 -1747970690.472024012
trunc(sysdate)+11/24+26/1440+57/86400 1747970817.269232887
--//Sum = 126.797208875
--//参数2使用BBBB，这样每个会话执行的sql语句都一样在cursor_sharing=force的情况下相同的.
SYS@book> @ ashtop event 1=1 trunc(sysdate)+11/24+24/1440+50/86400 trunc(sysdate)+11/24+26/1440+57/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----------------------- ------------------- ------------------- ---------- -------- -----------
581 4.6 46% | 2025-05-23 11:24:51 2025-05-23 11:26:56 214 119 313
509 4.0 40% | library cache: mutex X 2025-05-23 11:24:52 2025-05-23 11:26:56 11 121 80
130 1.0 10% | library cache load lock 2025-05-23 11:24:51 2025-05-23 11:26:56 10 58 10
16 .1 1% | cursor: mutex S 2025-05-23 11:25:05 2025-05-23 11:26:36 1 10 10
10 .1 1% | cursor: pin S 2025-05-23 11:24:52 2025-05-23 11:26:17 1 8 8
10 .1 1% | latch: shared pool 2025-05-23 11:25:17 2025-05-23 11:26:56 1 4 4
2 .0 0% | ADR block file read 2025-05-23 11:24:50 2025-05-23 11:24:50 2 1 2
7 rows selected.
SYS@book> @ ashtop event,p1raw,p1 "event='library cache: mutex X'" trunc(sysdate)+11/24+24/1440+50/86400 trunc(sysdate)+11/24+26/1440+57/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
321 2.5 63% | library cache: mutex X 00000000000079B7 31159 2025-05-23 11:24:52 2025-05-23 11:26:55 10 98 10
136 1.1 27% | library cache: mutex X 00000000F94879B7 4182276535 2025-05-23 11:24:52 2025-05-23 11:26:55 10 77 79
--//以上2项p1raw的后4位相同。
5 .0 1% | library cache: mutex X 000000000000DC89 56457 2025-05-23 11:25:27 2025-05-23 11:25:27 5 1 5
4 .0 1% | library cache: mutex X 00000000746B5BFF 1953192959 2025-05-23 11:26:33 2025-05-23 11:26:33 4 1 4
3 .0 1% | library cache: mutex X 000000007128E72C 1898506028 2025-05-23 11:24:59 2025-05-23 11:24:59 3 1 3
2 .0 0% | library cache: mutex X 0000000009B4203C 162799676 2025-05-23 11:26:10 2025-05-23 11:26:10 2 1 2
2 .0 0% | library cache: mutex X 0000000044BD6613 1153263123 2025-05-23 11:26:08 2025-05-23 11:26:08 2 1 2
2 .0 0% | library cache: mutex X 000000005B930106 1536360710 2025-05-23 11:26:47 2025-05-23 11:26:47 2 1 2
2 .0 0% | library cache: mutex X 00000000686AB267 1751822951 2025-05-23 11:26:40 2025-05-23 11:26:40 2 1 2
2 .0 0% | library cache: mutex X 000000007C87B954 2089269588 2025-05-23 11:26:31 2025-05-23 11:26:31 2 1 2
2 .0 0% | library cache: mutex X 00000000ABC256DC 2881640156 2025-05-23 11:25:26 2025-05-23 11:25:26 2 1 2
2 .0 0% | library cache: mutex X 00000000B82F1059 3090092121 2025-05-23 11:26:22 2025-05-23 11:26:22 2 1 2
2 .0 0% | library cache: mutex X 00000000EB794757 3950593879 2025-05-23 11:25:34 2025-05-23 11:25:34 2 1 2
2 .0 0% | library cache: mutex X 00000000FF6A08C8 4285139144 2025-05-23 11:26:42 2025-05-23 11:26:42 2 1 2
1 .0 0% | library cache: mutex X 00000000000008A9 2217 2025-05-23 11:25:21 2025-05-23 11:25:21 1 1 1
1 .0 0% | library cache: mutex X 0000000000005CB5 23733 2025-05-23 11:26:21 2025-05-23 11:26:21 1 1 1
1 .0 0% | library cache: mutex X 000000000000C3BF 50111 2025-05-23 11:26:48 2025-05-23 11:26:48 1 1 1
1 .0 0% | library cache: mutex X 000000000000E417 58391 2025-05-23 11:24:55 2025-05-23 11:24:55 1 1 1
1 .0 0% | library cache: mutex X 00000000000115F7 71159 2025-05-23 11:26:47 2025-05-23 11:26:47 1 1 1
1 .0 0% | library cache: mutex X 000000000001EE61 126561 2025-05-23 11:25:00 2025-05-23 11:25:00 1 1 1
1 .0 0% | library cache: mutex X 000000000001FD5A 130394 2025-05-23 11:26:56 2025-05-23 11:26:56 1 1 1
1 .0 0% | library cache: mutex X 0000000006C8E334 113828660 2025-05-23 11:25:30 2025-05-23 11:25:30 1 1 1
1 .0 0% | library cache: mutex X 000000001DC9B286 499757702 2025-05-23 11:26:07 2025-05-23 11:26:07 1 1 1
1 .0 0% | library cache: mutex X 0000000021805EA8 562060968 2025-05-23 11:25:07 2025-05-23 11:25:07 1 1 1
1 .0 0% | library cache: mutex X 00000000284B9893 676042899 2025-05-23 11:25:10 2025-05-23 11:25:10 1 1 1
1 .0 0% | library cache: mutex X 00000000472AD658 1193989720 2025-05-23 11:25:10 2025-05-23 11:25:10 1 1 1
1 .0 0% | library cache: mutex X 000000005DF6EF52 1576464210 2025-05-23 11:26:51 2025-05-23 11:26:51 1 1 1
1 .0 0% | library cache: mutex X 000000007234A436 1916052534 2025-05-23 11:26:10 2025-05-23 11:26:10 1 1 1
1 .0 0% | library cache: mutex X 0000000076492598 1984505240 2025-05-23 11:24:59 2025-05-23 11:24:59 1 1 1
1 .0 0% | library cache: mutex X 000000007BF86079 2079875193 2025-05-23 11:26:40 2025-05-23 11:26:40 1 1 1
30 rows selected.
SYS@book> @ sharepool/shp4 '' 00000000F94879B7
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000085B4BE88 00000000879F8278 Select /*+ BBBB */ count(*) from t1 wher 0 0 0 0000000088B81168 000000008567A770 4528 8088 3114 15730 15730 4182276535 5bfgs3zwnhydr 0
parent handle address 00000000879F8278 00000000879F8278 Select /*+ BBBB */ count(*) from t1 wher 0 0 0 0000000087B232C0 00 4752 0 0 4752 4752 4182276535 5bfgs3zwnhydr 65535
--//这是我以前没有测试的情况,在cursor_sharing=force的情况下,靠前的等待事件竟然是library cache: mutex X,以前如果使用绑定
--//变量的情况是cursor: pin S.为什么?另外写一篇分析.
--//也可以说明一点，实际上通过cursor_sharing=force, 实际上在许多地方存在mutex地址，而真正的绑定变量仅仅在子游标的堆0。
SYS@book> @ mutexprofz idn,loc,maddr "ts>=trunc(sysdate)+11/24+37/1440+06/86400 and hash=4182276535"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 50 sleeps...
-- column info : id idn hash hash_value=>hash_value ts=>sleep_timestamp
-- req=>requesting_session blk=>blocking_session val=>mutex_value maddr=>mutex_addr
SUM_SLEEPS GETS_DIFF MUTEX_TYPE IDN GET_LOCATION mutex_addr SQL_ID OBJECT_NAME
---------- -------------- --------------- ---------- --------------------------------- -------------------- ------------- --------------------------------------------------------------------------------
34480 20698 Library Cache 4182276535 kglhdgh1 64 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
25395 16909 Library Cache 4182276535 kgllkc1 57 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
16957 30539 Library Cache 4182276535 kgllkdl1 85 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
8860 Library Cache 4182276535 kgllkdl1 85 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
7837 141660 Cursor Pin 4182276535 kksLockDelete [KKSCHLPIN6] 000000008567A6C8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
3512 134173 Cursor Pin 4182276535 kkslce [KKSCHLPIN2] 000000008567A6C8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
3186 289478 hash table 4182276535 kkshGetNextChild [KKSHBKLOC1] 000000008567A308 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
4 Library Cache 4182276535 kglReleaseHandleReference 125 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
8 rows selected.
--//00000000879F83B8-00000000879F8248 = 0x170
--//00000000879F83B8-00000000879F8278 = 0x140 = 320
--//父游标句柄偏移0x140=320.
SYS@book> @ fchaz 00000000879F83B8
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 00000000879F8248 1 2 KGLHD 592 recr 80 00 00000000879F8248 00000000879F8498
--//位于父游标里面。
--//采用绑定变量，注解脚本record.txt 开头加入 alter session set cursor_sharing=force;。
--//改写loope.txt使用绑定变量。
$ cat loope.txt
set verify off
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t1 where id = :j ' INTO l_count using i;
--EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t1 where id = ' || i INTO l_count ;
END LOOP;
END;
/
$ zzdate ; seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @record.txt 1e6 cccc loope.txt > /dev/null ; zzdate
trunc(sysdate)+11/24+47/1440+50/86400 -1747972070.393439049
trunc(sysdate)+11/24+48/1440+40/86400 1747972120.258478330
--//Sum = 49.865039281
--//类似的测试50秒完成。
SYS@book> @ ashtop event,p1raw,p1 1=1 trunc(sysdate)+11/24+47/1440+50/86400 trunc(sysdate)+11/24+48/1440+40/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----------------------- ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
384 7.7 79% | 2872888977 2025-05-23 11:47:51 2025-05-23 11:48:39 201 49 245
95 1.9 19% | cursor: pin S 00000000AB3CCE91 2872888977 2025-05-23 11:47:52 2025-05-23 11:48:37 1 35 35
5 .1 1% | cursor: pin S wait on X 00000000EA7034E4 3933222116 2025-05-23 11:47:50 2025-05-23 11:47:50 1 1 1
3 .1 1% | 1650815232 2025-05-23 11:47:50 2025-05-23 11:48:00 3 3 3
1 .0 0% | 5 2025-05-23 11:47:58 2025-05-23 11:47:58 1 1 1
1 .0 0% | 100 2025-05-23 11:47:58 2025-05-23 11:47:58 1 1 1
6 rows selected.
--//带入hash值查询：
SYS@book> @ sharepool/shp4 '' 00000000EA7034E4
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 000000008797B2F0 00000000888D8490 SELECT DECODE('A','A','1','2') FROM DUAL 0 0 0 00000000879E8AD0 000000008868C868 69384 8088 3073 80545 80545 3933222116 dyk4dprp70d74 0
parent handle address 00000000888D8490 00000000888D8490 SELECT DECODE('A','A','1','2') FROM DUAL 0 0 0 0000000085B4FC38 00 4736 0 0 4736 4736 3933222116 dyk4dprp70d74 65535
SYS@book> @ sharepool/shp4 '' 00000000AB3CCE91
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000085AF2D48 00000000879EF5C0 Select /*+ cccc */ count(*) from t1 wher 0 0 0 0000000085A55050 0000000089663770 8600 8088 3099 19787 19787 2872888977 5dcmgmypmtmnj 0
parent handle address 00000000879EF5C0 00000000879EF5C0 Select /*+ cccc */ count(*) from t1 wher 0 0 0 000000008588F268 00 4736 0 0 4736 4736 2872888977 5dcmgmypmtmnj 65535
--//前几天在21c下测试表没有分析统计信息大量执行没有使用绑定变量sql语句遇到的情况，导致大量sql语句动态取样，出现等待事件
--//enq: RC - Result Cache: Contention靠前的情况，主要原因是动态执行的sql语句加入了R提示ESULT_CACHE(SNAPSHOT=3600)，
--//oracle的本意开始result cache的处理方式加快动态取样的执行，结果如果大量的文字变量语句将问题集中在其争用上，测试看看
--//以前11g会出现什么情况。
1.环境：
SCOTT@book> @ ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
2.测试环境建立：
SCOTT@book01p> create table t1 as select mod(rownum,1e4) id ,'test' vc from dual connect by level<=1e6;
Table created.
SCOTT@book01p> create index i_t1_id on t1(id);
Index created.
--//注意不分析表，建立索引不能唯一，否则不会执行动态取样。这样的情况仅仅索引有统计信息。
$ cat loope.txt
set verify off
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
--EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t1 where id = :j ' INTO l_count using i;
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t1 where id = ' || i INTO l_count ;
END LOOP;
END;
/
--//注：语句使用文字变量，如果参数2每个会话不同，导致执行的sql语句都是硬解析。
--//create table job_times (sid number, time_ela number,method varchar2(20));
$ cat record.txt
--// arg1 = loop counts ， arg2 = method ， arg3= test scirpt
set verify off
variable v_method varchar2(20)
exec :v_method := (case when '&2' >= '1' and '&2'<='9999' then 'QQQQ' else '&2' end);
define t=&&1;
column 3 new_value 3;
select decode('&3',null,'loop.txt','&&3') "3" from dual;
@@ &&3 5 &&2
--//insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
--//commit ;
@@ &&3 &&t &&2
--//update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method= :v_method;
--//commit;
quit
3.测试：
$ zzdate ; seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @record.txt 1e6 Q loope.txt > /dev/null ; zzdate
trunc(sysdate)+09/24+58/1440+13/86400 1747965493.102152219
--//参数2使用Q代替，这样每个会话执行的sql语句都不同，相当于产生大量的文字变量的sql语句。
4.不等执行完成开始分析：
SYS@book> host sleep 300
SYS@book> @ ashtop event 1=1 trunc(sysdate)+09/24+58/1440+13/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- --------------------------- ------------------- ------------------- ---------- -------- -----------
2423 7.0 70% | 2025-05-23 09:58:14 2025-05-23 10:03:58 29 343 371
967 2.8 28% | latch: shared pool 2025-05-23 09:58:17 2025-05-23 10:03:57 5 292 281
44 .1 1% | library cache: mutex X 2025-05-23 09:58:16 2025-05-23 10:03:56 2 29 27
20 .1 1% | latch: row cache objects 2025-05-23 09:58:14 2025-05-23 10:03:45 1 12 12
5 .0 0% | library cache load lock 2025-05-23 10:00:37 2025-05-23 10:03:38 1 4 4
3 .0 0% | control file parallel write 2025-05-23 09:58:21 2025-05-23 10:03:33 1 3 3
3 .0 0% | cursor: pin S 2025-05-23 10:02:07 2025-05-23 10:02:07 1 1 1
2 .0 0% | db file sequential read 2025-05-23 10:01:06 2025-05-23 10:02:10 2 2 2
1 .0 0% | db file scattered read 2025-05-23 10:02:13 2025-05-23 10:02:13 1 1 1
1 .0 0% | latch: enqueue hash chains 2025-05-23 10:03:47 2025-05-23 10:03:47 1 1 1
10 rows selected.
--//可以发现开始等待事件latch: shared pool排在第一，与21c下的测试enq: RC - Result Cache: Contention排第一不同。
--//如果扫描共享池按执行次数倒排序可以发现：
SCOTT@book> @ sql_id cuzphgv557zkj
-- SQL_ID = cuzphgv557zkj come from shared pool
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS opt_param('parallel_execution_enabled', 'false') NO_PARALLEL(SAMPLESUB) NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1"), NVL(SUM(C3),:"SYS_B_2") FROM (SELECT /*+ NO_PARALLEL("T1") INDEX("T1" I_T1_ID) NO_PARALLEL_INDEX("T1") */ :"SYS_B_3" AS C1, :"SYS_B_4" AS C2, :"SYS_B_5" AS C3 FROM "SCOTT"."T1" "T1" WHERE "T1"."ID"=:"SYS_B_6" AND ROWNUM <= :"SYS_B_7") SAMPLESUB;
SCOTT@book> @ sql_id 2dsmw1hvdhbds
-- SQL_ID = 2dsmw1hvdhbds come from shared pool
SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("T1") FULL("T1") NO_PARALLEL_INDEX("T1") */ :"SYS_B_2" AS C1, CASE WHEN "T1"."ID"=:"SYS_B_3" THEN :"SYS_B_4" ELSE :"SYS_B_5" END AS C2 FROM "SCOTT"."T1" SAMPLE BLOCK (:"SYS_B_6" , :"SYS_B_7") SEED (:"SYS_B_8") "T1") SAMPLESUB;
--//可以发现与21c不同，没有RESULT_CACHE(SNAPSHOT=3600)提示。
--//还可以发现出现另外1个等待事件latch: row cache objects，先放一放，看看library cache: mutex X。
SYS@book> @ ashtop event,p1raw,p1 "event='library cache: mutex X'" trunc(sysdate)+09/24+58/1440+13/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
37 .0 35% | library cache: mutex X 00000000D4387380 3560469376 2025-05-23 09:58:34 2025-05-23 10:11:05 1 22 22
17 .0 16% | library cache: mutex X 00000000DE8BA781 3733694337 2025-05-23 10:00:21 2025-05-23 10:11:03 1 6 6
5 .0 5% | library cache: mutex X 0000000036D82DB8 920137144 2025-05-23 09:58:37 2025-05-23 10:09:42 1 3 3
3 .0 3% | library cache: mutex X 0000000000017CF2 97522 2025-05-23 09:59:01 2025-05-23 09:59:01 1 1 1
3 .0 3% | library cache: mutex X 000000001D5F7CF2 492797170 2025-05-23 10:00:53 2025-05-23 10:07:36 2 3 2
2 .0 2% | library cache: mutex X 00000000CA53FE51 3394502225 2025-05-23 10:11:15 2025-05-23 10:11:15 1 1 1
1 .0 1% | library cache: mutex X 000000000000169E 5790 2025-05-23 10:05:38 2025-05-23 10:05:38 1 1 1
1 .0 1% | library cache: mutex X 000000000000242E 9262 2025-05-23 10:02:03 2025-05-23 10:02:03 1 1 1
1 .0 1% | library cache: mutex X 0000000000006C39 27705 2025-05-23 09:59:31 2025-05-23 09:59:31 1 1 1
1 .0 1% | library cache: mutex X 000000000000A998 43416 2025-05-23 10:05:51 2025-05-23 10:05:51 1 1 1
1 .0 1% | library cache: mutex X 000000000000AC9F 44191 2025-05-23 10:02:51 2025-05-23 10:02:51 1 1 1
1 .0 1% | library cache: mutex X 000000000000B498 46232 2025-05-23 10:09:58 2025-05-23 10:09:58 1 1 1
1 .0 1% | library cache: mutex X 000000000000B55F 46431 2025-05-23 10:09:22 2025-05-23 10:09:22 1 1 1
1 .0 1% | library cache: mutex X 000000000000BBF1 48113 2025-05-23 10:10:10 2025-05-23 10:10:10 1 1 1
1 .0 1% | library cache: mutex X 0000000000013BB0 80816 2025-05-23 10:10:04 2025-05-23 10:10:04 1 1 1
1 .0 1% | library cache: mutex X 00000000000164C1 91329 2025-05-23 10:07:05 2025-05-23 10:07:05 1 1 1
1 .0 1% | library cache: mutex X 0000000000019863 104547 2025-05-23 10:01:29 2025-05-23 10:01:29 1 1 1
1 .0 1% | library cache: mutex X 000000000001CDF0 118256 2025-05-23 10:02:15 2025-05-23 10:02:15 1 1 1
1 .0 1% | library cache: mutex X 000000000001ED78 126328 2025-05-23 10:08:06 2025-05-23 10:08:06 1 1 1
1 .0 1% | library cache: mutex X 00000000186C474C 409749324 2025-05-23 09:58:20 2025-05-23 09:58:20 1 1 1
1 .0 1% | library cache: mutex X 0000000022117ABB 571570875 2025-05-23 10:03:56 2025-05-23 10:03:56 1 1 1
1 .0 1% | library cache: mutex X 00000000466F59BF 1181702591 2025-05-23 10:07:14 2025-05-23 10:07:14 1 1 1
1 .0 1% | library cache: mutex X 0000000046951B7B 1184177019 2025-05-23 10:01:11 2025-05-23 10:01:11 1 1 1
1 .0 1% | library cache: mutex X 00000000597C2F8B 1501310859 2025-05-23 10:09:19 2025-05-23 10:09:19 1 1 1
1 .0 1% | library cache: mutex X 000000005E34F93D 1580529981 2025-05-23 10:07:02 2025-05-23 10:07:02 1 1 1
1 .0 1% | library cache: mutex X 0000000070331D5D 1882398045 2025-05-23 10:01:09 2025-05-23 10:01:09 1 1 1
1 .0 1% | library cache: mutex X 0000000072DEB715 1927198485 2025-05-23 10:06:20 2025-05-23 10:06:20 1 1 1
1 .0 1% | library cache: mutex X 00000000754F6B8C 1968139148 2025-05-23 10:06:36 2025-05-23 10:06:36 1 1 1
1 .0 1% | library cache: mutex X 000000007AA89CD0 2057870544 2025-05-23 10:06:38 2025-05-23 10:06:38 1 1 1
1 .0 1% | library cache: mutex X 00000000967A9FFD 2524618749 2025-05-23 09:59:58 2025-05-23 09:59:58 1 1 1
30 rows selected.
--//前面已经提到11g无法区分在library cache bucket出现的mutex，还是library cache出现的mutex，唯一的线索看看p1是否小于
--//2^17= 131072. 小于131072的大概率是发生在bucket上的mutex。
--//11g这类情况大部分等待还是集中在latch: shared pool。
--//比如 p1raw = 0000000000017CF2 ,000000001D5F7CF2,注意看后4位两者相同。看看是什么对象。
SYS@book> @ kglob '' 492797170 '' ''
==============================
INST_ID : 1
OWNER : SYS
NAME : book
DB_LINK :
NAMESPACE_NUM : DBINSTANCE
NAMESPACE_HEX : 4a
TYPE : CURSOR
SHARABLE_MEM : 0
PERSISTENT_MEM : 0
RUNTIME_MEM : 0
LOADS : 0
EXECUTIONS : 0
LOCKS : 8
PINS : 0
KEPT : NO
CHILD_LATCH : 97522
INVALIDATIONS : 0
HASH_VALUE : 492797170
HASH_HEX : 1d5f7cf2
LOCK_MODE : SHARED
PIN_MODE : NONE
STATUS : UNKOWN
TIMESTAMP :
PREVIOUS_TIMESTAMP :
LOCKED_TOTAL : 4478187
PINNED_TOTAL : 0
PROPERTY :
FULL_HASH_VALUE : d5a4dd9a32c90ace3b8391181d5f7cf2
ADDR : 000000008F980A30
PAR_ADDR : 000000008F980A30
HANDLE_TYPE : parent handle address
KGLOBHD0 : 00
KGLOBHD6 : 00
SQL_ID :
OBJECT_STR : book.SYS.\x4a\0\0\0
PL/SQL procedure successfully completed.
--//我的测试也许会话不多，大部分应该集中的表,实例，schema对象上。那些抓到1次大部分执行的文字变量的sql语句。
5.看看latch: row cache objects等待事件：
SYS@book> @ ashtop event,p1raw,p1 "event='latch: row cache objects'" trunc(sysdate)+09/24+58/1440+13/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
85 .0 38% | latch: row cache objects 000000008C235E48 2351128136 2025-05-23 09:58:25 2025-05-23 10:53:51 1 38 38
58 .0 26% | latch: row cache objects 000000008C135C88 2350079112 2025-05-23 09:58:14 2025-05-23 10:50:54 1 22 22
49 .0 22% | latch: row cache objects 000000008C741568 2356417896 2025-05-23 09:58:56 2025-05-23 10:51:23 1 22 22
24 .0 11% | latch: row cache objects 000000008C339D48 2352192840 2025-05-23 10:03:45 2025-05-23 10:47:16 1 10 10
10 .0 4% | latch: row cache objects 000000008C134140 2350072128 2025-05-23 10:06:47 2025-05-23 10:44:16 1 4 4
SYS@book> @ la 000000008C235E48
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SPINGETS SLEEPS WAIT_TIME
---------------- ---------- ------ ----------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000008C235E48 309 9 row cache objects 21805392 5485 38876 20 36060 2865 35280395
SYS@book> @ la 000000008C741568
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SPINGETS SLEEPS WAIT_TIME
---------------- ---------- ------ ----------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000008C741568 309 4 row cache objects 32460101 729 23794 2 22634 1173 13767705
SYS@book> @ la 000000008C135C88
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SPINGETS SLEEPS WAIT_TIME
---------------- ---------- ------ ----------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000008C135C88 309 8 row cache objects 16422143 451 12115 1 10777 1342 17042941
--//只能看出name='row cache objects'对象的latch，到底什么还是不清楚。
SYS@book> @latchprofx func,laddr % "row cache objects" 400000
-- LatchProfX 2.11 by Tanel Poder ( https://tanelpoder.com )
FUNC LADDR Held Gets Held % Held ms Avg hold ms
---------------------------------------- ---------------- ---------- ---------- ------- ----------- -----------
kqrpre: find obj 000000008C235E48 1156 934 .29 14.566 .016
kqrpre: find obj 000000008C135C88 318 316 .08 4.007 .013
kqrpre: find obj 000000008C741568 294 294 .07 3.704 .013
kqreqd: reget 000000008C235E48 239 214 .06 3.011 .014
kqrpre: find obj 000000008C339D48 227 194 .06 2.860 .015
kqreqd: reget 000000008C135C88 209 209 .05 2.633 .013
kqreqd 000000008C235E48 207 206 .05 2.608 .013
kqreqd 000000008C135C88 192 190 .05 2.419 .013
kqreqd 000000008C741568 174 152 .04 2.192 .014
kqrpre: find obj 000000008C134140 160 160 .04 2.016 .013
kqreqd: reget 000000008C741568 116 116 .03 1.462 .013
kqrso 000000008C339D48 58 44 .01 .731 .017
kqreqd: reget 000000008C134140 53 53 .01 .668 .013
kqreqd 000000008C134140 51 51 .01 .643 .013
kqreqd: reget 000000008C339D48 42 42 .01 .529 .013
kqreqd 000000008C339D48 37 37 .01 .466 .013
kghfrunp: clatch: nowait 000000008C339D48 18 18 .00 .227 .013
kqrsrd 000000008C339D48 3 3 .00 .038 .013
kqrpre: init complete 000000008C339D48 3 3 .00 .038 .013
kqrpre: init complete 000000008C235E48 1 1 .00 .013 .013
20 rows selected.
$ ./lookup.awk kqrpre
kqrpre : kernel query dictionary/row cache read a parent cache object
$ ./lookup.awk kqreqd
kqreqd : kernel query dictionary/row cache enqueue delete
SYS@book> select * from v$latch_misses where parent_name='row cache objects' and WTR_SLP_COUNT>1 order by 4;
PARENT_NAME WHERE NWFAIL_COUNT SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT LOCATION
----------------- --------------------- ------------ ----------- ------------- -------------- ------------------------------
row cache objects kqrsrd 0 2 3 0 kqrsrd
row cache objects kqrpre: init complete 0 19 4 0 kqrpre: init complete
row cache objects kqreqd 0 121 62 0 kqreqd
row cache objects kqrpre: find obj 0 549 18341 0 kqrpre: find obj
row cache objects kqreqd: reget 0 17358 4 0 kqreqd: reget
--//具体是那些对象的细节，还是无法知道。
SYS@book> @latchprofx laddr % "row cache objects" 400000
-- LatchProfX 2.11 by Tanel Poder ( https://tanelpoder.com )
LADDR Held Gets Held % Held ms Avg hold ms
---------------- ---------- ---------- ------- ----------- -----------
000000008C235E48 1507 1267 .38 19.779 .016
000000008C135C88 1265 764 .32 16.603 .022
000000008C741568 848 606 .21 11.130 .018
000000008C134140 325 311 .08 4.266 .014
000000008C339D48 239 236 .06 3.137 .013
SYS@book> select * from x$kqrst where kqrstcln in (9,4,8) and KQRSTGRQ>1000;
ADDR INDX INST_ID KQRSTCID KQRSTSNO KQRSTTYP KQRSTTXT KQRSTCSZ KQRSTOSZ KQRSTFCS KQRSTUSG KQRSTGRQ KQRSTFASTGRQ KQRSTGMI KQRSTSRQ KQRSTSMI KQRSTSCO KQRSTMRQ KQRSTMFL KQRSTCLN KQRSTILR KQRSTIFR KQRSTISR
---------------- ---------- ---------- ---------- ---------- ---------- -------------------- ---------- ---------- ---------- ---------- ---------- ------------ ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000008C63DE70 3 1 2 0 1 dc_segments 2 0 0 2 35108187 0 1478 0 0 0 28 28 4 0 0 0
000000008C63DF90 7 1 10 0 1 dc_users 3 0 0 3 17621959 0 1072 0 0 0 0 0 8 0 0 0
000000008C63DFD8 8 1 8 0 1 dc_objects 167 0 116 167 23650121 0 18621 0 0 0 156 39 9 0 0 0
--//主要还是硬解析导致问题。
6.继续测试：
--//中断前面的测试，分析表后重复测试：
$ zzdate ; seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @record.txt 1e6 Q loope.txt > /dev/null ; zzdate
trunc(sysdate)+11/24+10/1440+22/86400 1747969822.286993725
....
SYS@book> host sleep 300
SYS@book> @ ashtop event 1=1 trunc(sysdate)+11/24+10/1440+22/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
1536 6.4 64% | latch: shared pool 2025-05-23 11:10:23 2025-05-23 11:14:22 2 235 235
760 3.2 32% | 2025-05-23 11:10:23 2025-05-23 11:14:22 30 236 263
92 .4 4% | library cache: mutex X 2025-05-23 11:10:27 2025-05-23 11:14:19 2 27 28
18 .1 1% | latch: row cache objects 2025-05-23 11:10:50 2025-05-23 11:11:56 1 5 5
1 .0 0% | os thread startup 2025-05-23 11:11:22 2025-05-23 11:11:22 1 1 1
SYS@book> @ ashtop event,p1raw,p1 "event='library cache: mutex X'" trunc(sysdate)+11/24+10/1440+22/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
53 .2 55% | library cache: mutex X 0000000000017CF2 97522 2025-05-23 11:10:27 2025-05-23 11:14:57 2 12 10
27 .1 28% | library cache: mutex X 00000000D4387380 3560469376 2025-05-23 11:11:10 2025-05-23 11:14:14 1 14 14
8 .0 8% | library cache: mutex X 000000001D5F7CF2 492797170 2025-05-23 11:10:44 2025-05-23 11:14:14 2 6 6
6 .0 6% | library cache: mutex X 00000000DE8BA781 3733694337 2025-05-23 11:10:58 2025-05-23 11:13:38 1 5 5
3 .0 3% | library cache: mutex X 0000000000007380 29568 2025-05-23 11:13:19 2025-05-23 11:13:19 1 1 1
SYS@book> @ kglob '' 00000000D4387380 '' ''
==============================
INST_ID : 1
OWNER : SCOTT
NAME : T1
DB_LINK :
NAMESPACE_NUM : TABLE/PROCEDURE
NAMESPACE_HEX : 1
TYPE : TABLE
SHARABLE_MEM : 4696
PERSISTENT_MEM : 0
RUNTIME_MEM : 0
LOADS : 4
EXECUTIONS : 0
LOCKS : 5
PINS : 5
KEPT : NO
CHILD_LATCH : 29568
INVALIDATIONS : 0
HASH_VALUE : 3560469376
HASH_HEX : d4387380
LOCK_MODE : SHARED
PIN_MODE : SHARED
STATUS : VALID
TIMESTAMP : 2025-05-23/09:52:30
PREVIOUS_TIMESTAMP :
LOCKED_TOTAL : 7911108
PINNED_TOTAL : 7911105
PROPERTY :
FULL_HASH_VALUE : f1cd2b1c8166d406fc4e5e0fd4387380
ADDR : 0000000087ADDCA0
PAR_ADDR : 0000000087ADDCA0
HANDLE_TYPE : parent handle address
KGLOBHD0 : 000000008885B7C0
KGLOBHD6 : 00
SQL_ID :
OBJECT_STR : T1.SCOTT.\x1\0\0\0
PL/SQL procedure successfully completed.
SYS@book> @ ashtop event,p1raw,p1 "event='latch: row cache objects'" trunc(sysdate)+11/24+10/1440+22/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
13 .0 54% | latch: row cache objects 000000008C135C88 2350079112 2025-05-23 11:10:50 2025-05-23 11:11:56 1 4 4
6 .0 25% | latch: row cache objects 000000008C235E48 2351128136 2025-05-23 11:15:15 2025-05-23 11:16:21 1 2 2
5 .0 21% | latch: row cache objects 000000008C741568 2356417896 2025-05-23 11:11:52 2025-05-23 11:11:52 1 1 1
--//仔细对比发现比前面少2行。
SYS@book> @latchprofx func,laddr % "row cache objects" 400000
-- LatchProfX 2.11 by Tanel Poder ( https://tanelpoder.com )
FUNC LADDR Held Gets Held % Held ms Avg hold ms
---------------------------------------- ---------------- ---------- ---------- ------- ----------- -----------
kqrpre: find obj 000000008C235E48 4473 4382 1.12 33.436 .008
kqrpre: find obj 000000008C135C88 1812 1791 .45 13.545 .008
kqrpre: find obj 000000008C741568 1189 1164 .30 8.888 .008
kqreqd 000000008C235E48 1106 1095 .28 8.267 .008
kqreqd 000000008C135C88 1030 987 .26 7.699 .008
kqreqd: reget 000000008C235E48 861 858 .22 6.436 .008
kqreqd: reget 000000008C135C88 649 646 .16 4.851 .008
kqrpre: find obj 000000008C339D48 631 630 .16 4.717 .007
kqreqd 000000008C741568 421 421 .11 3.147 .007
kqreqd: reget 000000008C741568 350 323 .09 2.616 .008
kqreqd 000000008C339D48 154 154 .04 1.151 .007
kqreqd: reget 000000008C339D48 97 97 .02 .725 .007
kghfrunp: clatch: nowait 000000008C339D48 2 2 .00 .015 .007
kqrpre: init complete 000000008C235E48 1 1 .00 .007 .007
14 rows selected.
7.测试cursor_sharing=force的情况。
--//在执行脚本record.txt 开头加入 alter session set cursor_sharing=force;
$ zzdate ; seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @record.txt 1e6 BBBB loope.txt > /dev/null ; zzdate
trunc(sysdate)+11/24+24/1440+50/86400 -1747970690.472024012
trunc(sysdate)+11/24+26/1440+57/86400 1747970817.269232887
--//Sum = 126.797208875
--//参数2使用BBBB，这样每个会话执行的sql语句都一样在cursor_sharing=force的情况下相同的.
SYS@book> @ ashtop event 1=1 trunc(sysdate)+11/24+24/1440+50/86400 trunc(sysdate)+11/24+26/1440+57/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----------------------- ------------------- ------------------- ---------- -------- -----------
581 4.6 46% | 2025-05-23 11:24:51 2025-05-23 11:26:56 214 119 313
509 4.0 40% | library cache: mutex X 2025-05-23 11:24:52 2025-05-23 11:26:56 11 121 80
130 1.0 10% | library cache load lock 2025-05-23 11:24:51 2025-05-23 11:26:56 10 58 10
16 .1 1% | cursor: mutex S 2025-05-23 11:25:05 2025-05-23 11:26:36 1 10 10
10 .1 1% | cursor: pin S 2025-05-23 11:24:52 2025-05-23 11:26:17 1 8 8
10 .1 1% | latch: shared pool 2025-05-23 11:25:17 2025-05-23 11:26:56 1 4 4
2 .0 0% | ADR block file read 2025-05-23 11:24:50 2025-05-23 11:24:50 2 1 2
7 rows selected.
SYS@book> @ ashtop event,p1raw,p1 "event='library cache: mutex X'" trunc(sysdate)+11/24+24/1440+50/86400 trunc(sysdate)+11/24+26/1440+57/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------------------- ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
321 2.5 63% | library cache: mutex X 00000000000079B7 31159 2025-05-23 11:24:52 2025-05-23 11:26:55 10 98 10
136 1.1 27% | library cache: mutex X 00000000F94879B7 4182276535 2025-05-23 11:24:52 2025-05-23 11:26:55 10 77 79
--//以上2项p1raw的后4位相同。
5 .0 1% | library cache: mutex X 000000000000DC89 56457 2025-05-23 11:25:27 2025-05-23 11:25:27 5 1 5
4 .0 1% | library cache: mutex X 00000000746B5BFF 1953192959 2025-05-23 11:26:33 2025-05-23 11:26:33 4 1 4
3 .0 1% | library cache: mutex X 000000007128E72C 1898506028 2025-05-23 11:24:59 2025-05-23 11:24:59 3 1 3
2 .0 0% | library cache: mutex X 0000000009B4203C 162799676 2025-05-23 11:26:10 2025-05-23 11:26:10 2 1 2
2 .0 0% | library cache: mutex X 0000000044BD6613 1153263123 2025-05-23 11:26:08 2025-05-23 11:26:08 2 1 2
2 .0 0% | library cache: mutex X 000000005B930106 1536360710 2025-05-23 11:26:47 2025-05-23 11:26:47 2 1 2
2 .0 0% | library cache: mutex X 00000000686AB267 1751822951 2025-05-23 11:26:40 2025-05-23 11:26:40 2 1 2
2 .0 0% | library cache: mutex X 000000007C87B954 2089269588 2025-05-23 11:26:31 2025-05-23 11:26:31 2 1 2
2 .0 0% | library cache: mutex X 00000000ABC256DC 2881640156 2025-05-23 11:25:26 2025-05-23 11:25:26 2 1 2
2 .0 0% | library cache: mutex X 00000000B82F1059 3090092121 2025-05-23 11:26:22 2025-05-23 11:26:22 2 1 2
2 .0 0% | library cache: mutex X 00000000EB794757 3950593879 2025-05-23 11:25:34 2025-05-23 11:25:34 2 1 2
2 .0 0% | library cache: mutex X 00000000FF6A08C8 4285139144 2025-05-23 11:26:42 2025-05-23 11:26:42 2 1 2
1 .0 0% | library cache: mutex X 00000000000008A9 2217 2025-05-23 11:25:21 2025-05-23 11:25:21 1 1 1
1 .0 0% | library cache: mutex X 0000000000005CB5 23733 2025-05-23 11:26:21 2025-05-23 11:26:21 1 1 1
1 .0 0% | library cache: mutex X 000000000000C3BF 50111 2025-05-23 11:26:48 2025-05-23 11:26:48 1 1 1
1 .0 0% | library cache: mutex X 000000000000E417 58391 2025-05-23 11:24:55 2025-05-23 11:24:55 1 1 1
1 .0 0% | library cache: mutex X 00000000000115F7 71159 2025-05-23 11:26:47 2025-05-23 11:26:47 1 1 1
1 .0 0% | library cache: mutex X 000000000001EE61 126561 2025-05-23 11:25:00 2025-05-23 11:25:00 1 1 1
1 .0 0% | library cache: mutex X 000000000001FD5A 130394 2025-05-23 11:26:56 2025-05-23 11:26:56 1 1 1
1 .0 0% | library cache: mutex X 0000000006C8E334 113828660 2025-05-23 11:25:30 2025-05-23 11:25:30 1 1 1
1 .0 0% | library cache: mutex X 000000001DC9B286 499757702 2025-05-23 11:26:07 2025-05-23 11:26:07 1 1 1
1 .0 0% | library cache: mutex X 0000000021805EA8 562060968 2025-05-23 11:25:07 2025-05-23 11:25:07 1 1 1
1 .0 0% | library cache: mutex X 00000000284B9893 676042899 2025-05-23 11:25:10 2025-05-23 11:25:10 1 1 1
1 .0 0% | library cache: mutex X 00000000472AD658 1193989720 2025-05-23 11:25:10 2025-05-23 11:25:10 1 1 1
1 .0 0% | library cache: mutex X 000000005DF6EF52 1576464210 2025-05-23 11:26:51 2025-05-23 11:26:51 1 1 1
1 .0 0% | library cache: mutex X 000000007234A436 1916052534 2025-05-23 11:26:10 2025-05-23 11:26:10 1 1 1
1 .0 0% | library cache: mutex X 0000000076492598 1984505240 2025-05-23 11:24:59 2025-05-23 11:24:59 1 1 1
1 .0 0% | library cache: mutex X 000000007BF86079 2079875193 2025-05-23 11:26:40 2025-05-23 11:26:40 1 1 1
30 rows selected.
SYS@book> @ sharepool/shp4 '' 00000000F94879B7
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000085B4BE88 00000000879F8278 Select /*+ BBBB */ count(*) from t1 wher 0 0 0 0000000088B81168 000000008567A770 4528 8088 3114 15730 15730 4182276535 5bfgs3zwnhydr 0
parent handle address 00000000879F8278 00000000879F8278 Select /*+ BBBB */ count(*) from t1 wher 0 0 0 0000000087B232C0 00 4752 0 0 4752 4752 4182276535 5bfgs3zwnhydr 65535
--//这是我以前没有测试的情况,在cursor_sharing=force的情况下,靠前的等待事件竟然是library cache: mutex X,以前如果使用绑定
--//变量的情况是cursor: pin S.为什么?另外写一篇分析.
--//也可以说明一点，实际上通过cursor_sharing=force, 实际上在许多地方存在mutex地址，而真正的绑定变量仅仅在子游标的堆0。
SYS@book> @ mutexprofz idn,loc,maddr "ts>=trunc(sysdate)+11/24+37/1440+06/86400 and hash=4182276535"
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 50 sleeps...
-- column info : id idn hash hash_value=>hash_value ts=>sleep_timestamp
-- req=>requesting_session blk=>blocking_session val=>mutex_value maddr=>mutex_addr
SUM_SLEEPS GETS_DIFF MUTEX_TYPE IDN GET_LOCATION mutex_addr SQL_ID OBJECT_NAME
---------- -------------- --------------- ---------- --------------------------------- -------------------- ------------- --------------------------------------------------------------------------------
34480 20698 Library Cache 4182276535 kglhdgh1 64 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
25395 16909 Library Cache 4182276535 kgllkc1 57 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
16957 30539 Library Cache 4182276535 kgllkdl1 85 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
8860 Library Cache 4182276535 kgllkdl1 85 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
7837 141660 Cursor Pin 4182276535 kksLockDelete [KKSCHLPIN6] 000000008567A6C8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
3512 134173 Cursor Pin 4182276535 kkslce [KKSCHLPIN2] 000000008567A6C8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
3186 289478 hash table 4182276535 kkshGetNextChild [KKSHBKLOC1] 000000008567A308 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
4 Library Cache 4182276535 kglReleaseHandleReference 125 00000000879F83B8 5bfgs3zwnhydr Select /*+ BBBB */ count(*) from t1 where id = :"SYS_B_0"
8 rows selected.
--//00000000879F83B8-00000000879F8248 = 0x170
--//00000000879F83B8-00000000879F8278 = 0x140 = 320
--//父游标句柄偏移0x140=320.
SYS@book> @ fchaz 00000000879F83B8
GET_LOCATION KSMCHPTR KSMCHIDX KSMCHDUR KSMCHCOM KSMCHSIZ KSMCHCLS KSMCHTYP KSMCHPAR KSMCHPTR_BEGIN KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA 00000000879F8248 1 2 KGLHD 592 recr 80 00 00000000879F8248 00000000879F8498
--//位于父游标里面。
--//采用绑定变量，注解脚本record.txt 开头加入 alter session set cursor_sharing=force;。
--//改写loope.txt使用绑定变量。
$ cat loope.txt
set verify off
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t1 where id = :j ' INTO l_count using i;
--EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t1 where id = ' || i INTO l_count ;
END LOOP;
END;
/
$ zzdate ; seq 10 | xargs -IQ -P 10 sqlplus -s -l scott/book @record.txt 1e6 cccc loope.txt > /dev/null ; zzdate
trunc(sysdate)+11/24+47/1440+50/86400 -1747972070.393439049
trunc(sysdate)+11/24+48/1440+40/86400 1747972120.258478330
--//Sum = 49.865039281
--//类似的测试50秒完成。
SYS@book> @ ashtop event,p1raw,p1 1=1 trunc(sysdate)+11/24+47/1440+50/86400 trunc(sysdate)+11/24+48/1440+40/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW P1 FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----------------------- ----------------- ---------- ------------------- ------------------- ---------- -------- -----------
384 7.7 79% | 2872888977 2025-05-23 11:47:51 2025-05-23 11:48:39 201 49 245
95 1.9 19% | cursor: pin S 00000000AB3CCE91 2872888977 2025-05-23 11:47:52 2025-05-23 11:48:37 1 35 35
5 .1 1% | cursor: pin S wait on X 00000000EA7034E4 3933222116 2025-05-23 11:47:50 2025-05-23 11:47:50 1 1 1
3 .1 1% | 1650815232 2025-05-23 11:47:50 2025-05-23 11:48:00 3 3 3
1 .0 0% | 5 2025-05-23 11:47:58 2025-05-23 11:47:58 1 1 1
1 .0 0% | 100 2025-05-23 11:47:58 2025-05-23 11:47:58 1 1 1
6 rows selected.
--//带入hash值查询：
SYS@book> @ sharepool/shp4 '' 00000000EA7034E4
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 000000008797B2F0 00000000888D8490 SELECT DECODE('A','A','1','2') FROM DUAL 0 0 0 00000000879E8AD0 000000008868C868 69384 8088 3073 80545 80545 3933222116 dyk4dprp70d74 0
parent handle address 00000000888D8490 00000000888D8490 SELECT DECODE('A','A','1','2') FROM DUAL 0 0 0 0000000085B4FC38 00 4736 0 0 4736 4736 3933222116 dyk4dprp70d74 65535
SYS@book> @ sharepool/shp4 '' 00000000AB3CCE91
HANDLE_TYPE KGLHDADR KGLHDPAR C40 KGLHDLMD KGLHDPMD KGLHDIVC KGLOBHD0 KGLOBHD6 KGLOBHS0 KGLOBHS6 KGLOBT16 N0_6_16 N20 KGLNAHSH KGLOBT03 KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address 0000000085AF2D48 00000000879EF5C0 Select /*+ cccc */ count(*) from t1 wher 0 0 0 0000000085A55050 0000000089663770 8600 8088 3099 19787 19787 2872888977 5dcmgmypmtmnj 0
parent handle address 00000000879EF5C0 00000000879EF5C0 Select /*+ cccc */ count(*) from t1 wher 0 0 0 000000008588F268 00 4736 0 0 4736 4736 2872888977 5dcmgmypmtmnj 65535
浙公网安备 33010602011771号