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!

4 responses to “SQL trace on Autonomous”

  1. Rajeshwaran Jeyabal Avatar
    Rajeshwaran Jeyabal

    This is on ADB-S.
    When I tried to run ALTER SESSION for SQL_TRACE, it failed with the following error.
    Did I miss something here? Please advise.

    admin@ATP19C> alter session set sql_trace = true;
    ERROR:
    ORA-02097: parameter cannot be modified because specified value is invalid
    ORA-20000: Missing database property for object store credentials
    Help: https://docs.oracle.com/error-help/db/ora-02097/

      1. Rajeshwaran Jeyabal Avatar
        Rajeshwaran Jeyabal

        Thanks, Connor — this helps.

        Just trying to understand — in what kind of use cases would someone still need to use SQL Trace, given that features like the SQL Monitor Report are available?

        I’m aware of the SQL Monitor is available only for statements that run for more than 5 sec or for parallel statements , or should be explicitly enabled using monitor hint – https://sqlmaria.com/2017/08/01/getting-the-most-out-of-oracle-sql-monitor/

        1. Easy – you run a program and it runs for 2 hours and ran 175,000 SQL statements between an app server and the database. Help me diagnose that with SQL Monitor 🙂

Leave a reply to Rajeshwaran Jeyabal Cancel reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Trending