Recursive Calls

Here is one interesting subject – recursive calls and performance monitoring instrumentation. This is just a few observations of the session tracing facility, Statspack, AWR and Tkprof point of view on recursive calls. We want to observe and clarify how the Tkprof, Statspack and AWR calculate top and recursive call statistics.

The definition of recursive call as per Metalink Note:41634.1 and 10g Tkprof Manual

“Recursive Calls
—————

Sometimes to execute a SQL statement issued by a user, Oracle must issue
additional statements
. Such statements are called ‘recursive calls’ or
‘recursive SQL statements’. For example, if you insert a row into a table
that does not have enough space to hold that row, Oracle makes recursive
calls to allocate the space dynamically. Recursive calls are also generated
when data dictionary information is not available in the data dictionary
cache and must be retrieved from disk.

If recursive calls occur while the SQL trace facility is enabled, TKPROF
produces statistics for the recursive SQL statements and clearly marks them
as recursive SQL statements in the output file.  Note that the
statistics for
a recursive SQL statement are included in the listing for that statement
,
not in the listing for the SQL statement that caused the recursive call.  So
when you are calculating the total resources required to process a SQL
statement, you should consider the statistics for that statement as well as
those for recursive calls caused by that statement.”

Recursive calls are triggered by top level calls that governs processing of statements directly issued by users (or more precisely, issued by a program that communicates directly with Oracle on behalf of its end-users or scripts). Tkprof is supposed to report base statistics (excluding the statistics of its recursive calls) of a call at any level.

For the purpose of the following discussion let me add the following statistics definitions taken from Statistics Descriptions that can be viewed either in Statspack or AWR report or directly using v$sysstat view:

CPU used by this session – Amount of CPU time (in 10s of milliseconds) used by a session from the time a user call starts until it ends. If a user call completes within 10 milliseconds, the start and end user-call time are the same for purposes of this statistics, and 0 milliseconds are added.
recursive cpu usage – Total CPU time used by non-user calls (recursive calls). Subtract this value from “CPU used by this session” to determine how much CPU time was used by the user calls.”

Documentation says that “CPU used by this session” statistics includes CPU used by recursive calls.

Let’s run a test and take a look at this from practical perspecive and see how well 10.2.0.3 DB conforms to its documentation. I’ve chosen following code for this testing:

create or replace function recursive_function(leveln number, maxlevel number) return number
as
    l_level number := leveln;
    c number := 0;
begin

    loop
        exit when c > 4000000000;
        c := c + 1;
    end loop;

    if l_level+1 <= maxlevel then
        execute immediate 'select /*+ query at level '||(l_level+1)||' */ recursive_function('||(l_level+1)||','||maxlevel||') from dual' into c;
    end if;
   
    return c;
end;
/

begin
    perfstat.statspack.snap(i_ucomment=>'start at '||to_char(sysdate,'yy/mm/dd hh24:mi:ss'));
    DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT ('ALL');
end;
/

alter session set events '10046 trace name context forever, level 8';              

select /*+ top */ recursive_function(0,3) from dual;

begin
    perfstat.statspack.snap(i_ucomment=>'end at '||to_char(sysdate,'yy/mm/dd hh24:mi:ss'));
    DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT ('ALL');
end;
/

alter session set events '10046 trace name context off';

It triggers chain of recursive calls with max level 3. This code generates quasi-equal amount of pure CPU load and should allow identifying resource consumption on any level quite easily.

Raw Trace:

