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).
Good feature and appreciate for the comprehensive explanation about the feature.
Would like to see more kind of similar contribution.
Thanks
Srini
Really good feature. I might even want to set it to all_executions. That can also help with one of the
causes of “mysterious discrepancies” between RowSourceOperations and ExplainPlans — that being the
Execution Plan may change during the course of a program run.
(Of course the other issue is that an Explain Plan is different from RowSourceOperations if bind variables
are used).