[20241115]大量软软解析相关等待事件分析(21c).txt

--//顺便完善测试，测试应用程序大量软软解析导致的相关等待事件，主要以前对于一些细节不太重视。

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.建立测试环境：
drop table t purge ;
create table t as select rownum id ,'test' pad from dual connect by level<=2e5;
create unique index pk_t on t(id);
exec dbms_stats.gather_table_stats(user, 't', method_opt=>'for all columns size 1');

$ cat m4.txt
--//alter session set session_cached_cursors=0;
DECLARE
   v_pad   VARCHAR2 (200);
   l_count PLS_INTEGER;
BEGIN
    FOR i IN 1..&&1
    LOOP
       EXECUTE IMMEDIATE 'Select count(*) from t where id = :j ' INTO l_count USING i;
    END LOOP;
END;
/
--//注解session_cached_cursors=0;,这样每次执行几次以后都是软软解析。
--//sql语句第1个字符大写，避免前面的测试涉及到相关查询问题。

3.测试：

$ zzdate;seq 20 | xargs -P 20 -IQ sqlplus -s -l scott/book@book01p @m4.txt 5e5 > /dev/null;zzdate
trunc(sysdate)+16/24+46/1440+41/86400
trunc(sysdate)+16/24+47/1440+31/86400
--//等待测试完成。需要1*60+31-41= 50,比软解析的测试104秒快了许多。

SYS@book> @ ashtop event,p1raw,p1,p3raw 1=1 trunc(sysdate)+16/24+46/1440+41/86400 trunc(sysdate)+16/24+47/1440+31/86400
    Total                                                                                                                        Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT         P1RAW                     P1 P3RAW             FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------- ----------------- ---------- ----------------- ------------------- ------------------- ---------- -------- -----------
      721    14.4   75% |                                 2803829484                   2024-11-15 16:46:42 2024-11-15 16:47:30        396       49         444
      159     3.2   17% | cursor: pin S 00000000A71F0AEC  2803829484 0000000900000000  2024-11-15 16:46:43 2024-11-15 16:47:25          1       34          34
       72     1.4    7% | cursor: pin S 00000000A71F0AEC  2803829484 0000000300000000  2024-11-15 16:46:42 2024-11-15 16:47:29          1       30          30
        4      .1    0% |                                 1413697536                   2024-11-15 16:46:42 2024-11-15 16:46:42          3        1           3
        3      .1    0% |                                          1                   2024-11-15 16:47:26 2024-11-15 16:47:30          2        3           3
        1      .0    0% |                                         12                   2024-11-15 16:46:59 2024-11-15 16:46:59          1        1           1
        1      .0    0% |                                         20                   2024-11-15 16:47:03 2024-11-15 16:47:03          1        1           1
        1      .0    0% |                                      65536                   2024-11-15 16:47:27 2024-11-15 16:47:27          1        1           1
        1      .0    0% |                                     524288                   2024-11-15 16:47:28 2024-11-15 16:47:28          1        1           1
9 rows selected.
--//P3raw=0000000900000000,0000000300000000.

