ITPub博客
首页 博客 专栏 学院 社区 IT新媒体评选
发博

首页 > 数据库 > Oracle > [20200417]跟踪特定sql语句以及v$open_cursor视图.txt

[20200417]跟踪特定sql语句以及v$open_cursor视图.txt

原创 Oracle 作者：lfree 时间：2020-04-17 09:59:47 1 删除 编辑

[20200417]跟踪特定sql语句以及v$open_cursor视图.txt

--//工作需要跟踪特定sql语句，我发现一个奇特现象，有时候无法抓取sql语句,有时候跟踪的sql语句无法实现软软解析.
--//分几种情况分析.
--//感觉我遇到链接的情况:
--//http://blog.itpub.net/267265/viewspace-2675362/=>[20200212]使用DBMS_SHARED_POOL.MARKHOT与视图v$open_cursor.txt
--//做一个测试,顺便说明遇到的情况：
--//测试alter system set events 'sql_trace [sql:sql_id=80baj2c2ur47u] bind=false, wait=false';后登录会话的情况.

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

--//session 2:
SYS@book> alter system set events 'sql_trace off';
System altered.
--//初始化这步不要忘记!!避免影响下面的测试。我在这里犯了几次错误。

2.测试准备：
--//首先打开一个会话执行select * from dept where deptno=20;多次,保证不会挤出共享池,然后退出。
SCOTT@book> select * from dept where deptno=20;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        20 RESEARCH       DALLAS

SCOTT@book> @ hash
HASH_VALUE SQL_ID        CHILD_NUMBER HASH_HEX
---------- ------------- ------------ ---------
  95129850 80baj2c2ur47u            0   5ab90fa

--//获得sql_id=80baj2c2ur47u.

--//建立脚本利于反复执行:
$ cat voc.sql
column SID format 9999
column USER_NAME format a10
column CURSOR_TYPE format a32
column SQL_TEXT format a34
select * from v$open_cursor where sql_id='&&1' and sid=&&2;

$ cat vocx.sql
column KGLLKCTP format A32
column KGLNAOBJ format a34
SELECT inst_id
      ,kgllkuse
      ,kgllksnm
      ,user_name
      ,kglhdpar
      ,kglnahsh
      ,kgllksqlid
      ,kglnaobj
      ,kgllkest
      ,DECODE (kgllkexc, 0, TO_NUMBER (NULL), kgllkexc)
      ,kgllkctp
      ,kgllkhdl
  FROM x$kgllk
 WHERE     kglhdnsp = 0
       AND kglhdpar != kgllkhdl
       AND kgllksqlid = '&&1'
       AND kgllksnm = &&2;

3.测试:
--//测试启动特定sql跟踪后,然后其它会话登录的情况:
--//session 2:
SYS@book> alter system set events 'sql_trace [sql:sql_id=80baj2c2ur47u] bind=false, wait=false';
System altered.

--//session 2:
--//收尾执行 ：alter system set events 'sql_trace off';

--//session 1:
--//打开新的会话,注一定要在打开跟踪后登录,切记:
SCOTT@book> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        44        721 47324                    DEDICATED 47325       27         16 alter system kill session '44,721' immediate;
--//注：一般测试环境退出在登录sid不会变，仅仅serial#增加。

select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
select * from dept where deptno=20;
--//执行5次。

--//每次执行select * from dept where deptno=20;前在session 2 都执行@vcs 80baj2c2ur47u 44.

SYS@book> @ voc 80baj2c2ur47u 44
no rows selected

SYS@book> @ voc 80baj2c2ur47u 44
SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE
---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- --------------------------------
000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 OPEN

SYS@book> @ voc 80baj2c2ur47u 44
SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE
---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- --------------------------------
000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 OPEN

SYS@book> @ voc 80baj2c2ur47u 44
SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE
---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- --------------------------------
000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 OPEN

SYS@book> @ voc 80baj2c2ur47u 44
SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE
---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- --------------------------------
000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 OPEN
000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 DICTIONARY LOOKUP CURSOR CACHED

