I’ve blogged before about activating SQL trace on autonomous database, but here’s a little addenda that you might appreciate.
Lets assume I’ve done the setup as described in the blog and now I’m going to do some tracing on a long running SQL statement
SQL> alter session set sql_trace = true;
Session altered.
SQL> select max(lo_shipmode) from ssb.lineorder;
MAX(LO_SHI
----------
TRUCK
1 row selected.
SQL> alter session set sql_trace = false;
Session altered.
SQL> set pages 0
SQL> set lines 9999
SQL> spool c:\tmp\trace.out
SQL> select trace
2 from session_cloud_trace
3 order by row_number;
TRACE
----------------------------------------------------------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.29.0.1.0
Build label: RDBMS_PT.DBCLOUD19_LINUX.X64_250923
ORACLE_HOME: /u02/app/oracle/product/19.0.0.0_250923_251019-070249/dbhome_1
System name: Linux
Node name: xxxxxxxx
...
=====================
PARSING IN CURSOR #139962354157104 len=42 dep=0 uid=80 oct=3 lid=80 tim=2102213563585 hv=3469552605 ad='c98677a20' sqlid='64avp0b7cuayx'
select max(lo_shipmode) from ssb.lineorder
END OF STMT
PARSE #139962354157104:c=23008,e=25908,p=14,cr=2059,cu=12,mis=1,r=0,dep=0,og=1,plh=2267213921,tim=2102213563585
FETCH #139962354157104:c=84822342,e=106665862,p=21161175,cr=21161229,cu=0,mis=0,r=1,dep=0,og=1,plh=2267213921,tim=2102320229512
FETCH #139962354157104:c=17281,e=537319,p=1,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=2810914317,tim=2102717129736
CLOSE #139962354157104:c=17,e=17,dep=0,type=0,tim=2102320515935
=====================
PARSING IN CURSOR #139962354157104 len=35 dep=0 uid=80 oct=42 lid=80 tim=2102320515984 hv=310044142 ad='0' sqlid='988n7wn97ptgf'
alter session set sql_trace = false
END OF STMT
PARSE #139962354157104:c=16,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=2102320515984
3292 rows selected.
SQL> spool off
I could format that with tkprof, but even without that I can see that the FETCH took 106 seconds (e=106665862).
However, anyone with a familiarity with session tracing can spot that we’re missing one critical ingredient of the puzzle which would let us dig into why the fetch took 106 seconds…. The WAIT information!
If you try do that using some of the common methods, you will discover that this is locked down on Autonomous, because full ALTER SESSION is an incredibly dangerous privilege to give to anyone. ( That is true on any database for that matter)
SQL> alter session set events = '10046 trace name context forever, level 8';
ERROR:
ORA-01031: insufficient privileges
SQL> exec dbms_session.session_trace_enable(waits=>true)
BEGIN dbms_session.session_trace_enable(waits=>true); END;
*
ERROR at line 1:
ORA-01031: insufficient privileges
ORA-06512: at "SYS.DBMS_SESSION", line 343
ORA-06512: at line 1
You could try using DBMS_MONITOR, which will not return an error, but it’s not going to give you the trace data you wanted.
SQL> exec dbms_monitor.session_trace_enable(waits=>true)
PL/SQL procedure successfully completed.
SQL> select * from emp;
EMPNO ENAME JOB MGR HIREDATE SAL COMM DEPTNO
---------- ---------- --------- ---------- --------- ---------- ---------- ----------
7369 SMITH CLERK 7902 17-DEC-80 800 20
7499 ALLEN SALESMAN 7698 20-FEB-81 1600 300 30
7521 WARD SALESMAN 7698 22-FEB-81 1250 500 30
7566 JONES MANAGER 7839 02-APR-81 2975 20
7654 MARTIN SALESMAN 7698 28-SEP-81 1250 1400 30
7698 BLAKE MANAGER 7839 01-MAY-81 2850 30
7782 CLARK MANAGER 7839 09-JUN-81 2450 10
7788 SCOTT ANALYST 7566 09-DEC-82 3000 20
7839 KING PRESIDENT 17-NOV-81 5000 10
7844 TURNER SALESMAN 7698 08-SEP-81 1500 30
7876 ADAMS CLERK 7788 12-JAN-83 1100 20
7900 JAMES CLERK 7698 03-DEC-81 950 30
7902 FORD ANALYST 7566 03-DEC-81 3000 20
7934 MILLER CLERK 7782 23-JAN-82 1300 10
14 rows selected.
SQL> exec dbms_monitor.session_trace_disable;
PL/SQL procedure successfully completed.
SQL> select trace
2 from session_cloud_trace
3 order by row_number;
no rows selected
However, some good news is at hand. As long as you active SQL trace with “alter session set sql_trace = true”, than you can subsequently activate the waits with DBMS_MONITOR
SQL> alter session set sql_trace = true;
Session altered.
SQL> exec dbms_monitor.session_trace_enable(waits=>true);
PL/SQL procedure successfully completed.
SQL> select max(lo_shipmode) from ssb.lineorder;
MAX(LO_SHI
----------
TRUCK
1 row selected.
SQL> alter session set sql_trace = false;
Session altered.
SQL> set pages 0
SQL> set lines 9999
SQL> spool c:\tmp\trace.out
SQL> select trace
2 from session_cloud_trace
3 order by row_number;
TRACE
----------------------------------------------------------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.29.0.1.0
Build label: RDBMS_PT.DBCLOUD19_LINUX.X64_250923
ORACLE_HOME: /u02/app/oracle/product/19.0.0.0_250923_251019-070249/dbhome_1
System name: Linux
Node name: xxxxxxxx
...
=====================
PARSING IN CURSOR #139962354157104 len=42 dep=0 uid=80 oct=3 lid=80 tim=2102213563585 hv=3469552605 ad='c98677a20' sqlid='64avp0b7cuayx'
select max(lo_shipmode) from ssb.lineorder
END OF STMT
PARSE #139962354157104:c=23008,e=25908,p=14,cr=2059,cu=12,mis=1,r=0,dep=0,og=1,plh=2267213921,tim=2102213563585
EXEC #139962354157104:c=24,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2267213921,tim=2102213563619
WAIT #139962354157104: nam='SQL*Net message to client' ela= 5 driver id=1952673907 #bytes=1 p3=0 obj#=-1 tim=2102213563642
WAIT #139962354157104: nam='cell single block physical read: xrmem cache' ela= 197 cellhash#=1642384546 diskhash#=0 bytes=8192 obj#=30820 tim=2102213566813
WAIT #139962354157104: nam='cell single block physical read: xrmem cache' ela= 157 cellhash#=1299379196 diskhash#=0 bytes=8192 obj#=30820 tim=2102213570453
WAIT #139962354157104: nam='cell smart table scan' ela= 140 cellhash#=1642384546 p2=0 p3=0 obj#=30820 tim=2102213570804
WAIT #139962354157104: nam='cell smart table scan' ela= 121 cellhash#=1299379196 p2=0 p3=0 obj#=30820 tim=2102213571057
WAIT #139962354157104: nam='cell smart table scan' ela= 127 cellhash#=3707261927 p2=0 p3=0 obj#=30820 tim=2102213571296
WAIT #139962354157104: nam='cell smart table scan' ela= 179 cellhash#=491865413 p2=0 p3=0 obj#=30820 tim=2102213571594
WAIT #139962354157104: nam='cell smart table scan' ela= 154 cellhash#=134147362 p2=0 p3=0 obj#=30820 tim=2102213571866
WAIT #139962354157104: nam='cell disk open' ela= 137 cellid#=1433234330 where=2 p3=0 obj#=30820 tim=2102213572132
...
...
...
WAIT #139962354157104: nam='cell smart table scan' ela= 520 cellhash#=3617326319 p2=0 p3=0 obj#=-1 tim=2102320232313
WAIT #139962354157104: nam='cell smart table scan' ela= 516 cellhash#=2522958051 p2=0 p3=0 obj#=-1 tim=2102320232844
WAIT #139962354157104: nam='cell smart table scan' ela= 436 cellhash#=1642384546 p2=0 p3=0 obj#=-1 tim=2102320233287
WAIT #139962354157104: nam='cell smart table scan' ela= 348 cellhash#=3746744758 p2=0 p3=0 obj#=-1 tim=2102320233640
WAIT #139962354157104: nam='cell smart table scan' ela= 461 cellhash#=1299379196 p2=0 p3=0 obj#=-1 tim=2102320234116
WAIT #139962354157104: nam='cell smart table scan' ela= 476 cellhash#=2523353637 p2=0 p3=0 obj#=-1 tim=2102320234608
WAIT #139962354157104: nam='cell smart table scan' ela= 499 cellhash#=134147362 p2=0 p3=0 obj#=-1 tim=2102320235121
WAIT #139962354157104: nam='cell smart table scan' ela= 482 cellhash#=491865413 p2=0 p3=0 obj#=-1 tim=2102320235621
WAIT #139962354157104: nam='PGA memory operation' ela= 4000 which=5 bytes=36634624 where=4 obj#=-1 tim=2102320239783
WAIT #139962354157104: nam='SQL*Net message from client' ela= 276023 driver id=1952673907 #bytes=1 p3=0 obj#=-1 tim=2102320515836
CLOSE #139962354157104:c=17,e=17,dep=0,type=0,tim=2102320515935
=====================
PARSING IN CURSOR #139962354157104 len=35 dep=0 uid=80 oct=42 lid=80 tim=2102320515984 hv=310044142 ad='0' sqlid='988n7wn97ptgf'
alter session set sql_trace = false
END OF STMT
PARSE #139962354157104:c=16,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=2102320515984
26823 rows selected.
Look at all that WAIT goodness in there!




Leave a reply to Rajeshwaran Jeyabal Cancel reply