[20200417]跟踪特定sql语句以及v$open_cursor视图2.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 off';
System altered.

--//session 1:
SCOTT@book> @ spid

       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        44        725 47555                    DEDICATED 47556       27         18 alter system kill session '44,725' immediate;

select * from dept where deptno=20;
--//注：已经先于启动跟踪前，并且先执行1次。
--//session 2:
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
--//光标已经open。

SYS@book> alter system set events 'sql_trace [sql:sql_id=80baj2c2ur47u] bind=true, wait=true';
System altered.

--//session 1:
select * from dept where deptno=20;
select * from dept where deptno=20;

--//每次执行select * from dept where deptno=20;前在session 2 都执行@vcs 80baj2c2ur47u 44.
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                                 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                                 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         12          1         12         12             12              1    .008998   .000749833    .007968      .000664        101 8.41666667          1          0               0
   1 000000007C184260 000000007C930050 2852011669          8          1          8          8              8              1       .003      .000375    .003297   .000412125         16          2          0          0               0

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                                                                 SESSION CURSOR CACHED            000000007C186A28

--//后面的KGLLKHDL就是子光标的地址。指向child number#=0的子光标地址。
--//对于已经登录的会话再跟踪的情况，光标是可以cache的。也就是可以实现软软解析。
--//但是在这样的情况下，oracle是无法跟踪对于sql语句的。

--//从前面的测试知道进程号spid=47556.
$ ls -l  /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc
ls: /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc: No such file or directory
--//可以发现并没有建立跟踪文件。

4.继续测试：
--//如果你session 1一直执行：select * from dept where deptno=20;是无法抓取到这样的sql语句的。即使退出也不会生成跟踪文件。
--//但是如果你在会话执行另外的sql语句，然后在执行select * from dept where deptno=20;。
--//session 1:
SCOTT@book> @ pp
TRACEFILE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc

SCOTT@book> host ls -l /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc
ls: /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc: No such file or directory
--//可以发现还是没有建立跟踪文件。

SCOTT@book> select * from dept where deptno=20;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        20 RESEARCH       DALLAS

SCOTT@book> host ls -l /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc
-rw-r----- 1 oracle oinstall 1366 Apr 17 09:36 /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc
--//现在已经建立跟踪文件了。

--//session 1:
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                                 SESSION CURSOR CACHED

$ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc
PARSING IN CURSOR #139764967743728 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587087417430867 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'

--//session 1:
SCOTT@book> select * from dept where deptno=20;
    DEPTNO DNAME          LOC
---------- -------------- -------------
        20 RESEARCH       DALLAS

--//session 2:
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                                 SESSION CURSOR CACHED

$ grep "^PARS" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc
PARSING IN CURSOR #139764967743728 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587087417430867 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
--//仅仅PARSING IN CURSOR 1次。

$ cat /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc
Trace file /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_47556.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0.4/dbhome_1
System name:    Linux
Node name:      gxqyydg4
Release:        2.6.39-300.26.1.el5uek
Version:        #1 SMP Thu Jan 3 18:31:38 PST 2013
Machine:        x86_64
Instance name: book
Redo thread mounted by this instance: 1
Oracle process number: 27
Unix process pid: 47556, image: oracle@gxqyydg4 (TNS V1-V3)

*** 2020-04-17 09:36:57.431
*** SESSION ID:(44.725) 2020-04-17 09:36:57.431
*** CLIENT ID:() 2020-04-17 09:36:57.431
*** SERVICE NAME:(SYS$USERS) 2020-04-17 09:36:57.431
*** MODULE NAME:(SQL*Plus) 2020-04-17 09:36:57.431
*** ACTION NAME:() 2020-04-17 09:36:57.431

=====================
PARSING IN CURSOR #139764967743728 len=34 dep=0 uid=83 oct=3 lid=83 tim=1587087417430867 hv=95129850 ad='7c184260' sqlid='80baj2c2ur47u'
select * from dept where deptno=20
END OF STMT
EXEC #139764967743728:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587087417430861
WAIT #139764967743728: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1587087417431676
FETCH #139764967743728:c=0,e=40,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587087417431764

*** 2020-04-17 09:38:51.141
CLOSE #139764967743728:c=0,e=17,dep=0,type=3,tim=1587087531141236
EXEC #139764967743728:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2852011669,tim=1587087531141445
WAIT #139764967743728: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1587087531141541
FETCH #139764967743728:c=0,e=44,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=2852011669,tim=1587087531141650
--//最后1次执行没有分析。

5总结：
--//在跟踪特定sql语句时，已经登录的会话可能会遇到无法抓取sql语句的情况，只要跟踪开始时循环执行相同的语句，就可能出现这样的情况。
--//实际上只要启动跟踪特定sql语句，已经登录的会话执行的是不要跟踪的sql，后面再执行特定sql语句，才能生成跟踪文件，语言不好表达，
--//我在这里测试很久才找到这个规律，大家可以自行测试。

--//之所以有这个测试，因为我在实际的工作环境中正好遇到这样的情况，无法跟踪特定的sql语句。