SYS@book> @ voc 80baj2c2ur47u 44
SADDR              SID USER_NAME  ADDRESS          HASH_VALUE SQL_ID        SQL_TEXT                           LAST_SQL_ACTIVE_TIM SQL_EXEC_ID CURSOR_TYPE
---------------- ----- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ----------- --------------------------------
000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 OPEN
000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 DICTIONARY LOOKUP CURSOR CACHED
000000008638EC10    44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                 DICTIONARY LOOKUP CURSOR CACHED

--//你可以发现执行4次出现CURSOR_TYPE='DICTIONARY LOOKUP CURSOR CACHED'.再次执行出现相同的一行。不会出现SESSION CURSOR CACHED的情况。

SYS@book> @ tpt/sqlid 80baj2c2ur47u %
Show SQL text, child cursors and execution stats for SQLID 80baj2c2ur47u child nvl('%','%')
HASH_VALUE PLAN_HASH_VALUE  CH# SQL_TEXT
---------- --------------- ---- ----------------------------------
  95129850      2852011669    0 select * from dept where deptno=20

 CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED ROWS_PER_FETCH    CPU_SEC CPU_SEC_EXEC    ELA_SEC ELA_SEC_EXEC       LIOS  LIOS_EXEC       PIOS      SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- -------------- ---------- ------------ ---------- ------------ ---------- ---------- ---------- ---------- ---------------
   0 000000007C184260 000000007C186A28 2852011669          9          1          9          9              9              1    .007999   .000888778    .007498   .000833111         95 10.5555556          1          0               0
   1 000000007C184260 000000007C930050 2852011669          5          1          5          5              5              1       .003        .0006    .002871     .0005742         10          2          0          0               0
--//你可以实际上建立新的子光标，正好执行5次。

SYS@book> @ vocx 80baj2c2ur47u 44
   INST_ID KGLLKUSE           KGLLKSNM USER_NAME  KGLHDPAR           KGLNAHSH KGLLKSQLID    KGLNAOBJ                           KGLLKEST            DECODE(KGLLKEXC,0,TO_NUMBER(NULL),KGLLKEXC) KGLLKCTP                         KGLLKHDL
---------- ---------------- ---------- ---------- ---------------- ---------- ------------- ---------------------------------- ------------------- ------------------------------------------- -------------------------------- ----------------
         1 000000008638EC10         44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                                                 OPEN                             000000007C930050
         1 000000008638EC10         44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                                                 DICTIONARY LOOKUP CURSOR CACHED  000000007C930050
         1 000000008638EC10         44 SCOTT      000000007C184260   95129850 80baj2c2ur47u select * from dept where deptno=20                                                                 DICTIONARY LOOKUP CURSOR CACHED  000000007C930050
--//后面的KGLLKHDL就是子光标的地址。指向child number#=1的子光标地址。

$ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47325.trc
PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084890795500 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084894841044 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084898633156 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
PARSING IN CURSOR #140601268218120 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084902184981 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
PARSING IN CURSOR #140601268217176 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084907017138 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'

--//PARSING IN CURSOR 5次，注意前面3次cursor后面的数字一样，而第4，5次cursor后面的数字与前面的不同,不知道为什么？
--//可以看出软软解析无效。

--//摘要转储内容如下：
*** 2020-04-17 08:54:50.795
*** SESSION ID:(44.721) 2020-04-17 08:54:50.795
*** CLIENT ID:() 2020-04-17 08:54:50.795
*** SERVICE NAME:(SYS$USERS) 2020-04-17 08:54:50.795
*** MODULE NAME:(SQL*Plus) 2020-04-17 08:54:50.795
*** ACTION NAME:() 2020-04-17 08:54:50.795

=====================
PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084890795500 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
select * from dept where deptno=20
END OF STMT
EXEC #140601269096704:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084890795495
FETCH #140601269096704:c=0,e=68,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084890796248
STAT #140601269096704 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=59 us cost=1 size=20 card=1)'
STAT #140601269096704 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=31 us cost=0 size=0 card=1)'
FETCH #140601269096704:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084890796850

