Occurence

Before you comment – I do know that the title has a spelling mistake in it and the ‘r’ should appear twice in “occurrence”. The error’s there because the Oracle code uses exactly this spelling in one of the little-used features of the new tracing mechanism.

I wrote a note a few years ago about enabling sql_trace (and other events) system-wide for a single SQL statement. In the note I suggested that you could enable tracing for a few minutes then disable it to minimize the impact on the system while still capturing a reasonable number of statement traces. A recent thread on the Oracle Developer forum, however, described a problem where a particular statement executed in the order of 1,000,000 times per hour – which is getting on for about 300 executions per second, and you probably don’t want to leave a system-wide trace running for any length of time when things are operating at that rate. Fortunately we can refine the method with the occurence [sic] filter to capture a small and limited number of executions, spread over as many sessions as are running. Here’s an example of the syntax:

rem
rem     Script: trace_occur.sql
rem     Author: Jonathan Lewis
rem     Dated:  April 2019
rem

define m_sql_id = 'gu1s28n6y73dg'
define m_sql_id = 'fu0ftxk6jcyya'

alter system set events 
        '
        sql_trace[SQL:&m_sql_id] 
        {occurence: start_after 101, end_after 496}
        bind=true,
        wait=true
        '
;

pause   Run the test script here and press return when it ends

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

All I’ve done, compared to the earlier note, is include in curly brackets, just after identifying the SQL ID, the text: “{occurence: start_after 101 , end_after 496}”. Roughly speaking this means that every session will start counting calls to the given statement and on the hundred and first it will start dumping the trace file, and for a total of 496 calls it will continue dumping the trace file. So it’s possible to make sure that a session does trace but doesn’t dump a huge volume of trace data. Of course I do still execute a call to switch tracing off for the statement otherwise every session that subsequently logs on will still start tracing and dump a few executions into their trace file.

There is, unfortunately, a catch. I don’t know how Oracle is counting for the start_after/end_after values – but it’s not executions of the statement, and it varies with working environment, and it changes as the trace is enabled, and it changes with version, and is probably dependent on the session_cached_cursors parameter, and it behaves differently when interacting with the PL/SQL cursor cache. It is perhaps easiest to show an example.

I have table called test_lobs (id, bytes …) with a unique index on (id) for this test.

create table test_lobs (
        id        number(8,0) primary key,
        bytes     number(8,0)
);

insert into test_lobs values(-1,999):
commit;

execute dbms_stats.gather_table_stats(user,'test_lobs')

And one of my test scripts is as follows:

rem
rem     This generates a statement with SQL_ID = gu1s28n6y73dg
rem

declare
        m_result number;
begin
        for i in 1..1000 loop
                begin
                        select bytes into m_result from test_lobs where id = i;
                exception
                        when others then null;
        end;
        end loop;
end;
/

Running 18.3 I start the trace script from one session, then start the test script from another session. As it stands the SQL statement embedded in the PL/SQL loop will have the SQL_ID I am tracing, so the second session will start dumping a trace file. The big question is: which executions of the statement will it dump? Since I’ve enabled bind variable dumping and the bound value is a simple loop counter it will be easy (!) to find the answer to this question.

To stabilize the results I did the following:

• Session 1: Create the table.
• Session 1: Start the trace event
• Session 2: Connect to the database and run the test
• Session 1: End the trace event
• Session 1: Start the trace event again
• Session 2: Connect to the database again and run the test a second time
• Session 1: End the trace event

I’ll explain the need for looking at the results of the second cycle in a moment.

The trace file I produced started with the first three lines below, and then repeated the 10 line highlighted fragment a number of times:

PARSING IN CURSOR #140126713239784 len=43 dep=1 uid=104 oct=3 lid=104 tim=168304257545 hv=233016751 ad='63b8f0c0' sqlid='gu1s28n6y73dg'
SELECT BYTES FROM TEST_LOBS WHERE ID = :B1
END OF STMT

====================================================================================================
BINDS #140126713239784:

 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7f71cb0c67c0  bln=22  avl=02  flg=05
  value=50
EXEC #140126713239784:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2054437130,tim=168304262695
FETCH #140126713239784:c=0,e=3,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=1,plh=2054437130,tim=168304262729
CLOSE #140126713239784:c=0,e=1,dep=1,type=3,tim=168304262772
====================================================================================================

Notice the bind value report. A key feature that we are interested in is the first “value=” reported and the last “value=”. In my case the low/high were 26 and 87, for a total of 62 executions. A little arithmetic (and a few corroborating checks) highlight the significance of the following:

• I started tracing after the 25th execution, and 25 * 4 + 1 = 101, my start_after value.
• I traced 62 executions and 62 * 8 = 496, my end_after value.

Oracle is counting something whenever it hits the SQL_ID we’ve specified but (for SQL inside a PL/SQL loop) it’s counting something which happens 4 times for each execution; then when it hits the start_after and starts tracing whatever it counts happens twice as often each time around the loop.

My general response to this type of detail is: “Argh!!!” – by the way. Maybe a call to Frits Hoogland or Stefan Koehler asking them to trace C functions is in order.

By this time you may have guessed why I examined the trace file from the second run of the test. The counting seems to include counts of database calls that take place in the recursive SQL needed to optimize / hard parse the query – anything that relates to the SQL_ID we specify may be included in the counts. So on the first test I got a load of garbage in the trace file then saw a partial dump of the trace data for value=2 and the trace file ended partway through the trace data for value=17.

As a further test, I had a go with pure SQL calls in a test script:

set serveroutput off
variable b1 number;

exec :b1 := 100
select bytes from test_lobs where id = :b1;

exec :b1 := 101
select bytes from test_lobs where id = :b1;

...

exec :b1 := 129
select bytes from test_lobs where id = :b1;

After getting a stable result, versions 12.1.0.2 and 18.3.0.0 behaved differently;

• 18.3.0.0 – counted 5 for every execution, so start_after = 16 skipped the first 3 executions and started tracing for value = 103
• 12.1.0.2 – counted 7 for the first execution and 5 thereafter, so start_after=8 skipped one execution, start_after=13 skipped two and so on.
• Both versions counted 10 for every execution while tracing was enabled, so end_after = 30 traced 3 executions in both cases.

It’s possible, of course, that some differences in the way session_cached_cursors works would for the small difference – but I suspect I could have spent a couple of days trying to sort out minor variations due to slight parameter and implementation changes between versions. It’s also possible that some of my guesses are wrong and there is more method to the madness than I have spotted.

Conclusion

It is possible to enable tracing system-wide for a limited number of executions per session of a given statement; however the number of executions that might take place before tracing starts and the number of executions actually traced depends on a variety of details of which some may be outside your control.

As a baseline, it looks as if the number of executions before tracing starts is going to be about one-fifth of the value you set for start_after, and the number of executions trace will be about one-tenth of the end_after; however recursive SQL (perhaps even including dynamic sampling) can get caught up in the counts, potentially reducing the number of executions of the target statement that you see.