SYS@book> @ ashtop event,p1raw,p1,p2raw,p3raw 1=1 trunc(sysdate)+16/24+46/1440+41/86400 trunc(sysdate)+16/24+47/1440+31/86400
    Total                                                                                                                                          Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT         P1RAW                     P1 P2RAW             P3RAW             FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ------------- ----------------- ---------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
      721    14.4   75% |                                 2803829484                                     2024-11-15 16:46:42 2024-11-15 16:47:30        396       49         444
       16      .3    2% | cursor: pin S 00000000A71F0AEC  2803829484 0000009000000012  0000000900000000  2024-11-15 16:46:52 2024-11-15 16:46:52          1        1           1
       12      .2    1% | cursor: pin S 00000000A71F0AEC  2803829484 000001100000000E  0000000900000000  2024-11-15 16:47:01 2024-11-15 16:47:23          1        4           4
       11      .2    1% | cursor: pin S 00000000A71F0AEC  2803829484 0000009A0000000D  0000000900000000  2024-11-15 16:46:56 2024-11-15 16:47:04          1        3           3
        9      .2    1% | cursor: pin S 00000000A71F0AEC  2803829484 000000120000000F  0000000900000000  2024-11-15 16:46:49 2024-11-15 16:47:19          1        2           2
        8      .2    1% | cursor: pin S 00000000A71F0AEC  2803829484 0000009A0000000D  0000000300000000  2024-11-15 16:46:56 2024-11-15 16:47:04          1        3           3
        7      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 0000001500000011  0000000900000000  2024-11-15 16:47:16 2024-11-15 16:47:16          1        1           1
        7      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 0000002300000010  0000000900000000  2024-11-15 16:47:04 2024-11-15 16:47:19          1        2           2
        7      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 000000990000000E  0000000900000000  2024-11-15 16:47:03 2024-11-15 16:47:03          1        1           1
        6      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 000000120000000E  0000000900000000  2024-11-15 16:47:22 2024-11-15 16:47:22          1        1           1
        6      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 0000001C0000000E  0000000900000000  2024-11-15 16:47:14 2024-11-15 16:47:14          1        1           1
        6      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 000001100000000D  0000000900000000  2024-11-15 16:46:58 2024-11-15 16:46:58          1        1           1
        6      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 000001900000000D  0000000900000000  2024-11-15 16:46:56 2024-11-15 16:46:56          1        1           1
        6      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 000001940000000E  0000000900000000  2024-11-15 16:46:43 2024-11-15 16:46:51          1        2           2
        5      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 000000150000000F  0000000900000000  2024-11-15 16:47:25 2024-11-15 16:47:25          1        1           1
        5      .1    1% | cursor: pin S 00000000A71F0AEC  2803829484 000001940000000E  0000000300000000  2024-11-15 16:46:43 2024-11-15 16:46:58          1        3           3
        4      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 0000009A0000000F  0000000900000000  2024-11-15 16:46:48 2024-11-15 16:46:48          1        1           1
        4      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 0000010E0000000F  0000000900000000  2024-11-15 16:47:02 2024-11-15 16:47:25          1        2           2
        4      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 000001100000000D  0000000300000000  2024-11-15 16:46:58 2024-11-15 16:46:58          1        1           1
        4      .1    0% |                                 1413697536                                     2024-11-15 16:46:42 2024-11-15 16:46:42          3        1           3
        3      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 000000120000000E  0000000300000000  2024-11-15 16:47:22 2024-11-15 16:47:22          1        1           1
        3      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 000000150000000F  0000000300000000  2024-11-15 16:47:25 2024-11-15 16:47:25          1        1           1
        3      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 0000001A0000000D  0000000900000000  2024-11-15 16:47:25 2024-11-15 16:47:25          1        1           1
        3      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 000000990000000E  0000000300000000  2024-11-15 16:47:03 2024-11-15 16:47:03          1        1           1
        3      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 0000009A0000000F  0000000300000000  2024-11-15 16:46:48 2024-11-15 16:46:48          1        1           1
        3      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 0000010E0000000D  0000000900000000  2024-11-15 16:46:51 2024-11-15 16:47:03          1        2           2
        3      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 000001100000000F  0000000900000000  2024-11-15 16:46:47 2024-11-15 16:47:08          1        2           2
        3      .1    0% | cursor: pin S 00000000A71F0AEC  2803829484 0000019000000010  0000000900000000  2024-11-15 16:47:22 2024-11-15 16:47:22          1        1           1
        3      .1    0% |                                          1                                     2024-11-15 16:47:26 2024-11-15 16:47:30          2        3           3
        2      .0    0% | cursor: pin S 00000000A71F0AEC  2803829484 0000001500000010  0000000900000000  2024-11-15 16:46:50 2024-11-15 16:47:23          1        2           2