PARSING IN CURSOR #53 len=51 dep=0 uid=57 oct=3 lid=57 tim=1166023881658166 hv=1409094977 ad='6cf1aba8'
select /*+ top */ recursive_function(0,3) from dual
END OF STMT
PARSE #53:c=0,e=163,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1166023881658162
EXEC #53:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1166023881658276
WAIT #53: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=56115 tim=1166023881658319
WAIT #53: nam='SQL*Net message from client' ela= 44597 driver id=1413697536 #bytes=1 p3=0 obj#=56115 tim=1166023881702983
*** 2007-11-02 09:05:46.334
=====================
PARSING IN CURSOR #13 len=64 dep=1 uid=57 oct=3 lid=57 tim=1166024166342227 hv=1557986045 ad='72a95828'
select /*+ query at level 1 */ recursive_function(1,3) from dual
END OF STMT
PARSE #13:c=2999,e=2789,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1166024166342221
EXEC #13:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1166024166342394
*** 2007-11-02 09:10:59.564
=====================
PARSING IN CURSOR #55 len=64 dep=2 uid=57 oct=3 lid=57 tim=1166024472231315 hv=4273745374 ad='6e06c2e8'
select /*+ query at level 2 */ recursive_function(2,3) from dual
END OF STMT
PARSE #55:c=3000,e=2617,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=1,tim=1166024472231309
EXEC #55:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=1166024472231491
*** 2007-11-02 09:15:50.950
=====================
PARSING IN CURSOR #14 len=64 dep=3 uid=57 oct=3 lid=57 tim=1166024756787955 hv=1817767248 ad='6e2b2ec8'
select /*+ query at level 3 */ recursive_function(3,3) from dual
END OF STMT
PARSE #14:c=2000,e=2633,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=1,tim=1166024756787948
EXEC #14:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1166024756788155
*** 2007-11-02 09:20:42.250
FETCH #14:c=291241724,e=284472442,p=0,cr=0,cu=0,mis=0,r=1,dep=3,og=1,tim=1166025041260627
STAT#14 id=1 cnt=1 pid=0 pos=1 obj=0 op='FASTDUAL  (cr=0 pr=0 pw=0 time=5 us)'
FETCH #55:c=582567435,e=569029386,p=0,cr=0,cu=0,mis=0,r=1,dep=2,og=1,tim=1166025041260907
STAT#55 id=1 cnt=1 pid=0 pos=1 obj=0 op='FASTDUAL  (cr=0 pr=0 pw=0 time=3 us)'
FETCH #13:c=895731828,e=874918635,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=1166025041261058
WAIT #53: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=56115 tim=1166025041261123
FETCH #53:c=1187120530,e=1159558108,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1166025041261160
WAIT #53: nam='SQL*Net message from client' ela= 54812 driver id=1413697536 #bytes=1 p3=0 obj#=56115 tim=1166025041316063
STAT#53 id=1 cnt=1 pid=0 pos=1 obj=0 op='FASTDUAL  (cr=0 pr=0 pw=0 time=5 us)'

In the 10g raw trace time is given in microseconds. So, you see how the CPU cosumption and elapsed time are reported in the trace. At each level reported as its own CPU load plus the CPU load from the call sub-tree (all descendants):

CPUL3 (291241724)  = CPUL3.base + CPUL4(0: there are no further descendants)
CPUL2 (582567435)  = CPUL2.base + CPUL3(291241724)
CPUL1 (895731828)  = CPUL1.base + CPUL2(582567435)
CPUL0 (1187120530) = CPUL0.base + CPUL1(895731828)

or,

CPUL3.base = CPUL3 = 291241724 = 291 s
CPUL2.base = CPUL2 (582567435) - CPUL3(291241724) = 291325711 = 291 s
CPUL1.base = CPUL1 (895731828) - CPUL2(582567435) = 313164393 = 313 s
CPUL0.base = CPUL0 (1187120530) - CPUL1(895731828) = 291388702 = 291 s

Tkprof:

select /*+ top */ recursive_function(0,3)
from
 dual

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1   1187.12    1159.55          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3   1187.12    1159.55          0          0          0           1

Parsing user id: 57

================================================================================
select /*+ query at level 1 */ recursive_function(1,3)
from
 dual

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1    313.16     305.88          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3    313.16     305.88          0          0          0           1

Parsing user id: 57     (recursive depth: 1)

================================================================================
select /*+ query at level 2 */ recursive_function(2,3)
from
 dual

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1    291.32     284.55          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3    291.32     284.55          0          0          0           1

Parsing user id: 57     (recursive depth: 2)

================================================================================
select /*+ query at level 3 */ recursive_function(3,3)
from
 dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1    291.24     284.47          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3    291.24     284.47          0          0          0           1

Parsing user id: 57     (recursive depth: 3)

I always thought Tkprof doesn’t report net statistics for calls, but now I see how wrong I was. From this test it is obvious that the Tkprof reported base times for recursive calls at all levels, and only for the top level calls the CPU and elapsed time are defined as gross load including all levels: CPUL0 = CPUL0.base + CPUL1.base + CPUL2.base + CPUL3.base  = 291 + 313 + 291 + 291 = 1187 s. My memory might be playing tricks with me, but I recall I saw a discussion on Jonathan Lewis’s blog about this Tkprof deficiency. Maybe someone will update me where it was.

