Infrastructure at your Service

Clemens Bleile

Enable 10046 Tracing for a specific SQL

Available methods to enable 10046 trace are described in My Oracle Support Note 376442.1. You can enable 10046-tracing

– on session level (alter session)
– for other sessions (e.g. with oradebug, the package DBMS_MONITOR or DBMS_SYSTEM)

What is not covered with the methods above is the possibility to trace a specific SQL-statement, which runs “somewhen” in the future on the database. E.g. a SQL, which runs during a next batch job. With the introduction of UTS (Unified Tracing Service) in 11.2., you can actually do exactly that:

I.e. suppose I need a 10046-trace, level 12 of the SQL with SQL_ID cjrha4bzuupzf, which runs somewhen in the next 24 hours. So what I have to do is to just set the event “sql_trace” for the SQL_ID:


SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] level=12';

REMARK: With the introduction of the parameter “_evt_system_event_propagation” in 11g (default is TRUE) the event-settings of “alter system set events”-commands are also propagated to existing sessions.

Let’s see if only the statement in question is being traced. From another session I’m doing the following:
REMARK: I actually want to trace the statement with the GATHER_PLAN_STATISTICS-hint.


SQL> select /* BEFORE TRACE */ count(*) from t1 where object_type='INDEX';
 
COUNT(*)
----------
1432
 
SQL> select /*+ GATHER_PLAN_STATISTICS */ count(*) from t1 where object_type='INDEX';
 
COUNT(*)
----------
1432
 
SQL> select /*+ AFTER TRACE */ count(*) from t1 where object_type='INDEX';
 
COUNT(*)
----------
1432
 
SQL> select value from v$diag_info where name = 'Default Trace File';
 
VALUE
--------------------------------------------------------------------
D:\APP\CBL\diag\rdbms\gen11204\gen11204\trace\gen11204_ora_11552.trc

Below is the content of the produced trace file:


=====================
PARSING IN CURSOR #305977200 len=79 dep=0 uid=42 oct=3 lid=42 tim=628480230944 hv=4289550318 ad='7ff95ed9ed80' sqlid='cjrha4bzuupzf'
select /*+ GATHER_PLAN_STATISTICS */ count(*) from t1 where object_type='INDEX'
END OF STMT
EXEC #305977200:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3724264953,tim=628480230943
WAIT #305977200: nam='SQL*Net message to client' ela= 1 driver id=1111838976 #bytes=1 p3=0 obj#=15671 tim=628480231942
FETCH #305977200:c=0,e=652,p=0,cr=189,cu=0,mis=0,r=1,dep=0,og=1,plh=3724264953,tim=628480232614
STAT #305977200 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=189 pr=0 pw=0 time=652 us)'
STAT #305977200 id=2 cnt=1432 pid=1 pos=1 obj=15671 op='TABLE ACCESS FULL T1 (cr=189 pr=0 pw=0 time=622 us cost=56 size=10024 card=1432)'
FETCH #305977200:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3724264953,tim=628480232838
WAIT #305977200: nam='SQL*Net message to client' ela= 1 driver id=1111838976 #bytes=1 p3=0 obj#=15671 tim=628480232858
*** 2016-02-05 15:11:21.578
WAIT #305977200: nam='SQL*Net message from client' ela= 1336677 driver id=1111838976 #bytes=1 p3=0 obj#=15671 tim=628481569546
CLOSE #305977200:c=0,e=8,dep=0,type=0,tim=628481569645

So, as expected, only the SQL with SQL_ID cjrha4bzuupzf has been traced.

To switch off the setting for SQL_ID cjrha4bzuupzf do the following:


SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] off';

The event settings done with “alter system set events …” are not persistent settings. I.e. after a next restart of the instance the event is no longer active. To set the event persistently you would have to set it in the spfile as well:


SQL> alter system set event='sql_trace[sql: cjrha4bzuupzf] level=12' scope=spfile;

If you want to see if an event is currently active on the running instance do the following:


SQL> oradebug setmypid
Statement processed.
SQL> oradebug eventdump session
sql_trace[sql: cjrha4bzuupzf] level=12

If you have several events set in your spfile then it’s difficult to remove a single one of them, because the events are stored concatenated with a “:” as a single event. You can just overwrite the current setting or remove them all:


SQL> alter system reset event scope=spfile;

REMARK: Do not set events (except event 10046) without the instruction from Oracle Support to do so. I also do recommend to NOT set event 10046 in the spfile.

Update on the 18th of December 2017: The tracing of a specific SQL is broken in 12.2. Thanks to Nenad Noveljic who discovered that (see the Comment section below). The issue seems caused by the bugs 25989066 and 25994378 which are fixed in 18.1. More details on the issue in 12.2. can be found in Nenad’s Blog.

 

10 Comments

  • Hi Clemens,
    Have you tested the feature in 12.2?
    Kind regards,
    Nenad

     
    • Hi Nenad,

      I just tested it in 12.2. (with RU 12.2.0.1.171121) and I actually got an ORA-7445 when switching the event off:


      SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] off';
      alter system set events 'sql_trace[sql: cjrha4bzuupzf] off'
      *
      ERROR at line 1:
      ORA-03113: end-of-file on communication channel
      Process ID: 29527
      Session ID: 253 Serial number: 44759

      I.e. my session crashed, but the remaining of the DB was not affected.

      The trace-file showed


      ORA-07445: exception encountered: core dump [dbgdUnLinkEvent()+596] [SIGSEGV] [ADDR:0x152C8000] [PC:0x40A92C4] [Address not mapped to object] []

      Doing the same statement again in a new session worked correctly:


      SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] off';
       
      System altered.

      This is actually a bug and I’ll open a SR for it.
      So basically it works in 12.2. as well, but there’s obviously a bug which needs to be fixed.

      Regards
      Clemens

       
  • Hi Clemens,

    The ORA-07445 (and possibly ORA-0600) is a consequence of incorrect handling of doubly linked lists where the events are stored.

    Actually, I should have been more precise when asking the question in the first place: does the SQL gets traced when “alter system set events” and the SQL itself are executed in two different sessions? I assume that you ran both commands in the same session.

    Regards,

    Nenad

     
    • Hi Nenad,
      I actually ran the commands (enable trace and SQL) in the same session:

      SQL> connect cbleile/cbleile
      Connected.
      SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] level=12';
       
      System altered.
       
      SQL> select /* BEFORE TRACE */ count(*) from t1 where object_type='INDEX';
       
      COUNT(*)
      ----------
      1893
       
      SQL> select /*+ GATHER_PLAN_STATISTICS */ count(*) from t1 where object_type='INDEX';
       
      COUNT(*)
      ----------
      1893
       
      SQL> select /*+ AFTER TRACE */ count(*) from t1 where object_type='INDEX';
       
      COUNT(*)
      ----------
      1893
       
      SQL> select value from v$diag_info where name = 'Default Trace File';
       
      VALUE
      --------------------------------------------------------------------------------
      /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_31583.trc
       
      SQL> exit
      Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
      oracle@12cr2:/home/oracle/ [prem122] sqh
       
      SQL*Plus: Release 12.2.0.1.0 Production on Thu Oct 19 00:57:07 2017
       
      Copyright (c) 1982, 2016, Oracle. All rights reserved.
       
      Connected to:
      Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
       
      SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf[ off';
      alter system set events 'sql_trace[sql: cjrha4bzuupzf[ off'
      *
      ERROR at line 1:
      ORA-03113: end-of-file on communication channel
      Process ID: 31609
      Session ID: 14 Serial number: 20845

      But it actually also fails when running it in different sessions:


      oracle@12cr2:/home/oracle/ [prem122] sqh
       
      SQL*Plus: Release 12.2.0.1.0 Production on Thu Oct 19 01:03:58 2017
       
      Copyright (c) 1982, 2016, Oracle. All rights reserved.
       
      Connected to:
      Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
       
      SQL> connect cbleile/cbleile
      Connected.
      SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] level=12';
       
      System altered.
       
      SQL> exit
      Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
      oracle@12cr2:/home/oracle/[prem122] sqh
       
      SQL*Plus: Release 12.2.0.1.0 Production on Thu Oct 19 01:04:13 2017
       
      Copyright (c) 1982, 2016, Oracle. All rights reserved.
       
      Connected to:
      Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
       
      SQL> connect cbleile/cbleile
      Connected.
      SQL> select /* BEFORE TRACE */ count(*) from t1 where object_type='INDEX';
       
      COUNT(*)
      ----------
      1893
       
      SQL> select /*+ GATHER_PLAN_STATISTICS */ count(*) from t1 where object_type='INDEX';
       
      COUNT(*)
      ----------
      1893
       
      SQL> select /*+ AFTER TRACE */ count(*) from t1 where object_type='INDEX';
       
      COUNT(*)
      ----------
      1893
       
      SQL> select value from v$diag_info where name = 'Default Trace File';
       
      VALUE
      --------------------------------------------------------------------------------
      /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_31769.trc
       
      SQL> exit
      Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
      oracle@12cr2:/home/oracle/ [prem122] sqh
       
      SQL*Plus: Release 12.2.0.1.0 Production on Thu Oct 19 01:04:50 2017
       
      Copyright (c) 1982, 2016, Oracle. All rights reserved.
       
      Connected to:
      Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
       
      SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] off';
      alter system set events 'sql_trace[sql: cjrha4bzuupzf] off'
      *
      ERROR at line 1:
      ORA-03113: end-of-file on communication channel
      Process ID: 31787
      Session ID: 31 Serial number: 32248

      Regards
      Clemens

       
      • Hi Clemens,

        If I’ve interpreted the output correctly, “alter system set events” and select… are ran in the same session. Afterwards, “alter system set events…off” was executed in a different session. However, have you tried to run the two following commands in separate sessions:
        1. alter system set events ‘sql_trace level=12′;
        2. select /*+ GATHER_PLAN_STATISTICS */ count(*) from t1 where object_type=’INDEX';

        I reckon, unlike in 12.1, the trace won’t be produced in 12.2.

        Regards,
        Nenad

         
        • Hi Nenad,

          you are right, the trace is only produced in 12.2. if I enable the event and run the SQL in the same session:


          SQL> connect cbleile/cbleile
          Connected.
          SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] level=12';
           
          System altered.
           
          SQL> select /*+ GATHER_PLAN_STATISTICS */ count(*) from t1 where object_type='INDEX';
           
          COUNT(*)
          ----------
          1893
           
          SQL> select value from v$diag_info where name = 'Default Trace File';
           
          VALUE
          --------------------------------------------------------------------------------
          /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_32054.trc
           
          SQL> !ls -l /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_32054.trc
          -rw-r-----. 1 oracle oinstall 2222 Oct 19 01:19 /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_32054.trc
           
          SQL> exit
          Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

          I.e. a trace file has been produced. But running the SQL in a different session there is no trace:

          SQL> connect cbleile/cbleile
          Connected.
          SQL> alter system set events 'sql_trace[sql: cjrha4bzuupzf] level=12';
           
          System altered.
           
          SQL> exit
          Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
          oracle@12cr2:/home/oracle/ [prem122] sqh
           
          SQL*Plus: Release 12.2.0.1.0 Production on Thu Oct 19 01:20:26 2017
           
          Copyright (c) 1982, 2016, Oracle. All rights reserved.
           
          Connected to:
          Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
           
          SQL> connect cbleile/cbleile
          Connected.
          SQL> select /*+ GATHER_PLAN_STATISTICS */ count(*) from t1 where object_type='INDEX';
           
          COUNT(*)
          ----------
          1893
           
          SQL> select value from v$diag_info where name = 'Default Trace File';
           
          VALUE
          --------------------------------------------------------------------------------
          /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_32098.trc
           
          SQL> !ls -l /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_32098.trc
          ls: cannot access /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_32098.trc: No such file or directory
           
          SQL> exit
          Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
          oracle@12cr2:/home/oracle/ [prem122] ls -l /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_32098.trc
          ls: cannot access /u02/app/oracle/diag/rdbms/prem122/prem122/trace/prem122_ora_32098.trc: No such file or directory

          I actually haven’t found anything about this behaviour change. Can you point me to any doc about this?

          Regards
          Clemens

           
  • Hi Clemens,

    I had discovered the problem recently, but unluckily haven’t found any reference to it so far. So, I posted the question on the Oracle-L list yesterday, but unfortunately haven’t obtained any feedback yet. Apparently, the problem doesn’t seem to be widely known at this point.

    What I’ve done so far is, managed to reconstruct the doubly linked list which gets created when “alter system set events” is issued and subsequently gets read by the Oracle kernel function dbgdSyncEventGrpsDirect which in turn is called when initializing UGA while connecting to the database. Sadly, the entry in the doubly linked list for the SQL trace event is being read, but discarded afterwards. I still haven’t figured out why this happens.

    By the way, the calling stack for dbgd* functions looks somewhat different when compared to 12.1, which means that the feature has undergone some changes.

    Regards,
    Nenad

     

Leave a Reply

Clemens Bleile
Clemens Bleile

Technology Leader and Senior Consultant