[20260809]跟踪执行select sid from v$mystat where rownum=1;.txt

[20260809]跟踪执行select sid from v$mystat where rownum=1;.txt

--//前段时间测试cdb下密集执行select sid from v$mystat where rownum=1;很慢,发现调用kgllkal函数在实例对象上,大量的执行必
--//然要在该对象上产生争用。出现library cache: bucket mutex X,library cache: mutex X等待事件。
--//单独跟踪该sql语句的执行情况。

1.环境:
SYS@book> @ 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.跟踪执行:
--//在cdb下执行:
SYS@book> @ 46on 12

Session altered.

SYS@book> select sid from v$mystat where rownum<=1;
       SID
----------
        37

SYS@book> select sid from v$mystat where rownum<=1;
       SID
----------
        37

SYS@book> select sid from v$mystat where rownum<=1;
       SID
----------
        37

SYS@book> select sid from v$mystat where rownum<=1;
       SID
----------
        37

SYS@book> select sid from v$mystat where rownum<=1;
       SID
----------
        37

SYS@book> @ ti
New tracefile_identifier = /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951_0001.trc

SYS@book> select sid from v$mystat where rownum<=1;
       SID
----------
        37

SYS@book> select sid from v$mystat where rownum<=1;
       SID
----------
        37

SYS@book> select sid from v$mystat where rownum<=1;
       SID
----------
        37

SYS@book> @ 46off
Session altered.

3.分析跟踪:
$ tkprof /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951.trc
output = aa
TKPROF: Release 21.0.0.0.0 - Development on Sun Aug 9 11:05:01 2026
Copyright (c) 1982, 2021, Oracle and/or its affiliates.  All rights reserved.

--//查看aa.prf,可以发现,除了一些递归语句外发现:
SQL ID: 87gaftwrm2h68 Plan Hash: 1072382624

select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname
from
 obj$ o where o.obj#=:1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     37      0.00       0.00          0          0          0           0
Fetch       37      0.00       0.00          0         74          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       74      0.00       0.00          0         74          0           0

Misses in library cache during parse: 0
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 1)
********************************************************************************
--//执行5次,竟然执行37次.

$ grep 140582007015288 /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951.trc | grep EXEC|wc
     37      74    3588
--//确实有28次.

$ grep 140582007015288 /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951.trc | grep FETCH | tail -4
FETCH #140582007015288:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=1072382624,tim=4310945347
FETCH #140582007015288:c=0,e=7,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=1072382624,tim=4310945500
FETCH #140582007015288:c=0,e=7,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=1072382624,tim=4310945672
FETCH #140582007015288:c=0,e=6,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=1072382624,tim=4310945817
--//r=0.

--//看看那些绑定变量值:
$ grep -A 6 "BINDS #140582007015288:" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951.trc |grep value|cut -d"=" -f2| sort |uniq -c
      3 4294951106
     15 4294951107
      2 4294951280
     17 4294951930
--//Sum = 37

$ grep -A 6 "BINDS #140582007015288:" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951.trc |grep value|cut -d"=" -f2| tail -30
4294951280
4294951107
4294951107
4294951107
4294951930
4294951930
4294951107
4294951107
4294951930
4294951930
4294951107
4294951107
4294951930
4294951930
4294951107
4294951107
4294951930
4294951930
4294951107
4294951107
4294951930
4294951930
4294951107
4294951107
4294951930
4294951930
4294951107
4294951107
4294951930
4294951930
--//如果从尾部向上看,4个一组可以基本确定相关递归语句使用绑定变量值4294951107,4294951930。

SYS@book> select o.owner#,o.name,o.namespace,o.remoteowner,o.linkname,o.subname from  obj$ o where o.obj# in ( 4294951106,4294951107, 4294951280, 4294951930);
no rows selected
--//没有返回,r=0是正常的。

4.再来看看第2个跟踪文件:
$ grep 140582007015288 /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951_0001.trc | grep EXEC|wc
     40      80    3883
--//第2次跟踪文件里仅仅执行3次,居然还出现40次执行。也许ti.sql的执行又调用许多次。

$ grep -A 6 "BINDS #140582007015288:" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951_0001.trc |grep value|cut -d"=" -f2| sort |uniq -c
      1 0
      3 4294950940
      2 4294950998
      4 4294951046
      3 4294951066
      6 4294951107
      ~~~~~~~~~~~~~
      3 4294951129
      1 4294951198
      1 4294951293
      1 4294951325
      2 4294951708
      6 4294951930
      ~~~~~~~~~~~~~
      1 4294953011
      1 4294953012
      4 4294953013
      1 4294953633
--//上下比较同时出现的绑定变量值4294951107,4294951930。

