SQLMDX

Eventually it's all about data

Recursive calls and statistics

Posted by sqlmdx on May 11, 2014

There are many cases when executing some statement (either SQL or PL/SQL) may invoke execution of another SQL or PL/SQL statement.
However it’s not at all obvious how execution statistics for cursors are aggregated.

Let’s consider two cases

  1. SQL statement calls another SQL statement in a function
  2. PL/SQL block calls SQL statement

In both cases there will be two cursors: parent and child (in SQL trace at recursive depth 0 and 1 respectively).
This concept has no relation to child cursors and cursor sharing though (each sql_id has one ore more child cursors numbered from zero – v$sql.child_number).
Recursive SQL is the SQL associated with a database call and a recursive depth value greater then zero.
Recursive depth can be any non negative integer number and for any child cursor on n + 1 level there should be parent cursor on nth level.
Let’s analyze execution statistics for them.

1. To check stats for first case let’s issue three statements

  • Simple select from dual
  • Select of “nop” function from dual
  • Select of a function from dual which scans another table

Auxiliary actions

drop table t;
create table t as select lpad(' ',4000) value from dual connect by level <= 1000;
exec dbms_stats.gather_table_stats(user,'t');
create or replace function f return number as
  result number;
begin
  select /*+ qwerty */ count(*) into result from t;
  return result;
end f;
/
create or replace function f0 return number as
begin
  return 0;
end f0;
/

To minimize side effects I’m cleaning up shared pool and buffer cache before issuing the statements:

alter system flush buffer_cache;
alter system flush shared_pool;
select * from dual;
select /*+ qwerty1 */ 1 f from dual;
select /*+ qwerty0 */ f0 from dual;
select /*+ qwerty */ f from dual;

The output from v$sql is below:

SQL> select sql_text,
  2         sql_id,
  3         disk_reads,
  4         buffer_gets,
  5         cpu_time,
  6         elapsed_time,
  7         executions
  8    from v$sql
  9   where sql_text like '%qwerty%'
 10     and sql_text not like '%v$sql%'
 11   order by lower(sql_text);

SQL_TEXT                                 SQL_ID        DISK_READS BUFFER_GETS   CPU_TIME ELAPSED_TIME EXECUTIONS
---------------------------------------- ------------- ---------- ----------- ---------- ------------ ----------
SELECT /*+ qwerty */ COUNT(*) FROM T     fnzgacfvhu7rz       1009        1030          0       271592          1
select /*+ qwerty */ f from dual         fycxy6700td4z       1013        1116          0       299758          1
select /*+ qwerty0 */ f0 from dual       au9xq3wca1kxp        167        1235     109200       790238          1
select /*+ qwerty1 */ 1 f from dual      4d88y1knc2mas          0           0          0          972          1

It’s a bit surprising that number of buffer gets for “nop” function is greater than for “scanning” function and also number of disk reads is considerably greater then zero.
Let’s repeat the same experiment without second query (select /*+ qwerty0 */ f0 from dual).

SQL_TEXT                                 SQL_ID        DISK_READS BUFFER_GETS   CPU_TIME ELAPSED_TIME EXECUTIONS
---------------------------------------- ------------- ---------- ----------- ---------- ------------ ----------
SELECT /*+ qwerty */ COUNT(*) FROM T     fnzgacfvhu7rz       1009        1030          0       335558          1
select /*+ qwerty */ f from dual         fycxy6700td4z       1181        2273      78000      1185093          1
select /*+ qwerty1 */ 1 f from dual      4d88y1knc2mas          0           0          0          970          1

This output shows that overhead introduced by f0 in first output now added to SQL_ID fycxy6700td4z.
In order to figure out what Oracle was doing we can refer to SQL trace (for second scenario).
It shows that besides user statements (Parsing user id is not SYS) like

<skipped>
********************************************************************************

SQL ID: fycxy6700td4z
Plan Hash: 1388734953
select /*+ qwerty */ f 
from
 dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.02          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.02          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 91  

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        1.62          1.62
********************************************************************************
<skipped>
********************************************************************************

SQL ID: fnzgacfvhu7rz
Plan Hash: 2966233522
SELECT /*+ qwerty */ COUNT(*) 
FROM
 T


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      0.00       0.20       1001       1005          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00       0.21       1001       1005          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 91     (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=1005 pr=1001 pw=0 time=0 us)
   1000   TABLE ACCESS FULL T (cr=1005 pr=1001 pw=0 time=4245 us cost=279 size=0 card=1000)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         1        0.02          0.02
  db file scattered read                         23        0.02          0.16



********************************************************************************
<skipped>

there are a lot of statements executed under SYS schema which were used to derive dictionary and stats data etc.
For example

********************************************************************************

SQL ID: 5n1fs4m2n2y0r
Plan Hash: 299250003
select pos#,intcol#,col#,spare1,bo#,spare2,spare3 
from
 icol$ where obj#=:1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute     16      0.00       0.00          0          0          0           0
Fetch       59      0.00       0.00          0        118          0          43
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       78      0.00       0.00          0        118          0          43

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: CHOOSE
Parsing user id: SYS   (recursive depth: 2)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID ICOL$ (cr=4 pr=0 pw=0 time=0 us cost=2 size=54 card=2)
      1   INDEX RANGE SCAN I_ICOL1 (cr=3 pr=0 pw=0 time=0 us cost=1 size=0 card=2)(object id 42)

********************************************************************************

