Skip to Main Content
  • Questions
  • Query/Disk aggregated figures not matching execution plan in SQL trace for a single SQL statement.

Breadcrumb

Question and Answer

Chris Saxon

Thanks for the question, Javier.

Asked: June 29, 2016 - 4:34 pm UTC

Last updated: July 04, 2016 - 4:11 pm UTC

Version: Oracle Database 11g Enterprise Edition Release 11.2.0.3.0

Viewed 1000+ times

You Asked

Hi Tom,

My question is, not sure I'm hitting some sort of bug though I can't find anything on mos, why the query-current-disk aggregated figures do not match the execution plan cr value multiplied by the number of iterations or fetch calls:

SELECT SUM(D.HISTORY_HOURS) AS D_HOURS
FROM
DAY_HISTORY D WHERE D.PAYROLL_PERIOD < :B4 AND D.REFERENCE LIKE 'PAY1641%'
AND D.EMPNO = :B3 AND D.PAY_CODE = :B2 AND D.ROSTER_DATE = :B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 14057 1.04 2.72 0 0 0 0
Fetch 14057 325.10 18268.90 3183425 3924016 0 14057
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 28115 326.15 18271.62 3183425 3924016 0 14057

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=30 pr=28 pw=0 time=60053 us)
0 0 0 TABLE ACCESS BY INDEX ROWID DAY_HISTORY (cr=30 pr=28 pw=0 time=60044 us cost=7 size=29 card=1)
89 89 89 INDEX RANGE SCAN DAYHIST_RETRO (cr=4 pr=2 pw=0 time=7882 us cost=4 size=0 card=3)(object id 154916)


I would expect to have 30 * 14057 (one fetch + execution call for each value returned by the parent cursor) but instead the number of consistent reads is one order of magnitude larger.

what could be the reason of this kind of issue?

thanks in advance,
Javi

and Connor said...

14057 executions,
Each execution did an index range scan,
Each scan took 4 logical I'O's
Each scan gave you back 89 rows, thus 89 probes into the table

14057 * 4 * 89 = ~5million

You didnt include the predicates/access section of the plan, so I dont know if any filtering could be done in the index scan phase before we looked at the table, but if we dropped the '89' down to '30', we're at around 1.7million - in either case the consistent read numbers seem in the right ballpark to me.


Rating

  (1 rating)

Is this answer out of date? If it is, please let us know via a Comment

Comments

But then that wouldnt work for this next example

A reader, June 30, 2016 - 8:43 am UTC

Hi,

But then for a similar run I got completely different numbers (many fewer reads) with same execution plan and similar number of iterations:

SELECT SUM(D.HISTORY_HOURS) AS D_HOURS
FROM
DAY_HISTORY D WHERE D.PAYROLL_PERIOD < :B4 AND D.REFERENCE LIKE 'PAY1641%'
AND D.EMPNO = :B3 AND D.PAY_CODE = :B2 AND D.ROSTER_DATE = :B1


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 14057 1.27 1.63 0 0 0 0
Fetch 14057 14.47 747.59 145349 221218 0 14057
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 28115 15.74 749.22 145349 221218 0 14057

Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: ALL_ROWS
Parsing user id: 84 (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=30 pr=28 pw=0 time=95489 us)
0 0 0 TABLE ACCESS BY INDEX ROWID DAY_HISTORY (cr=30 pr=28 pw=0 time=95482 us cost=7 size=29 card=1)
89 89 89 INDEX RANGE SCAN DAYHIST_RETRO (cr=4 pr=2 pw=0 time=6274 us cost=4 size=0 card=3)(object id 154916)


predicate information for one looks like:

Predicate Information (identified by operation id):
---------------------------------------------------

2 - filter("D"."PAY_CODE"=4809 AND "D"."PAYROLL_PERIOD"<201628)
3 - access("D"."EMPNO"='456456D' AND "D"."REFERENCE" LIKE 'PAY1641%' AND
"D"."ROSTER_DATE"=TO_DATE(' 2016-05-13 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))
filter("D"."ROSTER_DATE"=TO_DATE(' 2016-05-13 00:00:00', 'syyyy-mm-dd hh24:mi:ss') AND
"D"."REFERENCE" LIKE 'PAY1641%')

Usually I would expect to get the accumulated cr number at the top of the plan multiplied by iterations so still don't understand how these figures are obtained.

thanks
Chris Saxon
July 04, 2016 - 4:11 pm UTC

The CR number in the "Row Source Operation" figures is the cumulative total of the CRs below it - for one execution of the query.

The disk/query/current figures are the totals for all executions in the tracefile.

For example, I create a table which has 1 row/value. Except 1,000. There are 20 rows with this value. The rows are "wide". So these 20 rows are spread across a few blocks.

create table t (
  x number, 
  stuff varchar2(1000)
);

insert into t select rownum, lpad('x', 1000, 'x') from dual connect by level <= 980;
insert into t select 1000, lpad('x', 1000, 'x') from dual connect by level <= 20;
create index i on t(x);

alter session set tracefile_identifier = chris;
alter session set sql_trace = true;
var v number;
exec :v := 1;
select * from t where x = :v;
exec :v := 1000;
select * from t where x = :v;
alter session set sql_trace = false;


tkprof only reports one CR for the table access in the row source though (4 - 3 from the index). This is because it's using the stats from the first execution. The query column reports the total buffer gets across both executions (11):

select *
from
 t where x = :v


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        4      0.00       0.00          0         11          0          21
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      0.00       0.00          0         11          0          21

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 121
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID T (cr=4 pr=0 pw=0 time=120 us cost=2 size=515 card=1)
         1          1          1   INDEX RANGE SCAN I (cr=3 pr=0 pw=0 time=99 us cost=1 size=0 card=1)(object id 131860)


So based on what you can see we can say:

- one execution used 30 consistent reads
- On average each execution took 221218 / 14057 ~ 16 reads.

The variations will be because different executions read more or less data based on the bind values and any DML run between executions.

Chris

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.