--//执行如下可以确定select sid from v$mystat where rownum<=1;语句时,递归执行SQL ID: 87gaftwrm2h68的绑定变量为4294951107,4294951930.
$ grep -A 6 "BINDS #140582007015288:" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3951_0001.trc |grep value|cut -d"=" -f2| tail -13
4294950940
4294951107
4294951107
4294951930
4294951930
4294951107
4294951107
4294951930
4294951930
4294951107
4294951107
4294951930
4294951930
--//才想起这些object_id 非常大的对象对应的是x表.

SYS@book> select * from gv$fixed_table where object_id  in ( 4294951106,4294951107, 4294951280, 4294951930,4294950940);
INST_ID NAME         OBJECT_ID TYPE    TABLE_NUM     CON_ID
------- ----------- ---------- ------ ---------- ----------
      1 X$KSUSGIF   4294951930 TABLE          52          0
      1 X$KSUMYSTA  4294951106 TABLE          54          0
      1 GV$MYSTAT   4294951280 VIEW        65537          0
      1 V$MYSTAT    4294951107 VIEW        65537          0
      1 V$PARAMETER 4294950940 VIEW        65537          0

--//select sid from v$mystat where rownum<=1; 执行计划如下:
Plan hash value: 3451101881
-----------------------------------------------------------------------
| Id  | Operation          | Name       | E-Rows |E-Bytes| Cost (%CPU)|
-----------------------------------------------------------------------
|   0 | SELECT STATEMENT   |            |        |       |     1 (100)|
|*  1 |  COUNT STOPKEY     |            |        |       |            |
|*  2 |   FIXED TABLE FULL | X$KSUMYSTA |      2 |    40 |     0   (0)|
|   3 |    FIXED TABLE FULL| X$KSUSGIF  |      1 |     4 |     0   (0)|
-----------------------------------------------------------------------

SYS@book> select * from v$rowcache_parent where UTL_RAW.cast_to_varchar2(key) like '%X$KSUMYSTA%';
no rows selected

SYS@book> select * from v$rowcache_parent where UTL_RAW.cast_to_varchar2(key) like '%X$KSUSGIF%';
no rows selected
--//似乎X表在数据字典里面没有记录.在11g做了类似查询也是没有记录。

SYS@book> column KEY noprint
SYS@book> select * from v$rowcache_parent where UTL_RAW.cast_to_varchar2(key) like '%V$MYSTAT%';

  INDX       HASH ADDRESS              CACHE# CACHE_NAME           EXISTENT  LOCK_MODE LOCK_REQUEST TXN              SADDR            INST_LOCK_REQUEST INST_LOCK_RELEASE IN INST_LOC INST_LOC CON_ID
------ ---------- ---------------- ---------- -------------------- -------- ---------- ------------ ---------------- ---------------- ----------------- ----------------- -- -------- -------- ------
  2495       2592 00000000647C0C38          8 dc_objects           Y                 0            0 00               00                               0                 0    00       00            3
  3055       4604 00000000647BF508          8 dc_objects           Y                 0            0 00               00                               0                 0    00       00            1
  8828      26200 00000000647C2698          8 dc_objects           N                 0            0 00               00                               0                 0    00       00            3
 13314       8905 00000000647C0C38          8 dc_objects           Y                 0            0 00               00                               0                 0    00       00            3
 16928      21576 00000000647BF508          8 dc_objects           Y                 0            0 00               00                               0                 0    00       00            1

SYS@book> column KEY print
SYS@book> select * from v$rowcache_parent where UTL_RAW.cast_to_varchar2(key) like '%V$MYSTAT%' and rownum=1;

  INDX       HASH ADDRESS              CACHE# CACHE_NAME           EXISTENT  LOCK_MODE LOCK_REQUEST TXN              SADDR            INST_LOCK_REQUEST INST_LOCK_RELEASE IN INST_LOC INST_LOC KEY                            CON_ID
------ ---------- ---------------- ---------- -------------------- -------- ---------- ------------ ---------------- ---------------- ----------------- ----------------- -- -------- -------- ------------------------------ ------
  2495       2592 00000000647C0C38          8 dc_objects           Y                 0            0 00               00                               0                 0    00       00       01000000080056244D595354415400      3
                                                                                                                                                                                               000000000000000000000000000000
                                                                                                                                                                                               000000000000000000000000000000
                                                                                                                                                                                               000000000000000000000000000000
                                                                                                                                                                                               000000000000000000000000000000
                                                                                                                                                                                               000000000000000000000000000000
                                                                                                                                                                                               00000000000000000000
--//key=01000000080056244D595354415400,看了一些资料,可以确定。
--//00000001,表示use_id,intel系列CPU大小头问题。
--//0008,表示对象的长度V$MYSTAT正好8个字符。
--//56244D5953544154 对应的ascii码就是 V$MYSTAT