30 rows selected.
--//基本集中在cursor: pin S等待事件。
--//P2RAW前8位表示阻塞sid，后8位表示持有mutex的数量。

SYS@book> @ ev_namezpr "cursor: pin S$"
==============================
EVENT#                        : 367
EVENT_ID                      : 352301881
NAME                          : cursor: pin S
PARAMETER1                    : idn
PARAMETER2                    : value
PARAMETER3                    : where
WAIT_CLASS_ID                 : 3875070507
WAIT_CLASS#                   : 4
WAIT_CLASS                    : Concurrency
DISPLAY_NAME                  : cursor: pin S
CON_ID                        : 0
PL/SQL procedure successfully completed.

SYS@book> @ sharepool/shp4  '' 2803829484
HANDLE_TYPE            KGLHDADR         KGLHDPAR         C40                                        KGLHDLMD   KGLHDPMD   KGLHDIVC KGLOBHD0         KGLOBHD6           KGLOBHS0   KGLOBHS6   KGLOBT16   N0_6_16        N20   KGLNAHSH KGLOBT03        KGLOBT09
---------------------- ---------------- ---------------- ---------------------------------------- ---------- ---------- ---------- ---------------- ---------------- ---------- ---------- ---------- --------- ---------- ---------- ------------- ----------
child handle address   0000000067D1BB88 000000006C574638 Select count(*) from t where id = :j              0          0          0 0000000067C45AF0 000000006A5CD4D8       8128      16176       3318     27622      27622 2803829484 ctt2p2qmjy2rc          0
parent handle address  000000006C574638 000000006C574638 Select count(*) from t where id = :j              0          0          0 0000000067B7F3C0 00                     4064          0          0      4064       4064 2803829484 ctt2p2qmjy2rc      65535

SYS@book> @ mutexprofz idn,hash,loc,maddr,p1raw "ts>=trunc(sysdate)+16/24+46/1440+41/86400 and ts<=trunc(sysdate)+16/24+47/1440+31/86400 "
-- MutexProf by Tanel Poder (http://www.tanelpoder.com)
-- Showing profile of top 20 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       HASH GET_LOCATION                      mutex_addr           P1RAW            OBJECT_NAME
---------- -------------- --------------- ---------- ---------- --------------------------------- -------------------- ---------------- --------------------------------------------------------------------------------
        11         669381 Cursor Pin      2803829484 2803829484 kksLockDelete [KKSCHLPIN6]        000000006A5CD430     00               Select count(*) from t where id = :j
         4         126907 Cursor Pin      2803829484 2803829484 kksfbc [KKSCHLFSP2]               000000006A5CD430     00               Select count(*) from t where id = :j

--//mutex_addr=000000006A5CD430.

SYS@book> @ fchaz 000000006A5CD430
GET_LOCATION                      KSMCHPTR           KSMCHIDX   KSMCHDUR KSMCHCOM           KSMCHSIZ KSMCHCLS   KSMCHTYP KSMCHPAR         KSMCHPTR_BEGIN   KSMCHPTR_END+1
--------------------------------- ---------------- ---------- ---------- ---------------- ---------- -------- ---------- ---------------- ---------------- -----------------
SGA                               000000006A5CCC80          1          1 KGLH0^a71f0aec         4096 recr           4095 0000000067B7F3C0 000000006A5CCC80 000000006A5CDC80
--//说明mutex_addr在父游标堆0里面。

SYS@book> @ opeek 000000006A5CD430 24 0
[06A5CD430, 06A5CD448) = 00000000 00000000 01312D48 00002B97 A71F0AEC 00000000
--//0xA71F0AEC = 2803829484 对应hash_value。

4.简单总结：
--//应用程序大量软软解析导致的相关等待事件,主要集中在cursor: pin S。