*** 2020-04-17 08:54:54.840
CLOSE #140601269096704:c=0,e=11,dep=0,type=0,tim=1587084894840825
=====================
PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084894841044 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
select * from dept where deptno=20
END OF STMT
EXEC #140601269096704:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084894841042
FETCH #140601269096704:c=0,e=30,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084894841206
STAT #140601269096704 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=25 us cost=1 size=20 card=1)'
STAT #140601269096704 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=15 us cost=0 size=0 card=1)'
FETCH #140601269096704:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084894841624

*** 2020-04-17 08:54:58.632
CLOSE #140601269096704:c=0,e=11,dep=0,type=0,tim=1587084898632954
=====================
PARSING IN CURSOR #140601269096704 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084898633156 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
select * from dept where deptno=20
END OF STMT
EXEC #140601269096704:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084898633154
FETCH #140601269096704:c=0,e=29,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084898633314
STAT #140601269096704 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=21 us cost=1 size=20 card=1)'
STAT #140601269096704 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=14 us cost=0 size=0 card=1)'
FETCH #140601269096704:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084898633728

*** 2020-04-17 08:55:02.184
CLOSE #140601269096704:c=0,e=14,dep=0,type=1,tim=1587084902184797
=====================
PARSING IN CURSOR #140601268218120 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084902184981 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
select * from dept where deptno=20
END OF STMT
EXEC #140601268218120:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084902184979
FETCH #140601268218120:c=0,e=29,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084902185144
STAT #140601268218120 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=22 us cost=1 size=20 card=1)'
STAT #140601268218120 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=15 us cost=0 size=0 card=1)'
FETCH #140601268218120:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084902185536

*** 2020-04-17 08:55:07.016
CLOSE #140601268218120:c=0,e=12,dep=0,type=1,tim=1587084907016941
=====================
PARSING IN CURSOR #140601268217176 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587084907017138 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
select * from dept where deptno=20
END OF STMT
EXEC #140601268217176:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587084907017136
FETCH #140601268217176:c=0,e=41,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587084907017310
STAT #140601268217176 id=1 cnt=1 pid=0 pos=1 obj=87106 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=25 us cost=1 size=20 card=1)'
STAT #140601268217176 id=2 cnt=1 pid=1 pos=1 obj=87107 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=16 us cost=0 size=0 card=1)'
FETCH #140601268217176:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2852011669,tim=1587084907017795

4.总结：
--//感觉这是一个bug。与我以前的一个测试链接很像。
--//http://blog.itpub.net/267265/viewspace-2675362/=>[20200212]使用DBMS_SHARED_POOL.MARKHOT与视图v$open_cursor.txt
--//在跟踪特定sql语句时，后登录的会话会出现前面测试所看到的情况，软软解析失效,打开v$open_cursor会看到上面的情况。
--//对于已经登录的会话呢，会出现什么情况呢，另外写一篇blog。

来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-2686680/ ，如需转载，请注明出处，否则将追究法律责任。

0
0
上一篇： [20200416]可怕的防水墙产品.txt
下一篇： [20200417]跟踪特定sql语句以及v$open_cursor视图2.txt
请登录后发表评论 登录
全部评论
lfree
专家姓名：张文胜
熟悉oracle相关技术，擅长sql优化，rman备份与恢复，熟悉linux shell编程。

注册时间：2008-01-03

  • 博文量
    4006
  • 访问量
    7969390

最新文章

支持我们 作者招募 用户协议 FAQ Contact Us

北京盛拓优讯信息技术有限公司. 版权所有  京ICP备16024965号-8 北京市公安局海淀分局网监中心备案编号：11010802021510 niuxiaotong@pcpop.com 17352615567 未成年人举报专区

广播电视节目制作经营许可证(京) 字第1234号 中国互联网协会会员

违法和不良信息举报电话:18101376593