[20241123]11g下测试遇到latch shared pool等待事件问题.txt
[20241123]11g下测试遇到latch shared pool等待事件问题.txt
--//这是昨天测试遇到的问题，实际上以前也遇到，没有仔细探究。以前的方法就是启动后做小量延迟，规避这个问题,实际上还是出现。
--//这次测试我总感觉哪里做的不对，仔细分析看看。
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.建立测试环境：
create table job_times (sid number, time_ela number,method varchar2(20));
drop table t purge ;
create table t as select rownum id ,'test' pad from dual connect by level<=5e5;
create unique index pk_t on t(id);
exec dbms_stats.gather_table_stats(user, 't', method_opt=>'for all columns size 1');
$ cat m9.txt
set verify off
variable v_method varchar2(20)
exec :v_method := '&&2';
--host sleep $((&&2/100|bc -l))
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
--insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
commit ;
--select sysdate from dual ;
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method= :v_method;
commit;
quit
--//如果参数2带入参数不同，开始执行瞬间基本全是硬解析，insert语句也是。导致测试前面出现latch shared pool等待事件应该正常。
--//但是我发现21c这样测试并没有出现，而11g出现很多，难道oracle 21c做了什么改进，先测试在11g的情况。
SCOTT@book> delete from job_times ;
60 rows deleted.
SCOTT@book> commit ;
Commit complete.
SYS@book> alter system flush shared_pool;
System altered.
SYS@book> alter system flush shared_pool;
System altered.
--//为了保证测试的重复性每次执行前刷新共享池。
3.测试：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+10/24+08/1440+59/86400
trunc(sysdate)+10/24+09/1440+48/86400
SYS@book> @ ashtop event,p1raw 1=1 trunc(sysdate)+10/24+08/1440+59/86400 trunc(sysdate)+10/24+09/1440+48/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ------------------- ------------------- ---------- -------- -----------
445 9.1 46% | 2024-11-23 10:08:59 2024-11-23 10:09:47 221 49 268
300 6.1 31% | resmgr:cpu quantum 0000000000000003 2024-11-23 10:09:01 2024-11-23 10:09:47 3 41 3
190 3.9 20% | latch: shared pool 000000006010DE50 2024-11-23 10:09:02 2024-11-23 10:09:43 1 26 26
17 .3 2% | resmgr:cpu quantum 0000000000000002 2024-11-23 10:09:00 2024-11-23 10:09:47 4 4 7
4 .1 0% | cursor: pin S wait on X 00000000367D06A6 2024-11-23 10:08:59 2024-11-23 10:08:59 1 1 1
1 .0 0% | control file parallel write 0000000000000002 2024-11-23 10:09:01 2024-11-23 10:09:01 1 1 1
1 .0 0% | cursor: pin S wait on X 0000000010439DEE 2024-11-23 10:08:59 2024-11-23 10:08:59 1 1 1
1 .0 0% | library cache load lock 0000000085E91AA0 2024-11-23 10:08:59 2024-11-23 10:08:59 1 1 1
8 rows selected.
--//latch: shared pool到达190秒。
SYS@book> @ la 000000006010DE50
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SPINGETS SLEEPS WAIT_TIME
---------------- ---------- ------ --------------------------------------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000006010DE50 336 1 shared pool 20422610 0 3350915 0 3342509 8864 337481310
--//我的测试环境配置内存不是很大，仅仅存在1个shared pool latch。
SYS@book> select addr,gets from v$latch_children where name like 'shared pool';
ADDR GETS
---------------- ----------
000000006010E210 56
000000006010E170 56
000000006010E0D0 56
000000006010E030 56
000000006010DF90 56
000000006010DEF0 56
000000006010DE50 20426597
7 rows selected.
--//其他gets很少。
--//根据前面m9.txt脚本，出现大量硬解析仅仅出现在测试开始。
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+10/24+08/1440+59/86400
trunc(sysdate)+10/24+09/1440+48/86400
SYS@book> @ ashtop sample_time "event='latch: shared pool'" trunc(sysdate)+10/24+08/1440+59/86400 trunc(sysdate)+10/24+09/1440+48/86400
Total Distinct Distinct Distinct
Seconds AAS %This SAMPLE_TIME FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----------------------- ------------------- ------------------- ---------- -------- -----------
15 .3 8% | 2024-11-23 10:09:11.821 2024-11-23 10:09:11 2024-11-23 10:09:11 1 1 1
15 .3 8% | 2024-11-23 10:09:27.831 2024-11-23 10:09:27 2024-11-23 10:09:27 1 1 1
14 .3 7% | 2024-11-23 10:09:02.811 2024-11-23 10:09:02 2024-11-23 10:09:02 1 1 1
14 .3 7% | 2024-11-23 10:09:24.821 2024-11-23 10:09:24 2024-11-23 10:09:24 1 1 1
14 .3 7% | 2024-11-23 10:09:39.831 2024-11-23 10:09:39 2024-11-23 10:09:39 1 1 1
13 .3 7% | 2024-11-23 10:09:07.821 2024-11-23 10:09:07 2024-11-23 10:09:07 1 1 1
13 .3 7% | 2024-11-23 10:09:22.821 2024-11-23 10:09:22 2024-11-23 10:09:22 1 1 1
12 .2 6% | 2024-11-23 10:09:33.831 2024-11-23 10:09:33 2024-11-23 10:09:33 1 1 1
10 .2 5% | 2024-11-23 10:09:35.831 2024-11-23 10:09:35 2024-11-23 10:09:35 1 1 1
9 .2 5% | 2024-11-23 10:09:05.821 2024-11-23 10:09:05 2024-11-23 10:09:05 1 1 1
9 .2 5% | 2024-11-23 10:09:14.821 2024-11-23 10:09:14 2024-11-23 10:09:14 1 1 1
9 .2 5% | 2024-11-23 10:09:15.821 2024-11-23 10:09:15 2024-11-23 10:09:15 1 1 1
6 .1 3% | 2024-11-23 10:09:19.821 2024-11-23 10:09:19 2024-11-23 10:09:19 1 1 1
5 .1 3% | 2024-11-23 10:09:06.821 2024-11-23 10:09:06 2024-11-23 10:09:06 1 1 1
5 .1 3% | 2024-11-23 10:09:38.831 2024-11-23 10:09:38 2024-11-23 10:09:38 1 1 1
4 .1 2% | 2024-11-23 10:09:16.821 2024-11-23 10:09:16 2024-11-23 10:09:16 1 1 1
3 .1 2% | 2024-11-23 10:09:09.821 2024-11-23 10:09:09 2024-11-23 10:09:09 1 1 1
3 .1 2% | 2024-11-23 10:09:20.821 2024-11-23 10:09:20 2024-11-23 10:09:20 1 1 1
3 .1 2% | 2024-11-23 10:09:21.821 2024-11-23 10:09:21 2024-11-23 10:09:21 1 1 1
3 .1 2% | 2024-11-23 10:09:23.821 2024-11-23 10:09:23 2024-11-23 10:09:23 1 1 1
2 .0 1% | 2024-11-23 10:09:31.831 2024-11-23 10:09:31 2024-11-23 10:09:31 1 1 1
2 .0 1% | 2024-11-23 10:09:36.831 2024-11-23 10:09:36 2024-11-23 10:09:36 1 1 1
2 .0 1% | 2024-11-23 10:09:37.831 2024-11-23 10:09:37 2024-11-23 10:09:37 1 1 1
2 .0 1% | 2024-11-23 10:09:42.831 2024-11-23 10:09:42 2024-11-23 10:09:42 1 1 1
2 .0 1% | 2024-11-23 10:09:43.831 2024-11-23 10:09:43 2024-11-23 10:09:43 1 1 1
1 .0 1% | 2024-11-23 10:09:17.821 2024-11-23 10:09:17 2024-11-23 10:09:17 1 1 1
26 rows selected.
2024-11-23 10:09:02.811
2024-11-23 10:09:05.821
2024-11-23 10:09:06.821
2024-11-23 10:09:07.821
2024-11-23 10:09:09.821
2024-11-23 10:09:11.821
2024-11-23 10:09:14.821
2024-11-23 10:09:15.821
2024-11-23 10:09:16.821
2024-11-23 10:09:17.821
2024-11-23 10:09:19.821
2024-11-23 10:09:20.821
2024-11-23 10:09:21.821
2024-11-23 10:09:22.821
2024-11-23 10:09:23.821
2024-11-23 10:09:24.821
2024-11-23 10:09:27.831
2024-11-23 10:09:31.831
2024-11-23 10:09:33.831
2024-11-23 10:09:35.831
2024-11-23 10:09:36.831
2024-11-23 10:09:37.831
2024-11-23 10:09:38.831
2024-11-23 10:09:39.831
2024-11-23 10:09:42.831
2024-11-23 10:09:43.831
--//单独取出SAMPLE_TIME排序，并没有出现在开头，而是出现在09：02-09：43范围内，这就解析不通了。
SYS@book> @ ashtop sid,module "event='latch: shared pool'" trunc(sysdate)+10/24+08/1440+59/86400 trunc(sysdate)+10/24+09/1440+48/86400
Total Distinct Distinct Distinct
Seconds AAS %This SID MODULE FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------- ------------ ------------------- ------------------- ---------- -------- -----------
14 .3 7% | 13 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 14 14
13 .3 7% | 196 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 13 13
12 .2 6% | 132 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:42 1 12 12
12 .2 6% | 197 SQL*Plus 2024-11-23 10:09:06 2024-11-23 10:09:43 1 12 12
11 .2 6% | 68 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 11 11
11 .2 6% | 137 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 11 11
10 .2 5% | 18 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 10 10
10 .2 5% | 195 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 10 10
10 .2 5% | 199 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:43 1 10 10
9 .2 5% | 7 SQL*Plus 2024-11-23 10:09:05 2024-11-23 10:09:39 1 9 9
9 .2 5% | 16 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:35 1 9 9
8 .2 4% | 12 SQL*Plus 2024-11-23 10:09:07 2024-11-23 10:09:39 1 8 8
8 .2 4% | 72 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:38 1 8 8
8 .2 4% | 74 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 8 8
8 .2 4% | 75 SQL*Plus 2024-11-23 10:09:05 2024-11-23 10:09:27 1 8 8
8 .2 4% | 140 SQL*Plus 2024-11-23 10:09:05 2024-11-23 10:09:39 1 8 8
8 .2 4% | 192 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:37 1 8 8
7 .1 4% | 9 SQL*Plus 2024-11-23 10:09:11 2024-11-23 10:09:39 1 7 7
7 .1 4% | 133 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:33 1 7 7
7 .1 4% | 134 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:35 1 7 7
20 rows selected.
--//正好20行，确实测试程序执行的。
--//我取消以下注解
--host sleep $((&&2/100|bc -l))
--//问题还是一样，说明我以前的测试并没有规避这个问题,以前的测试疏忽了，注意测试前一定要刷新共享池，看后面的测试就明白为
--//什么。也许以前的测试忘记做刷新共享池这步，以为小量延迟后问题消失。
--//我开始也怀疑resmgr:cpu quantum导致，仔细想想不应该。
--//当我将insert采用绑定变量写法后，问题依旧。
--insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
--//定下心来思考，理论在测试的中间不会出现latch: shared pool等待事情，sql语句也不会产生子光标，应该是执行第1次执行如下是
--//硬解析。
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
--//在等待事件中记录的是latch: shared pool，后面几次执行后马上软软解析。
--//而ash在取样是还是取到latch: shared pool等待事件，这样才会出现前面ashtop输出的奇葩情况。
--//注实际上有几次测试我忘记刷新共享池，发现latch: shared pool消失，这才想起问题匿名PLSQL代码循环体执行sql语句第1次是硬
--//解析,就会出现这样的情况。而且只有这样解析才解析的通。
--//修改如下：
$ cat m9.txt
set verify off
variable v_method varchar2(20)
exec :v_method := '&&2';
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
--host sleep $((&&2/100|bc -l))
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
--insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
commit ;
--select sysdate from dual ;
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method= :v_method;
commit;
quit
--//先循环1次就可以规避这个问题。
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+11/24+40/1440+35/86400
trunc(sysdate)+11/24+41/1440+22/86400
SYS@book> @ ashtop event 1=1 trunc(sysdate)+11/24+40/1440+35/86400 trunc(sysdate)+11/24+41/1440+22/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
655 13.9 72% | resmgr:cpu quantum 2024-11-23 11:40:36 2024-11-23 11:41:20 8 45 11
237 5.0 26% | 2024-11-23 11:40:36 2024-11-23 11:41:21 128 46 164
6 .1 1% | cursor: pin S wait on X 2024-11-23 11:40:35 2024-11-23 11:40:35 1 1 1
6 .1 1% | log file sync 2024-11-23 11:40:37 2024-11-23 11:41:21 1 3 3
1 .0 0% | control file parallel write 2024-11-23 11:40:59 2024-11-23 11:40:59 1 1 1
1 .0 0% | kksfbc child completion 2024-11-23 11:40:35 2024-11-23 11:40:35 1 1 1
6 rows selected.
--//不再出现latch: shared pool等待事情，我反复测试多次，结果都是一样。
4.总结：
--//感觉应该算11g的bug，不过我的测试是一个循环，非常特殊。
--//以前确实没有仔细查看一些细节，也许这样问题早就能发现。
--//这是昨天测试遇到的问题，实际上以前也遇到，没有仔细探究。以前的方法就是启动后做小量延迟，规避这个问题,实际上还是出现。
--//这次测试我总感觉哪里做的不对，仔细分析看看。
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.建立测试环境：
create table job_times (sid number, time_ela number,method varchar2(20));
drop table t purge ;
create table t as select rownum id ,'test' pad from dual connect by level<=5e5;
create unique index pk_t on t(id);
exec dbms_stats.gather_table_stats(user, 't', method_opt=>'for all columns size 1');
$ cat m9.txt
set verify off
variable v_method varchar2(20)
exec :v_method := '&&2';
--host sleep $((&&2/100|bc -l))
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
--insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
commit ;
--select sysdate from dual ;
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method= :v_method;
commit;
quit
--//如果参数2带入参数不同，开始执行瞬间基本全是硬解析，insert语句也是。导致测试前面出现latch shared pool等待事件应该正常。
--//但是我发现21c这样测试并没有出现，而11g出现很多，难道oracle 21c做了什么改进，先测试在11g的情况。
SCOTT@book> delete from job_times ;
60 rows deleted.
SCOTT@book> commit ;
Commit complete.
SYS@book> alter system flush shared_pool;
System altered.
SYS@book> alter system flush shared_pool;
System altered.
--//为了保证测试的重复性每次执行前刷新共享池。
3.测试：
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+10/24+08/1440+59/86400
trunc(sysdate)+10/24+09/1440+48/86400
SYS@book> @ ashtop event,p1raw 1=1 trunc(sysdate)+10/24+08/1440+59/86400 trunc(sysdate)+10/24+09/1440+48/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1RAW FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ------------------- ------------------- ---------- -------- -----------
445 9.1 46% | 2024-11-23 10:08:59 2024-11-23 10:09:47 221 49 268
300 6.1 31% | resmgr:cpu quantum 0000000000000003 2024-11-23 10:09:01 2024-11-23 10:09:47 3 41 3
190 3.9 20% | latch: shared pool 000000006010DE50 2024-11-23 10:09:02 2024-11-23 10:09:43 1 26 26
17 .3 2% | resmgr:cpu quantum 0000000000000002 2024-11-23 10:09:00 2024-11-23 10:09:47 4 4 7
4 .1 0% | cursor: pin S wait on X 00000000367D06A6 2024-11-23 10:08:59 2024-11-23 10:08:59 1 1 1
1 .0 0% | control file parallel write 0000000000000002 2024-11-23 10:09:01 2024-11-23 10:09:01 1 1 1
1 .0 0% | cursor: pin S wait on X 0000000010439DEE 2024-11-23 10:08:59 2024-11-23 10:08:59 1 1 1
1 .0 0% | library cache load lock 0000000085E91AA0 2024-11-23 10:08:59 2024-11-23 10:08:59 1 1 1
8 rows selected.
--//latch: shared pool到达190秒。
SYS@book> @ la 000000006010DE50
ADDR LATCH# CHLD NAME GETS IGETS MISSES IMISSES SPINGETS SLEEPS WAIT_TIME
---------------- ---------- ------ --------------------------------------------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
000000006010DE50 336 1 shared pool 20422610 0 3350915 0 3342509 8864 337481310
--//我的测试环境配置内存不是很大，仅仅存在1个shared pool latch。
SYS@book> select addr,gets from v$latch_children where name like 'shared pool';
ADDR GETS
---------------- ----------
000000006010E210 56
000000006010E170 56
000000006010E0D0 56
000000006010E030 56
000000006010DF90 56
000000006010DEF0 56
000000006010DE50 20426597
7 rows selected.
--//其他gets很少。
--//根据前面m9.txt脚本，出现大量硬解析仅仅出现在测试开始。
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+10/24+08/1440+59/86400
trunc(sysdate)+10/24+09/1440+48/86400
SYS@book> @ ashtop sample_time "event='latch: shared pool'" trunc(sysdate)+10/24+08/1440+59/86400 trunc(sysdate)+10/24+09/1440+48/86400
Total Distinct Distinct Distinct
Seconds AAS %This SAMPLE_TIME FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ----------------------- ------------------- ------------------- ---------- -------- -----------
15 .3 8% | 2024-11-23 10:09:11.821 2024-11-23 10:09:11 2024-11-23 10:09:11 1 1 1
15 .3 8% | 2024-11-23 10:09:27.831 2024-11-23 10:09:27 2024-11-23 10:09:27 1 1 1
14 .3 7% | 2024-11-23 10:09:02.811 2024-11-23 10:09:02 2024-11-23 10:09:02 1 1 1
14 .3 7% | 2024-11-23 10:09:24.821 2024-11-23 10:09:24 2024-11-23 10:09:24 1 1 1
14 .3 7% | 2024-11-23 10:09:39.831 2024-11-23 10:09:39 2024-11-23 10:09:39 1 1 1
13 .3 7% | 2024-11-23 10:09:07.821 2024-11-23 10:09:07 2024-11-23 10:09:07 1 1 1
13 .3 7% | 2024-11-23 10:09:22.821 2024-11-23 10:09:22 2024-11-23 10:09:22 1 1 1
12 .2 6% | 2024-11-23 10:09:33.831 2024-11-23 10:09:33 2024-11-23 10:09:33 1 1 1
10 .2 5% | 2024-11-23 10:09:35.831 2024-11-23 10:09:35 2024-11-23 10:09:35 1 1 1
9 .2 5% | 2024-11-23 10:09:05.821 2024-11-23 10:09:05 2024-11-23 10:09:05 1 1 1
9 .2 5% | 2024-11-23 10:09:14.821 2024-11-23 10:09:14 2024-11-23 10:09:14 1 1 1
9 .2 5% | 2024-11-23 10:09:15.821 2024-11-23 10:09:15 2024-11-23 10:09:15 1 1 1
6 .1 3% | 2024-11-23 10:09:19.821 2024-11-23 10:09:19 2024-11-23 10:09:19 1 1 1
5 .1 3% | 2024-11-23 10:09:06.821 2024-11-23 10:09:06 2024-11-23 10:09:06 1 1 1
5 .1 3% | 2024-11-23 10:09:38.831 2024-11-23 10:09:38 2024-11-23 10:09:38 1 1 1
4 .1 2% | 2024-11-23 10:09:16.821 2024-11-23 10:09:16 2024-11-23 10:09:16 1 1 1
3 .1 2% | 2024-11-23 10:09:09.821 2024-11-23 10:09:09 2024-11-23 10:09:09 1 1 1
3 .1 2% | 2024-11-23 10:09:20.821 2024-11-23 10:09:20 2024-11-23 10:09:20 1 1 1
3 .1 2% | 2024-11-23 10:09:21.821 2024-11-23 10:09:21 2024-11-23 10:09:21 1 1 1
3 .1 2% | 2024-11-23 10:09:23.821 2024-11-23 10:09:23 2024-11-23 10:09:23 1 1 1
2 .0 1% | 2024-11-23 10:09:31.831 2024-11-23 10:09:31 2024-11-23 10:09:31 1 1 1
2 .0 1% | 2024-11-23 10:09:36.831 2024-11-23 10:09:36 2024-11-23 10:09:36 1 1 1
2 .0 1% | 2024-11-23 10:09:37.831 2024-11-23 10:09:37 2024-11-23 10:09:37 1 1 1
2 .0 1% | 2024-11-23 10:09:42.831 2024-11-23 10:09:42 2024-11-23 10:09:42 1 1 1
2 .0 1% | 2024-11-23 10:09:43.831 2024-11-23 10:09:43 2024-11-23 10:09:43 1 1 1
1 .0 1% | 2024-11-23 10:09:17.821 2024-11-23 10:09:17 2024-11-23 10:09:17 1 1 1
26 rows selected.
2024-11-23 10:09:02.811
2024-11-23 10:09:05.821
2024-11-23 10:09:06.821
2024-11-23 10:09:07.821
2024-11-23 10:09:09.821
2024-11-23 10:09:11.821
2024-11-23 10:09:14.821
2024-11-23 10:09:15.821
2024-11-23 10:09:16.821
2024-11-23 10:09:17.821
2024-11-23 10:09:19.821
2024-11-23 10:09:20.821
2024-11-23 10:09:21.821
2024-11-23 10:09:22.821
2024-11-23 10:09:23.821
2024-11-23 10:09:24.821
2024-11-23 10:09:27.831
2024-11-23 10:09:31.831
2024-11-23 10:09:33.831
2024-11-23 10:09:35.831
2024-11-23 10:09:36.831
2024-11-23 10:09:37.831
2024-11-23 10:09:38.831
2024-11-23 10:09:39.831
2024-11-23 10:09:42.831
2024-11-23 10:09:43.831
--//单独取出SAMPLE_TIME排序，并没有出现在开头，而是出现在09：02-09：43范围内，这就解析不通了。
SYS@book> @ ashtop sid,module "event='latch: shared pool'" trunc(sysdate)+10/24+08/1440+59/86400 trunc(sysdate)+10/24+09/1440+48/86400
Total Distinct Distinct Distinct
Seconds AAS %This SID MODULE FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ---------- ------------ ------------------- ------------------- ---------- -------- -----------
14 .3 7% | 13 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 14 14
13 .3 7% | 196 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 13 13
12 .2 6% | 132 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:42 1 12 12
12 .2 6% | 197 SQL*Plus 2024-11-23 10:09:06 2024-11-23 10:09:43 1 12 12
11 .2 6% | 68 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 11 11
11 .2 6% | 137 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 11 11
10 .2 5% | 18 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 10 10
10 .2 5% | 195 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 10 10
10 .2 5% | 199 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:43 1 10 10
9 .2 5% | 7 SQL*Plus 2024-11-23 10:09:05 2024-11-23 10:09:39 1 9 9
9 .2 5% | 16 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:35 1 9 9
8 .2 4% | 12 SQL*Plus 2024-11-23 10:09:07 2024-11-23 10:09:39 1 8 8
8 .2 4% | 72 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:38 1 8 8
8 .2 4% | 74 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:39 1 8 8
8 .2 4% | 75 SQL*Plus 2024-11-23 10:09:05 2024-11-23 10:09:27 1 8 8
8 .2 4% | 140 SQL*Plus 2024-11-23 10:09:05 2024-11-23 10:09:39 1 8 8
8 .2 4% | 192 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:37 1 8 8
7 .1 4% | 9 SQL*Plus 2024-11-23 10:09:11 2024-11-23 10:09:39 1 7 7
7 .1 4% | 133 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:33 1 7 7
7 .1 4% | 134 SQL*Plus 2024-11-23 10:09:02 2024-11-23 10:09:35 1 7 7
20 rows selected.
--//正好20行，确实测试程序执行的。
--//我取消以下注解
--host sleep $((&&2/100|bc -l))
--//问题还是一样，说明我以前的测试并没有规避这个问题,以前的测试疏忽了，注意测试前一定要刷新共享池，看后面的测试就明白为
--//什么。也许以前的测试忘记做刷新共享池这步，以为小量延迟后问题消失。
--//我开始也怀疑resmgr:cpu quantum导致，仔细想想不应该。
--//当我将insert采用绑定变量写法后，问题依旧。
--insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
--//定下心来思考，理论在测试的中间不会出现latch: shared pool等待事情，sql语句也不会产生子光标，应该是执行第1次执行如下是
--//硬解析。
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
--//在等待事件中记录的是latch: shared pool，后面几次执行后马上软软解析。
--//而ash在取样是还是取到latch: shared pool等待事件，这样才会出现前面ashtop输出的奇葩情况。
--//注实际上有几次测试我忘记刷新共享池，发现latch: shared pool消失，这才想起问题匿名PLSQL代码循环体执行sql语句第1次是硬
--//解析,就会出现这样的情况。而且只有这样解析才解析的通。
--//修改如下：
$ cat m9.txt
set verify off
variable v_method varchar2(20)
exec :v_method := '&&2';
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
--host sleep $((&&2/100|bc -l))
insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,'&&2') ;
--insert into job_times values ( sys_context ('userenv', 'sid') ,dbms_utility.get_time ,:v_method) ;
commit ;
--select sysdate from dual ;
DECLARE
l_count PLS_INTEGER;
BEGIN
FOR i IN 1..&&1
LOOP
EXECUTE IMMEDIATE 'Select /*+ &2 */ count(*) from t where id = :j ' INTO l_count USING i;
END LOOP;
END;
/
update job_times set time_ela = dbms_utility.get_time - time_ela where sid=sys_context ('userenv', 'sid') and method= :v_method;
commit;
quit
--//先循环1次就可以规避这个问题。
$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book @m9.txt 5e5 Q > /dev/null;zzdate
trunc(sysdate)+11/24+40/1440+35/86400
trunc(sysdate)+11/24+41/1440+22/86400
SYS@book> @ ashtop event 1=1 trunc(sysdate)+11/24+40/1440+35/86400 trunc(sysdate)+11/24+41/1440+22/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
655 13.9 72% | resmgr:cpu quantum 2024-11-23 11:40:36 2024-11-23 11:41:20 8 45 11
237 5.0 26% | 2024-11-23 11:40:36 2024-11-23 11:41:21 128 46 164
6 .1 1% | cursor: pin S wait on X 2024-11-23 11:40:35 2024-11-23 11:40:35 1 1 1
6 .1 1% | log file sync 2024-11-23 11:40:37 2024-11-23 11:41:21 1 3 3
1 .0 0% | control file parallel write 2024-11-23 11:40:59 2024-11-23 11:40:59 1 1 1
1 .0 0% | kksfbc child completion 2024-11-23 11:40:35 2024-11-23 11:40:35 1 1 1
6 rows selected.
--//不再出现latch: shared pool等待事情，我反复测试多次，结果都是一样。
4.总结：
--//感觉应该算11g的bug，不过我的测试是一个循环，非常特殊。
--//以前确实没有仔细查看一些细节，也许这样问题早就能发现。
