In Oracle 12.2, Oracle Corp. added the ability to run SQL trace on specific SQL_ID. So, let’s get SQL_ID for tracing:
SQL> select sql_id,sql_text from v$sqlstats where lower(sql_text) like 'select%from emp%';
SQL_ID SQL_TEXT
________________ __________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________________
0a56fma6rh6c8 SELECT /* DS_SVC */ /*+ dynamic_sampling(0) no_sql_tune no_monitoring optimizer_features_enable(default) no_parallel */ NVL(SUM(C1),0) FROM (SELECT /*+ qb_name("innerQuery") */ 1 AS C1 FROM (SELECT "X$KGLCURSOR_CHILD"."KGLOBT03" "SQL_ID","X$KGLCURSOR_CHILD"."KGLNAOBJ" "SQL_TEXT" FROM "SYS"."X$KGLCURSOR_CHILD" "X$KGLCURSOR_CHILD" WHERE ("X$KGLCURSOR_CHILD"."CON_ID"=0 OR "X$KGLCURSOR_CHILD"."CON_ID"=3) AND LOWER("X$KGLCURSOR_CHILD"."KGLNAOBJ") LIKE 'select%from emp%' AND "X$KGLCURSOR_CHILD"."INST_ID"=USERENV('INSTANCE')) "VW_QBEST_Q") innerQuery
g5hn8a7munp3u select sql_id,sql_text from v$sql where lower(sql_text) like 'select%from emp%'
08xtxky9ths2s SELECT /* DS_SVC */ /*+ dynamic_sampling(0) no_sql_tune no_monitoring optimizer_features_enable(default) no_parallel */ NVL(SUM(C1),0) FROM (SELECT /*+ qb_name("innerQuery") */ 1 AS C1 FROM (SELECT "X$KKSSQLSTAT"."SQL_ID" "SQL_ID","X$KKSSQLSTAT"."SQL_TEXT" "SQL_TEXT" FROM "SYS"."X$KKSSQLSTAT" "X$KKSSQLSTAT" WHERE LOWER("X$KKSSQLSTAT"."SQL_TEXT") LIKE 'select%from emp%' AND ("X$KKSSQLSTAT"."CON_ID"=0 OR "X$KKSSQLSTAT"."CON_ID"=3) AND "X$KKSSQLSTAT"."INST_ID"=USERENV('INSTANCE')) "VW_QBEST_Q") innerQuery
b1bsmpmm2stn0 SELECT /* DS_SVC */ /*+ dynamic_sampling(0) no_sql_tune no_monitoring optimizer_features_enable(default) no_parallel */ NVL(SUM(C1),0) FROM (SELECT /*+ qb_name("innerQuery") */ 1 AS C1 FROM "SYS"."X$KKSSQLSTAT" "X$KKSSQLSTAT" WHERE (LOWER("X$KKSSQLSTAT"."SQL_TEXT") LIKE 'select%from emp%') AND ("X$KKSSQLSTAT"."CON_ID"=0 OR "X$KKSSQLSTAT"."CON_ID"=3)) innerQuery
484mc6v3sxqrj SELECT /* DS_SVC */ /*+ dynamic_sampling(0) no_sql_tune no_monitoring optimizer_features_enable(default) no_parallel */ NVL(SUM(C1),0) FROM (SELECT /*+ qb_name("innerQuery") */ 1 AS C1 FROM "SYS"."X$KGLCURSOR_CHILD" "X$KGLCURSOR_CHILD" WHERE (LOWER("X$KGLCURSOR_CHILD"."KGLNAOBJ") LIKE 'select%from emp%') AND ("X$KGLCURSOR_CHILD"."CON_ID"=0 OR "X$KGLCURSOR_CHILD"."CON_ID"=3)) innerQuery
a2dk8bdn0ujx7 select * from emp
43vmxqgq37j7m select sql_id,sql_text from v$sqlstats where lower(sql_text) like 'select%from emp%'
7 rows selected.
OK, we now have SQL_ID=’a2dk8bdn0ujx7′ for SQL being “select * from emp”. The “old” mechanism, if 12.2 invention can be called that, looks like this:
SQL> alter system set events='SQL_TRACE[SQL:a2dk8bdn0ujx7] wait=true';
System SET altered.
The trace file can be conveniently located from V$DIAG_INFO
SQL> select value from v$diag_info where name='Default Trace File';
VALUE
__________________________________________________________
/opt/oracle/diag/rdbms/free/FREE/trace/FREE_ora_638.trc
The file looks just like we would expect:
Trace file /opt/oracle/diag/rdbms/free/FREE/trace/FREE_ora_638.trc
Oracle Database 23c Free, Release 23.0.0.0.0 - Developer-Release
Version 23.2.0.0.0
Build label: RDBMS_23.2.0.0.0_LINUX.X64_230325
ORACLE_HOME: /opt/oracle/product/23c/dbhomeFree
System name: Linux
Node name: umajor
Release: 6.3.4-201.fc38.x86_64
Version: #1 SMP PREEMPT_DYNAMIC Sat May 27 15:08:36 UTC 2023
Machine: x86_64
CLID: P
Instance name: FREE
Redo thread mounted by this instance: 1
Oracle process number: 105
Unix process pid: 638, NID: 4026533011, image: oracle@umajor
*** 2023-06-02T16:14:52.580358+00:00 (FREEPDB1(3))
*** SESSION ID:(1034.30759) 2023-06-02T16:14:52.580395+00:00
*** CLIENT ID:() 2023-06-02T16:14:52.580415+00:00
*** SERVICE NAME:(freepdb1) 2023-06-02T16:14:52.580431+00:00
*** MODULE NAME:(SQLcl) 2023-06-02T16:14:52.580446+00:00
*** ACTION NAME:() 2023-06-02T16:14:52.580462+00:00
*** CLIENT DRIVER:(jdbcthin : 21.10.0.0.0) 2023-06-02T16:14:52.580475+00:00
*** CONTAINER ID:(3) 2023-06-02T16:14:52.580491+00:00
*** CLIENT IP:(127.0.0.1) 2023-06-02T16:14:52.580506+00:00
=====================
PARSING IN CURSOR #140695102917112 len=678 dep=1 uid=0 oct=3 lid=0 tim=11592632601 hv=3152351506 ad='6bd42430' sqlid='ga4mbqqxya48k'
select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowc
nt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.f
lbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,nvl(t.spare7,0),ts.cachedblk,ts.cachehit,ts.logicalread,
ts.im_imcu_count,ts.im_block_count,ts.im_sys_incarnation,ts.im_stat_update_time,ts.scanrate,nvl(t.acdrflags, 0),nvl(t.acdrtsobj#, 0),t.acdrdefau
lttime,nvl(t.acdrrowtsintcol#, 0) from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)
END OF STMT
EXEC #140695102917112:c=44,e=44,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2035254952,tim=11592632595
......
That is very well known and nothing to blog about. However, in Oracle 23c, there is a new package called DBMS_USERDIAG. The package looks very practical and promising:
SQL> desc dbms_userdiag
PROCEDURE CHECK_SQL_TRACE_EVENT
Argument Name Type In/Out Default?
________________ _________________ _________ ___________
LEVEL BINARY_INTEGER OUT
SQL_ID VARCHAR2 IN DEFAULT
SYS BINARY_INTEGER IN DEFAULT
PROCEDURE ENABLE_SQL_TRACE_EVENT
Argument Name Type In/Out Default?
________________ _________________ _________ ___________
LEVEL BINARY_INTEGER IN DEFAULT
SID BINARY_INTEGER IN DEFAULT
SER BINARY_INTEGER IN DEFAULT
BINDS BINARY_INTEGER IN DEFAULT
WAITS BINARY_INTEGER IN DEFAULT
PLAN_STAT VARCHAR2 IN DEFAULT
SQL_ID VARCHAR2 IN DEFAULT
DISABLE BINARY_INTEGER IN DEFAULT
SYS BINARY_INTEGER IN DEFAULT
FUNCTION GET_CALL_ERROR_MSG RETURNS VARCHAR2
FUNCTION GET_CALL_STATUS RETURNS NUMBER
PROCEDURE SET_EXCEPTION_MODE
Argument Name Type In/Out Default?
________________ __________ _________ ___________
EXC_MODE BOOLEAN IN DEFAULT
PROCEDURE SET_TRACEFILE_IDENTIFIER
Argument Name Type In/Out Default?
_________________ ___________ _________ ___________
TRC_IDENTIFIER VARCHAR2 IN
PROCEDURE TRACE
Argument Name Type In/Out Default?
________________ _________________ _________ ___________
MESSAGE VARCHAR2 IN
ALERT BINARY_INTEGER IN DEFAULT
So, let’s turn off tracing for the given statement id:
SQL> alter system set events='SQL_TRACE[SQL:a2dk8bdn0ujx7] level=0';
System SET altered.
Now, let’s try with the DBMS_USERDIAG package:
SQL> exec DBMS_USERDIAG.ENABLE_SQL_TRACE_EVENT(waits=>1,sql_id=>'a2dk8bdn0ujx7');
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.03
Now, we need to re-execute the statement and check the trace file:
SQL> select * from emp;
EMPNO ENAME JOB MGR HIREDATE SAL COMM DEPTNO
________ _________ ____________ _______ ___________ _______ _______ _________
7369 SMITH CLERK 7902 19801217 800 20
7499 ALLEN SALESMAN 7698 19810220 1600 300 30
7521 WARD SALESMAN 7698 19810222 1250 500 30
7566 JONES MANAGER 7839 19810402 2975 20
7654 MARTIN SALESMAN 7698 19810928 1250 1400 30
7698 BLAKE MANAGER 7839 19810501 2850 30
7782 CLARK MANAGER 7839 19810609 2450 10
7788 SCOTT ANALYST 7566 19870419 3000 20
7839 KING PRESIDENT 19811117 5000 10
7844 TURNER SALESMAN 7698 19810908 1500 0 30
7876 ADAMS CLERK 7788 19870523 1100 20
7900 JAMES CLERK 7698 19811203 950 30
7902 FORD ANALYST 7566 19811203 3000 20
7934 MILLER CLERK 7782 19820123 1300 10
14 rows selected.
Elapsed: 00:00:00.012
SQL> select value from v$diag_info where name='Default Trace File';
VALUE
__________________________________________________________
/opt/oracle/diag/rdbms/free/FREE/trace/FREE_ora_829.trc
Elapsed: 00:00:00.005
Unfortunately, when checking with ADRCI, there is nothing there:
adrci> show trace /opt/oracle/diag/rdbms/free/FREE/trace/FREE_ora_829.trc
DIA-48908: No trace files are found
It looks like the first bug in Oracle 23c. Of course, Oracle 23c FREE, which I am using here, is just an XE version and an early version at that. Now, the philosophical part of tracing. Tracing is usually done on the entire session, to see where the time is spent and to locate the SQL that may need to be improved. Why would anyone want to trace a single statement? The reason for tracing a single statement is very simple: sometimes, the problem with SQL is not in the plan, but in the extenuating circumstances, like global cache events in the RAC environment or waiting for a lock in the 2PC environment.
Tracing the particular SQL_ID is usually done very rarely, but when it does need to be done, it’s an extremely useful tool.
dbwhisperer 
