[20260802]测试遇到的问题.txt
--//我的测试很喜欢写一个脚本，打开一定数量并发，执行特定循环次数，看看遇到什么相关等待事件。前段时间测试带dblink的sql语
--//句密集执行的情况，以及select sid from v$mystat where rownum=1的pdb与cdb情况，实际上测试应该选择类似sql语句执行格式：
select /*+ &3 */sid from v$mystat where rownum=1
--//避免全部执行sql语句共享相同的光标，产生cursor pin：S 等待事件，突出测试中的问题。
--//没有选择如上执行方式的原因，源于11g我遇到的一个问题，始终没有展开分析，今天认真分析看看。
--//首先在21c下测试：
1.环境：
SCOTT@book01p> @ ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 21.0.0.0.0
BANNER : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
2.建立测试环境以及执行脚本：
SCOTT@book01p> create table t as select rownum id ,'test' vc from dual connect by level<=4e5;
Table created.
SCOTT@book01p> create unique index pk_t on t (id);
Index created.
SCOTT@book01p> alter table t add constraint pk_t primary key (id);
Table altered.
--//create table job_times (sid number, serial# number,time_ela1 number,time_ela2 number ,start_date timestamp,end_date timestamp,method varchar2(20));
$ cat zza.txt
set verify off
variable v_method varchar2(30);
exec :v_method := '&&2';
insert into job_times values ( sys_context ('userenv', 'sid') ,&3,dbms_utility.get_time ,null , localtimestamp,null ,:v_method) ;
commit ;
declare
v_vc VARCHAR2(32);
begin
for i in 1 .. &&1 loop
--select vc into v_vc from t where id=i;
select /*+ &&3 */ vc into v_vc from t where id=i;
end loop;
end ;
/
update job_times set time_ela2 = dbms_utility.get_time ,end_date=localtimestamp where sid=sys_context ('userenv', 'sid') and serial#= &3 and method= :v_method and time_ela2 is null;
commit;
quit
--//简单说明：这样每个会话带入&3不相同，每个会话执行sql语句都不相同，避免测试cursor pin：S等待事件。但是有一点点小问题，
--//就是开始瞬间会出现大量硬解析，出现小量latch: shared pool等待事件是正常的，以前为了规避这个问题每次执行前都会加入小量
--//sleep再执行脚本,实际上根本没用，看最后11g的执行情况。
3.测试：
--//为了测试的一致性首先重启数据库，在选择执行如下命令：
$ zzdate;seq 50 | xargs -IQ -P 50 sqlplus -s -l scott/book@book01p @zza.txt 3e5 P=50 Q >/dev/null;zzdate
trunc(sysdate)+09/24+22/1440+22/86400 -1785633742.694599216
trunc(sysdate)+09/24+23/1440+29/86400 1785633809.506977496
--//Sum = 66.81237828
SYS@book> @ ashtop event 1=1 trunc(sysdate)+09/24+22/1440+22/86400 trunc(sysdate)+09/24+23/1440+29/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
2594 38.7 100% | 2026-08-02 09:22:24 2026-08-02 09:23:28 1416 65 1478
2 .0 0% | control file parallel write 2026-08-02 09:22:23 2026-08-02 09:22:26 1 2 2
2 .0 0% | db file sequential read 2026-08-02 09:23:05 2026-08-02 09:23:15 1 2 2
1 .0 0% | Disk file operations I/O 2026-08-02 09:22:54 2026-08-02 09:22:54 1 1 1
1 .0 0% | PGA memory operation 2026-08-02 09:22:29 2026-08-02 09:22:29 1 1 1
--//21c下基本看不见latch: shared pool等待事件。
--//另外可以选择select vc into v_vcl from t where id=i;执行方式,这样会出现cursor pin：S 等待事件.
$ zzdate;seq 50 | xargs -IQ -P 50 sqlplus -s -l scott/book@book01p @zza.txt 3e5 P=50A Q >/dev/null;zzdate
trunc(sysdate)+09/24+26/1440+56/86400 -1785634016.860805391
trunc(sysdate)+09/24+28/1440+02/86400 1785634082.959584063
--//Sum = 66.098778672
--//注:没有重启数据库.
SYS@book> @ ashtop event 1=1 trunc(sysdate)+09/24+26/1440+56/86400 trunc(sysdate)+09/24+28/1440+02/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
1801 27.3 82% | 2026-08-02 09:26:58 2026-08-02 09:28:01 1026 64 1088
402 6.1 18% | cursor: pin S 2026-08-02 09:27:01 2026-08-02 09:27:59 1 38 38
3 .0 0% | control file parallel write 2026-08-02 09:27:54 2026-08-02 09:28:00 1 3 3
SCOTT@book01p> select method,count(*),round(avg(TIME_ELA2-TIME_ELA1),0),sum(TIME_ELA2-time_ela1) from scott.job_times group by method order by 3;
METHOD COUNT(*) ROUND(AVG(TIME_ELA2-TIME_ELA1),0) SUM(TIME_ELA2-TIME_ELA1)
-------------------- ---------- --------------------------------- ------------------------
P=50A 50 4414 220692
P=50 50 5149 257441
--//后者的平均执行时间44秒.基本看不出打散执行sql语句的方式优点,所以通过测试认为打散sql的执行并不会带来多大的好处,除非你
--//的环境执行sql语句密集程度比我的测试还厉害的多.
4.回到问题,如果在11g执行相同测试:
SCOTT@book> @ ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 11.2.0.4.0
BANNER : Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
PL/SQL procedure successfully completed.
--//建立好测试环境,重启数据库.仅仅贴出测试结果:
$ zzdate;seq 50 | xargs -IQ -P 50 sqlplus -s -l scott/book @zza.txt 3e5 P=50B Q >/dev/null;zzdate
trunc(sysdate)+09/24+41/1440+10/86400 -1785634870.132937551
trunc(sysdate)+09/24+42/1440+13/86400 1785634933.631878263
--//Sum = 63.498940712
SYS@book> @ ashtop event 1=1 trunc(sysdate)+09/24+41/1440+10/86400 trunc(sysdate)+09/24+42/1440+13/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
1683 26.7 56% | latch: shared pool 2026-08-02 09:41:12 2026-08-02 09:42:11 1 58 58
1303 20.7 44% | 2026-08-02 09:41:11 2026-08-02 09:42:12 701 62 762
1 .0 0% | control file parallel write 2026-08-02 09:41:17 2026-08-02 09:41:17 1 1 1
1 .0 0% | log file sync 2026-08-02 09:41:11 2026-08-02 09:41:11 1 1 1
1 .0 0% | os thread startup 2026-08-02 09:41:18 2026-08-02 09:41:18 1 1 1
--//很明显11g下看到的结果与21c完全不同，看到了大量的latch: shared pool，如果执行看FIRST_SEEN，LAST_SEEN几乎贯穿测试的开
--//始到结束。
SYS@book> @ ashtop event username='SCOTT' trunc(sysdate)+09/24+41/1440+10/86400 trunc(sysdate)+09/24+42/1440+13/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
1683 26.7 56% | latch: shared pool 2026-08-02 09:41:12 2026-08-02 09:42:11 1 58 58
1299 20.6 44% | 2026-08-02 09:41:11 2026-08-02 09:42:12 701 62 762
1 .0 0% | log file sync 2026-08-02 09:41:11 2026-08-02 09:41:11 1 1 1
--//基本排除了其他owner的情况。
SYS@book> @ ashtop event,sid "username='SCOTT' and event='latch: shared pool'" trunc(sysdate)+09/24+41/1440+10/86400 trunc(sysdate)+09/24+42/1440+13/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT SID FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------ ------ ------------------- ------------------- ---------- -------- -----------
40 .6 2% | latch: shared pool 11 2026-08-02 09:41:12 2026-08-02 09:42:10 1 40 40
39 .6 2% | latch: shared pool 157 2026-08-02 09:41:14 2026-08-02 09:42:11 1 39 39
39 .6 2% | latch: shared pool 231 2026-08-02 09:41:12 2026-08-02 09:42:10 1 39 39
38 .6 2% | latch: shared pool 9 2026-08-02 09:41:15 2026-08-02 09:42:11 1 38 38
38 .6 2% | latch: shared pool 18 2026-08-02 09:41:14 2026-08-02 09:42:07 1 38 38
38 .6 2% | latch: shared pool 161 2026-08-02 09:41:14 2026-08-02 09:42:11 1 38 38
37 .6 2% | latch: shared pool 81 2026-08-02 09:41:14 2026-08-02 09:42:10 1 37 37
37 .6 2% | latch: shared pool 89 2026-08-02 09:41:13 2026-08-02 09:42:10 1 37 37
37 .6 2% | latch: shared pool 158 2026-08-02 09:41:15 2026-08-02 09:42:10 1 37 37
36 .6 2% | latch: shared pool 14 2026-08-02 09:41:15 2026-08-02 09:42:11 1 36 36
36 .6 2% | latch: shared pool 79 2026-08-02 09:41:12 2026-08-02 09:42:11 1 36 36
36 .6 2% | latch: shared pool 85 2026-08-02 09:41:15 2026-08-02 09:42:11 1 36 36
36 .6 2% | latch: shared pool 162 2026-08-02 09:41:15 2026-08-02 09:42:11 1 36 36
36 .6 2% | latch: shared pool 163 2026-08-02 09:41:13 2026-08-02 09:42:11 1 36 36
35 .6 2% | latch: shared pool 6 2026-08-02 09:41:12 2026-08-02 09:42:10 1 35 35
35 .6 2% | latch: shared pool 155 2026-08-02 09:41:16 2026-08-02 09:42:11 1 35 35
35 .6 2% | latch: shared pool 156 2026-08-02 09:41:15 2026-08-02 09:42:10 1 35 35
35 .6 2% | latch: shared pool 230 2026-08-02 09:41:14 2026-08-02 09:42:09 1 35 35
34 .5 2% | latch: shared pool 8 2026-08-02 09:41:15 2026-08-02 09:42:11 1 34 34
34 .5 2% | latch: shared pool 13 2026-08-02 09:41:14 2026-08-02 09:42:11 1 34 34
34 .5 2% | latch: shared pool 16 2026-08-02 09:41:14 2026-08-02 09:42:11 1 34 34
34 .5 2% | latch: shared pool 80 2026-08-02 09:41:12 2026-08-02 09:42:11 1 34 34
34 .5 2% | latch: shared pool 91 2026-08-02 09:41:15 2026-08-02 09:42:10 1 34 34
33 .5 2% | latch: shared pool 10 2026-08-02 09:41:12 2026-08-02 09:42:10 1 33 33
33 .5 2% | latch: shared pool 82 2026-08-02 09:41:15 2026-08-02 09:42:06 1 33 33
33 .5 2% | latch: shared pool 83 2026-08-02 09:41:12 2026-08-02 09:42:07 1 33 33
33 .5 2% | latch: shared pool 84 2026-08-02 09:41:12 2026-08-02 09:42:10 1 33 33
33 .5 2% | latch: shared pool 86 2026-08-02 09:41:13 2026-08-02 09:42:11 1 33 33
33 .5 2% | latch: shared pool 87 2026-08-02 09:41:14 2026-08-02 09:42:11 1 33 33
33 .5 2% | latch: shared pool 90 2026-08-02 09:41:15 2026-08-02 09:42:10 1 33 33
33 .5 2% | latch: shared pool 164 2026-08-02 09:41:15 2026-08-02 09:42:11 1 33 33
33 .5 2% | latch: shared pool 226 2026-08-02 09:41:12 2026-08-02 09:42:07 1 33 33
33 .5 2% | latch: shared pool 229 2026-08-02 09:41:12 2026-08-02 09:42:10 1 33 33
33 .5 2% | latch: shared pool 237 2026-08-02 09:41:14 2026-08-02 09:42:11 1 33 33
32 .5 2% | latch: shared pool 19 2026-08-02 09:41:15 2026-08-02 09:42:11 1 32 32
32 .5 2% | latch: shared pool 165 2026-08-02 09:41:15 2026-08-02 09:42:10 1 32 32
32 .5 2% | latch: shared pool 166 2026-08-02 09:41:14 2026-08-02 09:42:10 1 32 32
32 .5 2% | latch: shared pool 232 2026-08-02 09:41:15 2026-08-02 09:42:07 1 32 32
32 .5 2% | latch: shared pool 233 2026-08-02 09:41:13 2026-08-02 09:42:11 1 32 32
31 .5 2% | latch: shared pool 152 2026-08-02 09:41:14 2026-08-02 09:42:10 1 31 31
31 .5 2% | latch: shared pool 159 2026-08-02 09:41:12 2026-08-02 09:42:07 1 31 31
31 .5 2% | latch: shared pool 235 2026-08-02 09:41:15 2026-08-02 09:42:11 1 31 31
31 .5 2% | latch: shared pool 236 2026-08-02 09:41:14 2026-08-02 09:42:10 1 31 31
30 .5 2% | latch: shared pool 160 2026-08-02 09:41:15 2026-08-02 09:42:10 1 30 30
30 .5 2% | latch: shared pool 238 2026-08-02 09:41:15 2026-08-02 09:42:09 1 30 30
29 .5 2% | latch: shared pool 12 2026-08-02 09:41:12 2026-08-02 09:42:07 1 29 29
29 .5 2% | latch: shared pool 15 2026-08-02 09:41:14 2026-08-02 09:42:10 1 29 29
29 .5 2% | latch: shared pool 234 2026-08-02 09:41:17 2026-08-02 09:42:10 1 29 29
28 .4 2% | latch: shared pool 7 2026-08-02 09:41:15 2026-08-02 09:42:11 1 28 28
28 .4 2% | latch: shared pool 227 2026-08-02 09:41:15 2026-08-02 09:42:09 1 28 28
50 rows selected.
--//几乎每个会话都有latch: shared pool等待事件，而且时间都不短，很明显11g上这类测试有问题。取样抓取还是最后1个latch:
--//shared pool等待事件，视乎11g没有清除，导致ashtop的输出出现大量latch: shared pool，其实根本不存在这么长时间的latch:
--//shared pool。
$ cat zza.txt
set verify off
variable v_method varchar2(30);
exec :v_method := '&&2';
host sleep $(echo &3/10|bc -l)
insert into job_times values ( sys_context ('userenv', 'sid') ,&3,dbms_utility.get_time ,null , localtimestamp,null ,:v_method) ;
commit ;
declare
v_vc VARCHAR2(32);
begin
for i in 1 .. &&1 loop
--select vc into v_vc from t where id=i;
select /*+ &&3 */ vc into v_vc from t where id=i;
end loop;
end ;
/
update job_times set time_ela2 = dbms_utility.get_time ,end_date=localtimestamp where sid=sys_context ('userenv', 'sid') and serial#= &3 and method= :v_method and time_ela2 is null;
commit;
quit
--//每个会话加入sleep，最后执行sleep的时间越长，最大延迟50/10=5秒。
--//重启数据库，执行如下：
$ zzdate;seq 50 | xargs -IQ -P 50 sqlplus -s -l scott/book @zza.txt 3e5 P=50C Q >/dev/null;zzdate
trunc(sysdate)+10/24+07/1440+06/86400 -1785636426.417994838
trunc(sysdate)+10/24+08/1440+09/86400 1785636489.476594125
--//Sum = 63.058599287
SYS@book> @ ashtop event "username='SCOTT' " trunc(sysdate)+10/24+07/1440+06/86400 trunc(sysdate)+10/24+08/1440+09/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
1521 24.1 55% | latch: shared pool 2026-08-02 10:07:08 2026-08-02 10:08:07 1 57 57
1237 19.6 45% | 2026-08-02 10:07:08 2026-08-02 10:08:08 661 61 721
2 .0 0% | ADR block file read 2026-08-02 10:07:07 2026-08-02 10:07:08 2 2 2
2 .0 0% | log file sync 2026-08-02 10:08:05 2026-08-02 10:08:07 1 2 2
--//还是可以发现大量latch: shared pool等待事件。
--//如果你修改 host sleep $(echo &3/10|bc -l) 为 host sleep &3，测试结果类似。
$ zzdate;seq 50 | xargs -IQ -P 50 sqlplus -s -l scott/book @zza.txt 3e5 P=50D Q >/dev/null;zzdate
trunc(sysdate)+10/24+12/1440+01/86400 -1785636721.123908847
trunc(sysdate)+10/24+13/1440+05/86400 1785636785.190810429
--//Sum = 64.066901582
SYS@book> @ ashtop event "username='SCOTT' " trunc(sysdate)+10/24+12/1440+01/86400 trunc(sysdate)+10/24+13/1440+05/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ------------------- ------------------- ---------- -------- -----------
551 8.6 85% | 2026-08-02 10:12:02 2026-08-02 10:13:04 348 63 402
93 1.5 14% | latch: shared pool 2026-08-02 10:12:19 2026-08-02 10:13:02 1 20 20
2 .0 0% | log file sync 2026-08-02 10:12:22 2026-08-02 10:12:44 1 2 2
SYS@book> select method,count(*),round(avg(TIME_ELA2-TIME_ELA1),0),sum(TIME_ELA2-time_ela1) from scott.job_times group by method order by 3;
METHOD COUNT(*) ROUND(AVG(TIME_ELA2-TIME_ELA1),0) SUM(TIME_ELA2-TIME_ELA1)
-------------------- ---------- --------------------------------- ------------------------
P=50D 50 1274 63706
P=50C 50 5550 277522
P=50B 50 5973 298645
5.小结：
--//实际上这个问题，当时在11g下测试时就非常困惑，什么会出现这样的情况，直接导致我在另外一个问题上的误判。
--//我以前以为加入延迟可以规避这个问题，实际上也是错的，这个应该是11g的一个bug，只不过还有我的测试脚本非常特殊。
--//这也导致11g软解析测试出现一些混乱，11g下没有library cache: bucket mutex X 等待，而是把该事件归在library cache: mutex
-//X，只能通过P1raw<=131072大致判断，知道21c测试才明白问题在那里。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-3179837/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