--//自己写一个查询脚本:
SYS@book> @ dc/dc_objects "DC_OBJ_NAME='V$MYSTAT'"
USERNAME DC_OBJ_NAME KEY_STR_LEN HASH_HEX   INDX   HASH ADDRESS              CACHE# CACHE_NAME EXISTENT  LOCK_MODE LOCK_REQUEST TXN  SADDR INST_LOCK_REQUEST INST_LOCK_RELEASE IN INST_LOC INST_LOC CON_ID
-------- ----------- ----------- -------- ------ ------ ---------------- ---------- ---------- -------- ---------- ------------ ---- ----- ----------------- ----------------- -- -------- -------- ------
         V$MYSTAT              8 0xa20      2495   2592 00000000647C0C38          8 dc_objects Y                 0            0 00   00                    0                 0    00       00            3
         V$MYSTAT              8 0x11fc     3055   4604 00000000647BF508          8 dc_objects Y                 0            0 00   00                    0                 0    00       00            1
         V$MYSTAT              8 0x5448    16928  21576 00000000647BF508          8 dc_objects Y                 0            0 00   00                    0                 0    00       00            1
         V$MYSTAT              8 0x22c9    13314   8905 00000000647C0C38          8 dc_objects Y                 0            0 00   00                    0                 0    00       00            3
SCOTT    V$MYSTAT              8 0x6658     8828  26200 00000000647C2698          8 dc_objects N                 0            0 00   00                    0                 0    00       00            3
--//scott.V$MYSTAT的 EXISTENT=N,表示不存在,其他为什么每个存在2行不是很理解(con_id不同)。

--//这样就很好理解为什么前面密集执行的测试出现row cache mutex等待事件。语句要不停的访问数据字段。
SYS@book> @ ashtop event 1=1 trunc(sysdate)+16/24+00/1440+35/86400 trunc(sysdate)+16/24+33/1440+26/86400
    Total                                                                                         Distinct Distinct    Distinct
  Seconds     AAS %This   EVENT                         FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1
--------- ------- ------- ----------------------------- ------------------- ------------------- ---------- -------- -----------
    15830     8.0   65% | library cache: bucket mutex X 2026-06-04 16:25:02 2026-06-04 16:33:25          1      501         501
     4930     2.5   20% |                               2026-06-04 16:25:02 2026-06-04 16:33:25        424      446         867
     1881     1.0    8% | library cache: mutex X        2026-06-04 16:25:02 2026-06-04 16:33:24          1      425         425
     1277      .6    5% | cursor: pin S                 2026-06-04 16:25:02 2026-06-04 16:33:24          1      207         207
      468      .2    2% | row cache mutex               2026-06-04 16:25:03 2026-06-04 16:33:18          1      108         108
       38      .0    0% | latch: session allocation     2026-06-04 16:25:33 2026-06-04 16:33:10          1       16          16
        1      .0    0% | sort segment request          2026-06-04 16:31:20 2026-06-04 16:31:20          1        1           1
7 rows selected.

5.附上测试过程使用脚本:

$ cat dc/dc_objects.sql
column DC_PROP_NAME format a28
column CACHE_NAME   format a20
column EXISTENT     format a8
column KEY_OID$     format a32
column dc_obj_name  format a32
column dc_obj_name1 format a32
column username     format a20
column con_id       format 99999
column indx         format 99999
column hash         format 99999
column key          noprint

  SELECT *
    FROM (SELECT --TO_NUMBER ( (SUBSTR (key, 7, 2) || SUBSTR (key, 5, 2) || SUBSTR (key, 3, 2) || SUBSTR (key, 1, 2)), 'XXXXXXXX') Schema_User_ID ,
                 (SELECT username
                    FROM dba_users
                   WHERE user_id = TO_NUMBER ( (SUBSTR (key, 7, 2) || SUBSTR (key, 5, 2) || SUBSTR (key, 3, 2) || SUBSTR (key, 1, 2)) ,'XXXXXXXX')) username
                --,RTRIM (UTL_RAW.cast_to_varchar2 (SUBSTR (v.key, 13)), CHR (0)) dc_obj_name
                --,TO_NUMBER (TRIM (BOTH '0' FROM SUBSTR (key, 11, 2) || SUBSTR (key, 9, 2)), 'XXXX') key_str_len
                ,UTL_RAW.cast_to_varchar2 (SUBSTR (v.key, 13,2*TO_NUMBER ( SUBSTR (key, 11, 2) || SUBSTR (key, 9, 2), 'XXXX'))) dc_obj_name
                ,TO_NUMBER ( SUBSTR (key, 11, 2) || SUBSTR (key, 9, 2), 'XXXX') key_str_len
                                ,'0x'||to_char(v.hash,'FMXXXX') hash_hex
                ,v.*
            FROM v$rowcache_parent v
           WHERE cache# in (8,11)
        )
   WHERE (&1)
ORDER BY key;

column key print
column hash clear


posted @ 2026-08-14 21:55  lfree  阅读(5)  评论(0)    收藏  举报