[20261018]光标跟踪事件3.txt

--//前几天测试使用cursortrace跟踪事件，想起以前子光标的性能测试。以后它应该很好跟踪该事件，重复测试看看。

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.建立测试脚本：
create table t as select rownum id ,cast('test' as varchar2(10)) name from dual ;
alter table t modify ( id  not null );
create unique index i_t_id on t(id);
--//分析表略。

$ cat m13.txt
--//alter session set session_cached_cursors=0;
set verify off
variable vmethod varchar2(20);
exec :vmethod := '&&2';
alter session set optimizer_index_cost_adj = &&3;
declare
v_id number;
v_d date;
l_count PLS_INTEGER;
begin
    for i in 1 .. &&1 loop
        SELECT COUNT(NAME) INTO v_id FROM T WHERE ID=1;
    end loop;
end ;
/
quit
--//说明：参数1表示循环次数，参数2表示method(在这里暂时没用)，参数3表示设置optimizer_index_cost_adj。

$ sql_idz.sh "SELECT COUNT(NAME) FROM T WHERE ID=1\0" 3
sql_text = SELECT COUNT(NAME) FROM T WHERE ID=1\0
full_hash_value(16) = C11A46B81FF591945FB98984B14F5520 or c11a46b81ff591945fb98984b14f5520
xxxxx_matching_signature(10) = 6897695507298080032 or  25344439581007631648
hash_value(10) = 2974766368 or hash_value(16) = B14F5520 or b14f5520
kgl_backet(10) = 87328 or kgl_bucket(16) =  15520 or 15520
sql_id(16) = 5FB98984B14F5520 or 5fb98984b14f5520
sql_id(32) = 5zfc9hhsnyp90
sql_id(32) = 5zfc9hhsnyp90
sql_id(32) = 5zfc9hhsnyp90
--//记下sql_id=5zfc9hhsnyp90,hash_value=2974766368.

$ cat aa3.txt
define hash_value=2974766368
alter session set events 'immediate trace name cursortrace level 0x41, address &hash_value';
@m13.txt 1 xx 129
alter session set events 'immediate trace name cursortrace level 0x80, address &hash_value';
@ t

3.测试：
$ seq 128 | xargs -IQ sqlplus -s -l scott/book@book01p @m13.txt 6 xx Q > /dev/null
--//每个情况执行6次,保证其在共享池中.sql_id='5zfc9hhsnyp90',注意sql语句全部大写，因为PL/SQL内部做了转化为大写。
SYS@book> select count(*) from v$sql where sql_id='5zfc9hhsnyp90';
  COUNT(*)
----------
       128
--//产生128个子光标.

SCOTT@book01p> @ aa3.txt
Session altered.
Session altered.
PL/SQL procedure successfully completed.
Session altered.
PL/SQL procedure successfully completed.
--//脚本存在一点小错误，m13.txt包含quit已经退出，导致aa3.txt无法执行@t显示生成的跟踪文件名,不过很容易找到跟踪文件。

4.查看跟踪文件：
PDB#3 CUR#1 XSC 0x7f027ea74c60 CHILD#-1 CI (nil) CTX (nil)
 kksfbc begin 0x108 0 0
 No valid child pinned
 Parent 0x706ba7e8(0x68e6c978) ready for search
 kksCheckCursor: next child is #99
Child was pruned
 kksCheckCursor: next child is #98
Child was pruned
 kksCheckCursor: next child is #97
Child was pruned
 kksCheckCursor: next child is #96
Child was pruned
 kksCheckCursor: next child is #95
Child was pruned
 kksCheckCursor: next child is #94
Child was pruned
 kksCheckCursor: next child is #93
Child was pruned
 kksCheckCursor: next child is #92
Child was pruned
...
 kksCheckCursor: next child is #3
Child was pruned
 kksCheckCursor: next child is #2
Child was pruned
 kksCheckCursor: next child is #1
Child was pruned
 kksCheckCursor: next child is #0
Child was pruned
 kksCheckCursor: next child is #100
Child was pruned
 kksCheckCursor: next child is #101
Child was pruned
 kksCheckCursor: next child is #102
Child was pruned
 kksCheckCursor: next child is #103
