sql_trace

Here’s a convenient aid to trouble-shooting that appeared in 11g with its enhancements to setting events. It’s a feature that may help you to work out (among other things) why a given statement seems to have a highly variable performance profile. If you can find the SQL_ID for a parent cursor you can enable tracing for just that cursor whenever it executes, whoever executes it.

rem
rem     Script:         sql_trace_11g.sql
rem     Author:         Jonathan Lewis
rem     Dated:          May 2012
rem
rem     Last tested:
rem           19.11.0.0
rem           11.2.0.4
rem

define m_sql_id = '&1'
define m_sql_id = '9tz4qu4rj9rdp'

alter system set events
        '
        sql_trace[SQL: &m_sql_id ]
/*
        plan_stat=all_executions,
        wait=false,
        bind=false
*/
        '
;

pause Press return to stop tracing

alter system set events
        '
        sql_trace[SQL: &m_sql_id ]
        off
        '
;

This is the whole of a little script I’ve got – the generic &1 is how I normally use it, I’ve just included a specific value (which is the SQL_ID for “select count(*) from all_objects;” as an example) that starts tracing across the entire system, but only for a given SQL_ID. On a production system, if I think I really need to do this, I would check the expected frequency of execution for the statement and wait enough time to capture a few occurrences before disabling the trace. Each session generates its own trace file, but if you’ve been sufficiently patient you get a reasonable sampling of the different workloads – and if you’ve captured the bind variables as well, this may give you some clues about why different work loads can appear.

A nice detail about this feature is that if the SQL_ID is for a pl/sql block, all the SQL executing inside the block is traced as part of the trace on the block (and that was particularly helpful the last time I had to make use of the feature) and that makes it easy to see the effects of SQL statements calling PL/SQL functions that contain SQL statements. In the sample I’ve given I also found that some recursive SQL – relating to the xmlschema object types defined in the view – was also traced as the main statement was traced …

NOTE: the pingback in comment #1 will lead you to a note on how to use a similar method to force Oracle to dump the CBO (10053) trace file for a given SQL_ID every time it is hard parsed.

Update for 12c [Dec 2017]

Another little detail (which I hadn’t considered until a posting on Oracle forums today reminded me of the possibility) if you enable this trace for a statement the resulting trace file will also include the dynamic sampling SQL used by the optimizer in 12c as it tries to optimize the statement.  That’s a real boon if you’re trying to answer the question: “Why does it take so long to get going the first time I run this query?” when all the usual answers don’t apply.

Update Aug 2021

A question on the Oracle developers’ forum about getting the execution plans for all the SQL called by a table() operation reminded me that this is (usually) just a special case of tracing a pl/sql function. For example:

select * from table(dbms_xplan.display_cursor(format => 'outline'));

If you enable tracing for this statement (its SQL_ID is ’04j57fnt6uzg5′) then the trace file will contain all the SQL executed by the display_cursor() function of the dbms_xplan package whenever anyone executes the statement.

Footnote

You can use similar syntax to enable tracing in your own session while limiting the content of the trace file to just the specific SQL_ID you’re particularly interested in. Just change “system” to “session”, e.g.

create table t1 as select * from all_objects where rownum <= 50000;

alter session set events
        '
        sql_trace[SQL:g2y0pjcy1hnqr]
        plan_stat=all_executions,
        wait=false,
        bind=true
        '
;

declare 
        n1 number;
begin
        for r in (select distinct owner from t1) loop

                select  count(*) 
                into    n1
                from    t1 
                where   owner = r.owner
                ;

                dbms_output.put_line(r.owner || chr(9) || n1);

        end loop;
end;
/

alter session set events
        '
        sql_trace[SQL:g2y0pjcy1hnqr]
        off
        '
;

The trace file contains nothing but the details about executing the “select count(*) …” query, and the output from tkprof for the trace file shows:

SQL ID: g2y0pjcy1hnqr Plan Hash: 2432955788

SELECT COUNT(*)
FROM
 T1 WHERE OWNER = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     13      0.00       0.00          0          0          0           0
Fetch       13      0.00       0.00          0        134          0          13
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       26      0.00       0.00          0        134          0          13

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 112     (recursive depth: 1)
Number of plan statistics captured: 13

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=10 pr=0 pw=0 time=502 us starts=1)
         6       3846      42034   INDEX RANGE SCAN T1_I1 (cr=10 pr=0 pw=0 time=732 us starts=1 cost=1 size=30 card=6)(object id 168462)

Note how the highlighted line says there are 13 sets of plan statistics captured (one for each execution), and the Rows (1st) / (avg) / (max) are not identical for every line of the plan. The stats in the Row Source Operation column come from the first execution, so if you want to see the effects of the varying :B1 bind variable you have to examine the raw trace file (or play games with awk et. al.) or run tkprof with the option aggregate=no – which might produce a very large output file if there are lots of executions of the specified query in the trace file.