AWR:

SQL ordered by Elapsed Time

  Elapsed      CPU                  Elap per  % Total
  Time (s)   Time (s)  Executions   Exec (s)  DB Time    SQL Id
---------- ---------- ------------ ---------- ------- -------------
     1,160      1,160            1     1159.6    99.8 1rcptud9zu5a1
Module: SQL Developer
select /*+ top */ recursive_function(0,3) from dual

       875        875            1      874.9    75.3 9pgc4u1fdtyrx
Module: SQL Developer
select /*+ query at level 1 */ recursive_function(1,3) from dual

       569        569            1      569.0    49.0 0v0qmk7zbsbfy
Module: SQL Developer
select /*+ query at level 2 */ recursive_function(2,3) from dual

       284        284            1      284.5    24.5 2zfr66tq5jvah
Module: SQL Developer
select /*+ query at level 3 */ recursive_function(3,3) from dual


Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                          1,162         100.0
control file parallel write             396           1      1    0.0 System I/O
...


Time Model Statistics

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                              1,162.0        100.0
DB CPU                                                1,161.9        100.0
PL/SQL execution elapsed time                         1,159.6         99.8
...
DB time                                               1,162.1          N/A
background elapsed time                                   2.9          N/A
background cpu time                                       1.5          N/A


Instance Activity Stats

Statistic                                     Total     per Second     per Trans
-------------------------------- ------------------ -------------- -------------
CPU used by this session                    118,971          100.0      13,219.0
CPU used when call started                  118,946           99.9      13,216.2
recursive cpu usage                          89,804           75.5       9,978.2

I rearranged it a little bit for better view.  

First of all, the top section shows that each of the times reported at each level contain times of its descendants (i.e. as in raw trace). Well, no wonder, there is probably not enough information to track call dependency and subtract statistics of children from a parent. Anyhow, it reports gross load for each recursive level and top level calls. Anyone analyzing AWR reports should note statement “Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.”that precedes this section. Apparently it is actually true not only for PL/SQL code, but for any type of code. This can be seen in the time model statistics where the sql execute elapsed time roughly equal PL/SQL execution elapsed time.

Also, comparing this section to the raw trace or Tkprof output shows that in the AWR report CPU time matches exactly the elapsed time, although it was not the same in the raw trace. This would seem just a reporting “feature”, if not for the information from the further sections. CPU time in Top 5 Timed Events and DB CPU in Time Model Statistics is roughly about 1,160 s. Ignoring small difference, same time is spent by the top level statement. Only Instance Activity Stats section shows 1,189.7 s that almost matches the raw trace CPU time consumed by all subject statements with a little offset of 2.58 s. Further, the recursive cpu usage of 898 s matches the CPU time of the recursive calls starting at level 1 with difference of 2.3 s. Both deltas for the most part are time spent in Statspack subroutines that were captured by AWR.

Statspack:

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                     1,190          99.9
control file parallel write                        397           1      1     .0
...

In Statspack the Time Model Statistics and Instance Activity Stats precisely equal to the corresponding sections in the AWR report. The SQL statistics wasn’t captured for our statements because they didn’t generate logical or physical reads nor they generate other activity that is considered a treat by the Statspack. However in the Top 5 Timed Events you can see that the CPU time is the figure of CPU used by this session statistics in the Instance Activity Stats, so it comes from v$sysstat view.

This behavior is different from AWR algorithm, which rather seem to be taking CPU time in Top 5 Timed Events from v$sys_time_model or directly from their common source. In case v$sys_time_model and v$sysstat have different source of information, AWR is not bound to the figures of the later when reporting Top 5 Timed Events. This perhaps holds an explanation for the AWR oddity seen by Jonathan Lewis. It would be interesting to find the relevant clues in the reports or in this particular system.

About these ads

2 Responses to “Recursive Calls”

  1. BipNouppy Says:

    emm. strange ))

  2. kayak deals Says:

    Oh my goodness! Incredible article dude! Thanks, However I am having issues with your RSS.
    I don’t understand why I am unable to subscribe to it.
    Is there anybody getting identical RSS issues?
    Anyone who knows the answer will you kindly respond? Thanx!!


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: