As of 11g the package DBMS_MONITOR provides an important new feature. The aim of this post is to describe not only what this feature is, but also why it is important.
To illustrate how the new feature works, two things are necessary. First, a small table:
SQL> SELECT * FROM t;
N
----------
1
2
3
4
5
Second, an anonymous PL/SQL block. About it notice that:
- Three queries using the very same cursor are executed.
- The number of fetched rows is different for each execution.
- Array processing is used to fetch all data in a single call.
- The package DBMS_MONITOR is used to enable and disable SQL trace.
DECLARE
l_cursor INTEGER;
l_n dbms_sql.number_table;
l_retval INTEGER;
BEGIN
dbms_monitor.session_trace_enable;
l_cursor := dbms_sql.open_cursor;
dbms_sql.parse(l_cursor, 'SELECT n FROM t WHERE n <= :1', 1);
dbms_sql.define_array(l_cursor, 1, l_n, 5, 1);
FOR i IN 1..3
LOOP
dbms_sql.bind_variable(l_cursor, ':1', i);
l_retval := dbms_sql.execute(l_cursor);
l_retval := dbms_sql.fetch_rows(l_cursor);
END LOOP;
dbms_sql.close_cursor(l_cursor);
dbms_monitor.session_trace_disable;
END;
Now, let’s start by executing the anonymous PL/SQL block in 10.2.0.4. In that version, the content of the generated trace file is the following. Notice that:
- One single parse (PARSE line) was performed.
- Three executions (EXEC lines) were performed.
- Three fetches (FETCH lines) were performed. The first one fetched 1 row (value “r”), the second one fetched 2 rows, and the third one fetched 3 rows.
- The information about the execution plan (STAT line; notice that I manually removed the runtime statistics and query optimizer estimations to keep the output more readable) was written in the trace file only when the cursor was closed. According to it, 6 rows were fetched (value “cnt”). In other words, 1+2+3.
PARSING IN CURSOR #18 len=29 dep=1 uid=28 oct=3 lid=28 tim=1204698401458764 hv=2067044879 ad='72de8330'
SELECT n FROM t WHERE n <= :1
END OF STMT
PARSE #18:c=0,e=427,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1204698401458760
EXEC #18:c=1000,e=912,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1204698401509992
FETCH #18:c=0,e=68,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,tim=1204698401510109
EXEC #18:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1204698401510184
FETCH #18:c=0,e=26,p=0,cr=3,cu=0,mis=0,r=2,dep=1,og=1,tim=1204698401510234
EXEC #18:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1204698401510290
FETCH #18:c=0,e=19,p=0,cr=3,cu=0,mis=0,r=3,dep=1,og=1,tim=1204698401510333
STAT #18 id=1 cnt=6 pid=0 pos=1 obj=15665 op='TABLE ACCESS FULL T'
And now, let’s execute it in 11.1.0.6. In this case notice that:
- The same number of parse, execute and fetch calls as in 10.2.0.4 were performed.
- The information about the execution plan was written in the trace file just after the first execution and not when the statement was closed. For this reason, according to it, only 1 row was fetched.
PARSING IN CURSOR #4 len=29 dep=1 uid=30 oct=3 lid=30 tim=1233611735664091 hv=2067044879 ad='6ae30880' sqlid='cxa35s1xm96hg'
SELECT n FROM t WHERE n <= :1
END OF STMT
PARSE #4:c=4000,e=118923,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233611735664086
EXEC #4:c=1999,e=28275,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233611735779067
FETCH #4:c=0,e=88,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,tim=1233611735779278
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=17363 op='TABLE ACCESS FULL T'
EXEC #4:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1233611735795372
FETCH #4:c=0,e=45,p=0,cr=3,cu=0,mis=0,r=2,dep=1,og=1,tim=1233611735795449
EXEC #4:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1233611735795509
FETCH #4:c=0,e=18,p=0,cr=3,cu=0,mis=0,r=3,dep=1,og=1,tim=1233611735795552
Why this difference?
It is because, as of 11g, the procedures in the package dbms_monitor that are used to enable SQL trace accept an additional parameter: PLAN_STAT. As written in the documentation, this parameter is used to specify the frequency at which the row source statistics (i.e. information about execution plans) are written in trace files. The accepted values are the following (the default value is NULL):
- NEVER: no information about the execution plan is written in trace files.
- FIRST_EXECUTION (equivalent to NULL): information about the execution plan is written just after the first execution.
- ALL_EXECUTIONS: information about the execution plan is written for every execution.
Therefore, when the parameter PLAN_STAT is set to ALL_EXECUTIONS, the content of the trace file is the following:
PARSING IN CURSOR #9 len=29 dep=1 uid=30 oct=3 lid=30 tim=1233613010415243 hv=2067044879 ad='6ae30880' sqlid='cxa35s1xm96hg'
SELECT n FROM t WHERE n <= :1
END OF STMT
PARSE #9:c=2000,e=28550,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233613010415239
EXEC #9:c=2000,e=21361,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233613010500308
FETCH #9:c=0,e=70,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,tim=1233613010500878
STAT #9 id=1 cnt=1 pid=0 pos=1 obj=17364 op='TABLE ACCESS FULL T'
EXEC #9:c=999,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1233613010506855
FETCH #9:c=0,e=24,p=0,cr=3,cu=0,mis=0,r=2,dep=1,og=1,tim=1233613010506906
STAT #9 id=1 cnt=2 pid=0 pos=1 obj=17364 op='TABLE ACCESS FULL T'
EXEC #9:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1233613010507425
FETCH #9:c=0,e=27,p=0,cr=3,cu=0,mis=0,r=3,dep=1,og=1,tim=1233613010507479
STAT #9 id=1 cnt=3 pid=0 pos=1 obj=17364 op='TABLE ACCESS FULL T'
Why is this feature important?
It is because up to 10g, especially for application keeping cursors open for a “long time”, it is not unusual to see trace files not containing information about execution plans for every cursor. Since that information is critical to diagnose performance problems, it might be a major issue. As of 11g, however, the trace files should always contain this critical information (except if the value NEVER is used, of course).