The crucial point here is that statistics for child statement is not added for parent unlike the approach for v$sql.
So you can see that elapsed time for fycxy6700td4z is near zero and disk reads are zero.

Interesting question is how to find out parent statement for given child recursive statement.
As described in Optimizing Oracle Performance by Cary Millsap

The rule for determining the recursive relationships among database calls is simple:
A database call with dep=n + 1 is the recursive child of the first subsequent dep=n database call listed in the SQL trace data stream.

For above example the extract from raw trace is following

<skipped>
=====================
PARSING IN CURSOR #4 len=32 dep=0 uid=91 oct=3 lid=91 tim=2759732282942 hv=3222058143 ad='abf4afc8' sqlid='fycxy6700td4z'
select /*+ qwerty */ f from dual
END OF STMT
PARSE #4:c=78000,e=640250,p=139,cr=610,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=2759732282940
EXEC #4:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=2759732283145
WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=116 tim=2759732283232
=====================
<skipped>
=====================
PARSING IN CURSOR #7 len=36 dep=1 uid=91 oct=3 lid=91 tim=2759732743714 hv=3071090431 ad='bea06e20' sqlid='fnzgacfvhu7rz'
SELECT /*+ qwerty */ COUNT(*) FROM T
END OF STMT
PARSE #7:c=15600,e=69522,p=8,cr=25,cu=0,mis=1,r=0,dep=1,og=1,plh=2966233522,tim=2759732743713
EXEC #7:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2966233522,tim=2759732743851
WAIT #7: nam='db file sequential read' ela= 23254 file#=4 block#=31450 blocks=1 obj#=140614 tim=2759732767199
WAIT #7: nam='db file scattered read' ela= 1041 file#=4 block#=31451 blocks=5 obj#=140614 tim=2759732768408
<skipped scattered reads>
WAIT #7: nam='db file scattered read' ela= 13593 file#=4 block#=7170 blocks=126 obj#=140614 tim=2759732950277
FETCH #7:c=0,e=207546,p=1001,cr=1005,cu=0,mis=0,r=1,dep=1,og=1,plh=2966233522,tim=2759732951463
STAT #7 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1005 pr=1001 pw=0 time=0 us)'
STAT #7 id=2 cnt=1000 pid=1 pos=1 obj=140614 op='TABLE ACCESS FULL T (cr=1005 pr=1001 pw=0 time=4245 us cost=279 size=0 card=1000)'
CLOSE #7:c=0,e=3,dep=1,type=3,tim=2759732951690
FETCH #4:c=109201,e=668494,p=1041,cr=1663,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=2759732951781
<skipped>

It clearly shows that parent cursor for cursor #7 is cursor #4 which is expected.

2. The same behavior takes place when the parent statement is anonymous block.

declare
  result number;
begin
  select /*+ qwerty */ count(*) into result from t;
end f;
/
SQL_TEXT                                 SQL_ID        DISK_READS BUFFER_GETS   CPU_TIME ELAPSED_TIME EXECUTIONS
---------------------------------------- ------------- ---------- ----------- ---------- ------------ ----------
declare   result number; begin   select  7rhrw221spyn7       1129        1577          0       721003          1
/*+ qwerty */ count(*) into result from
t; end f;

SELECT /*+ qwerty */ COUNT(*) FROM T     fnzgacfvhu7rz       1006        1016          0       248527          1

As you can see statistics for parent statement in v$sql are aggregated which includes statistics for recursive user statement (SQL_ID fnzgacfvhu7rz) and other recursive statements under SYS schema. As well as statistics are not aggregated in TKPROF output.

declare
  result number;
begin
  select /*+ qwerty */ count(*) into result from t;
end f;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.01       0.01          0          0          0           1

So there are a lot of cases when one statement recursively calls another user statements (function, trigger, SQL statement in PL/SQL block etc) or SYS statements (retrieving dictionary information, dynamic sampling etc) and it’s important to understand how to treat execution statistics.

Update
It’s worth to mention two additional popular tools for analyzing SQL performance: SQL Monitor (dbms_sqltune.report_sql_monitor) and dbms_xplan.display_cursor with enabled (either via hint gather_plan_statistics or using “alter session set statistics_level = all”) rowsource execution statistics.

  • dbms_xplan.display_cursor does not include any information about statistics for recursive calls
  • dbms_sqltune.report_sql_monitor has section “Global Stats” which displays total statistics including recursive calls
  • It looks as following for statement “select /*+ monitor */ f from dual”

    Global Stats
    =====================================================================================
    | Elapsed |   Cpu   |    IO    | PL/SQL  |  Other   | Fetch | Buffer | Read | Read  |
    | Time(s) | Time(s) | Waits(s) | Time(s) | Waits(s) | Calls |  Gets  | Reqs | Bytes |
    =====================================================================================
    |    2.65 |    0.03 |     0.92 |    0.00 |     1.69 |     1 |   1666 |   98 |   8MB |
    =====================================================================================
    
    SQL Plan Monitoring Details (Plan Hash Value=1388734953)
    ======================================================================================================================
    | Id |    Operation     | Name |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity | Activity Detail |
    |    |                  |      | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |   (# samples)   |
    ======================================================================================================================
    |  0 | SELECT STATEMENT |      |         |      |         1 |     +2 |     1 |        1 |          |                 |
    |  1 |   FAST DUAL      |      |       1 |    2 |         1 |     +2 |     1 |        1 |          |                 |
    ======================================================================================================================
    

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

 
%d bloggers like this: