Oracle diagnostic events — Cheat sheet

Oracle diagnostic events is a great feature, but unfortunately poorly documented and nonintuitive, so it’s difficult to remember all events/actions/parameters and even read its internal documentation using oradebug. So I decided to compile its internal doc as a more convenient html-version (https://orasql.org/files/events/) and make a cheat sheet of some unknown or little-known use cases.

Example 1:

alter system set events 
   'kg_event[1476]
        {occurence: start_after 1, end_after 3}
            trace("stack is: %\n", shortstack())
            errorstack(2)
    ';

1. kg_event[errno] – Kernel Generic event in library Generic for error number events, which instructs to trace ORA-errno errors;
2. {occurence: start_after X, end_after Y} – is a filter, which instructs to skip X event checks and trace just Y times;
3. trace(format, str1, str2, …, str15) – is a function from ACTIONS for printing into a trace file;
4. shortstack() – is a function from ACTIONS , which returns a short call stack as a string;
5. errorstack(level) – is a function from ACTIONS, which prints extended info (level: 0 – errorstack only, 1 – errorstack + call stack, 2 – as level 1 + processtate, 3 – as level 2 + context area). You can get more details with  PROCESSSTATE or SYSTEMSTATE. If you need just a call stack, you can use CALLSTACK(level) , with function arguments in case of level>1.

Example 2:

alter system set events 
    'trace[SQL_Compiler.* | SQL_Execution.*]
        [SQL: ...]
            {process: ospid = ...}
            {occurence:end_after 3}
                controlc_signal()';

1. trace[component] – is the main diagnostic event, which allows to specify Components to trace. This command shows how to specify all child components of SQL_Compiler and SQL_Execution. 
2. SQL[SQL: sqlid ] – is the only SCOPE in library RDBMS, which allows to trace specific SQL_ID and all its recursive calls (or for example, if you specify sql_id of a PL/SQL call, then all its internal queries will be traced too);
3. {process: …} – is a filter, which allows to filter processes;
4. controlc_signal – is an ACTION, that raises “ORA-01013: user requested cancel of current operation”, ie it’s like this session interrupted own call.

I’ve used this command recently when I had to help developers to find where some suboptimal and unnecessary queries, discovered during performance load testing, come from their code (huge webapp with hibernate).

Example 3:

alter system set events 
    'sql_trace {process: ospid = ...} 
     trace("sqlid(%): %\n", sqlid(), evfunc())
     ';

sql_trace – is just a good old trace event #10046, and this function forces oracle to print a function name and sql_id for each sql_trace event. Simple example:

As you can see we get 26 “occurrences” in case of “_rowsource_statistics_sampfreq”=1 instead just 12 by default. More details about this here: https://alexanderanokhin.com/2012/12/24/timing-rowsource-statistics-part-2-overhead-and-inconsistent-time/

Example 4:

alter system set events 
    'wait_event["enq: TM - contention"]
        {wait: minwait=1000} 
            errorstack(1)
            trace("event=[%] sqlid=%, ela=% p1=% p2=% p3=%\n", 
                   evargs(5), sqlid(), evargn(1), evargn(2), evargn(3), evargn(4))
    ';

1. wait_event[name] – event to control wait event post-wakeup actions, first argument is a wait event name, all wait event names and their parameters (P1,P2,P3) you can find in v$event_name:

select 
   wait_class,name
  ,parameter1,parameter2,parameter3
  ,display_name 
from v$event_name;

2. {wait: … } – is a filter that allows to specify both the minimum wait time(ms) and parameters P1, P2, P3. For example, for this “TM-contention” wait event, P2 is “object #”, and we can specify {wait: minwait=1000; p2=12345}, ie only table TM-lock wait events on the table with object_id=12345 and longer than 1 sec;
3. evargX() – functions from ACTIONs, which return event check arguments values, where 1st argument is an elapsed time(ms), 2nd-4th – parameters p1-p3, and 5th – wait event name. kg_event has own related functions – errargX().

Example 5:

Occasionally, it may be useful to investigate which session variables have been altered. Consider the case where someone forgot to specify nls parameters in to_number() and didn’t specify "on conversion error" clause, and some session sporadically get “ORA-01722: invalid number”:

-- original parameters:
SQL> alter session set nls_numeric_characters='.,';

Session altered.

-- all works fine...
SQL> select to_number('1,200.3','999g999d999') + 10 from dual;

TO_NUMBER('1,200.3','999G999D999')+10
-------------------------------------
                               1210.3

-- until they've been changed at some point:
SQL> alter session set nls_numeric_characters=".'";

Session altered.

-- obviously we get errors:
SQL> select to_number('1,200.3','999g999d999') + 10 from dual;
select to_number('1,200.3','999g999d999') + 10 from dual
                 *
ERROR at line 1:
ORA-01722: invalid number

There is no special view for session parameters which are not a part of v$ses_optimizer_env, but we can easily get them using  MODIFIED_PARAMETERS():

alter system set events 
    'kg_event[1722] 
        {process: ospid=27556}
        {occurence:end_after 1}
            MODIFIED_PARAMETERS()';

And since we have v$diag_alert_ext for alert.log and v$diag_trace_file_contents for trace files, we can get them using this simple query:

select c.payload
from v$diag_trace_file_contents c
where 1=1
  and c.session_id   = &sid -- session sid 
  and c.serial#      = &serial -- session serial#
  and c.section_name = 'Error Stack' -- they will be in "Error Stack"
--  and c.payload like '%nls_numeric%' -- we can filter only specific nls parameters
  and c.timestamp>systimestamp-interval'15'minute -- last 15 minutes
;

-- Results:
DYNAMICALLY MODIFIED PARAMETERS:
  nls_language             = "AMERICAN"
  nls_territory            = "AMERICA"
  nls_sort                 = "BINARY"
  nls_date_language        = "AMERICAN"
  nls_date_format          = "yyyy-mm-dd hh24:mi:ss"
  nls_currency             = "$"
  nls_numeric_characters   = ".'"
  nls_iso_currency         = "AMERICA"
  nls_calendar             = "GREGORIAN"
  nls_time_format          = "hh24:mi:ssxff"
  nls_timestamp_format     = "yyyy-mm-dd hh24:mi:ssxff"
  nls_time_tz_format       = "hh24:mi:ssxff TZR"
  nls_timestamp_tz_format  = "yyyy-mm-dd hh24:mi:ssxff TZR"
  nls_dual_currency        = "$"
  nls_comp                 = "BINARY"
  local_listener           = ""

Update 1:

I’ve just got a question:

We use “Extensible Optimizer Interface”, i.e. Oracle CBO calls such code internally, which fails periodically with “ORA-06550 PL/SQL compile error“. Can we specify both “kg_event” and “sql_id” so we could get those errors with details in alert.log?

Of course, we can – simple example:

alter system set events 
    'kg_event[6550]
        [sql: 5cmnpq8t0g7pd]
            {occurence: start_after 1, end_after 3}
                errorstack(3)
                incident(plserrors)
      ';

As you can see we use incident(label) here to generate an incident file (which you can easily pack and send to Oracle support or consulters) and kg_event[6550] to trace  “ORA-06550: line %, column %” errors.

Update 2:

Just link to my another post: Where does the commit or rollback happen in PL/SQL code?

https://orasql.org/2021/09/12/where-does-the-commit-or-rollback-happen-in-pl-sql-code/

Update 3:

Recently in telegram I’ve got a question: how to catch and trace ‘alter table’ operation?
In this case we can find a function that executes alter table on orafun.info (function ‘atb’) and use this function name for a filter {callstack: fprefix ...}, for example:

alter session set events 
    'sql_trace {callstack: fprefix atb} {occurence:end_after 1} errorstack(1)';

And you’ll get in the trace file something like this:

dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=1, mask=0x0)
----- Error Stack Dump -----
<error barrier> at 0x7ffe52ad1db0 placed dbkda.c@296
----- Current SQL Statement for this session (sql_id=ggx91ms9duqbz) -----
alter table dd add b int
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x7977d758         1  anonymous block

----- Call Stack Trace -----
calling              call     entry                argument values in hex
location             type     point                (? means dubious value)
-------------------- -------- -------------------- ----------------------------

Useful links:

Very useful articles by Tanel Poder:
1. The full power of Oracle’s diagnostic events, part 1: Syntax for KSD debug event handling
2. The full power of Oracle’s diagnostic events, part 2: ORADEBUG DOC and 11g improvements
3. What Caused This Wait Event: Using Oracle’s wait_event[] tracing
4. http://tech.e2sn.com/oracle/troubleshooting/oradebug-doc

Ora C functions on Frits Hoogland’s site: http://orafun.info/

HTML version of the internal oradebug/diagnostic events doc: https://orasql.org/files/events