Child was pruned
 kksCheckCursor: next child is #104
Child was pruned
 kksCheckCursor: next child is #105
Child was pruned
 kksCheckCursor: next child is #106
Child was pruned
 kksCheckCursor: next child is #107
Child was pruned
 kksCheckCursor: next child is #108
Child was pruned
 kksCheckCursor: next child is #109
Child was pruned
 kksCheckCursor: next child is #110
Child was pruned
 kksCheckCursor: next child is #111
Child was pruned
 kksCheckCursor: next child is #112
Child was pruned
 kksCheckCursor: next child is #113
Child was pruned
 kksCheckCursor: next child is #114
Child was pruned
 kksCheckCursor: next child is #115
Child was pruned
 kksCheckCursor: next child is #116
Child was pruned
 kksCheckCursor: next child is #117
Child was pruned
 kksCheckCursor: next child is #118
Child was pruned
 kksCheckCursor: next child is #119
Child was pruned
 kksCheckCursor: next child is #120
Child was pruned
 kksCheckCursor: next child is #121
Child was pruned
 kksCheckCursor: next child is #122
Child was pruned
 kksCheckCursor: next child is #123
Child was pruned
 kksCheckCursor: next child is #124
Child was pruned
 kksCheckCursor: next child is #125
Child was pruned
 kksCheckCursor: next child is #126
Child was pruned
 kksCheckCursor: next child is #127
 kksCheckCursor: pinning child #127 in shared mode 0x706ba518 0x72573450
 kksUnlockChild: releasing child
 Failed sharing : 4
 kksSearchChildList: no suitable child found (hash_match=1)
 SearchChildList failed ctx=(nil) xscflg=20 ctxflg=0 flg=108
 allocated new child slot bi=0x72580248 flg=1 cld=128 hsh=b14f5520
kkshinins insert child into incomplete list bi=0x72580248 cld=128 flg=25
 Created new child obj #128 dsfl=2002011 8003c00 xsc=0x7f027ea74c60 chd=0x6d73c048 clk=0x706baab8
 Pin new child obj #128 dsfl=2002011 xsc=0x7f027ea74c60 chd=0x6d73c048 clk=0x706baab8 cpn=(nil)
 kksLoadChild: reload 0 path 2 kkscsusr 109 ksuudsid 109
 kksLoadChild: reload 0 path 3 kkscsusr 109 ksuudsid 109
 Child creation successful xsc=0x7f027ea74c60 chd=0x6d73c048 cpn=0x6fc56fa0 sta=0 bi=0x72580248 cld=128
 Add new child to parent list pi=0x6d2da6a8 psn=128 bi=0x72580248 cld=128 flg=35
kkshindel remove child from incomplete list bi=0x72580248 cld=128 flg=30
 kkshhcins insert child into hash table bi=0x72580248 cld=128 flg=38
 Downgrading child pin to share
 kksfbc begin 0x102 1 1
 Cursor about get executed
PDB#3 CUR#1 XSC 0x7f027ea74c60 CHILD#128 CI 0x6b20fea0 CTX (nil)
 Closing cursor

--//从kksCheckCursor显示顺序，可以确定先从child number=99到child number=0，然后从100到127，全部不合适建立新的子光标128。

SYS@book> select count(*) from v$sql where sql_id='5zfc9hhsnyp90';
  COUNT(*)
----------
       129

--//如果m13.txt脚本修改取消alter session set session_cached_cursors=0;注解，这样每次都是执行软解析。
--//child=99执行最快，相当于optimizer_index_cost_adj = 100.

$ time sqlplus -s -l scott/book@book01p @m13.txt 1e5 xx 100 > /dev/null
real    0m3.601s
user    0m0.208s
sys     0m0.003s

$ time sqlplus -s -l scott/book@book01p @m13.txt 1e5 xx 101 > /dev/null
real    0m6.926s
user    0m0.239s
sys     0m0.014s
--//对比前面有将近2倍差距。因为child number从99->0,然后100.

$ time sqlplus -s -l scott/book@book01p @m13.txt 1e5 xx 129 > /dev/null
real    0m7.143s
user    0m0.256s
sys     0m0.015s