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
- SQL statement calls another SQL statement in a function
- 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