Heisenberg

Okay, so the title is pretentious; but I thought it was a snappy summary of this item [until someone pointed out that Heisenberg’s Uncertainty Principle is not about measurement error].

I’ve blogged before about the improved features in 10g of the dbms_xplan package, in particular the display_cursor() procedure, with its option for displaying rowsource execution statistics.

There is a bit of a problem with this feature, though, which I’ll demonstrate (at least on my laptop) with a query that I first introduced some time ago when discussing filter subqueries and scalar subquery caching. The query references a table called emp, which holds details of 20,000 employees spread over 6 departments. Here’s my test run, with the resulting execution plan:

set serveroutput off

select
	/*+ gather_plan_statistics */
	count(*)
from	(
	select	/*+ no_merge */
		outer.*
	from emp outer
	where outer.sal >
		(
			select /*+ no_unnest */ avg(inner.sal)
		 	from emp inner
			where inner.dept_no = outer.dept_no
		)
	)
;

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

====================================================================

  COUNT(*)
----------
      9998

1 row selected.

Elapsed: 00:00:00.14

PLAN_TABLE_OUTPUT
---------------------------
SQL_ID gncq9drn4sdgw, child number 0
-------------------------------------
select  /*+ gather_plan_statistics */  count(*) from (  select /*+ no_merge */
outer.* from emp outer where outer.sal > ( select /*+ no_unnest */
avg(inner.sal) from emp inner where inner.dept_no = outer.dept_no ) )

Plan hash value: 322796046

----------------------------------------------------------------------------------------
| Id  | Operation             | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE       |      |      1 |      1 |      1 |00:00:00.12 |    1540 |
|   2 |   VIEW                |      |      1 |    167 |   9998 |00:00:00.23 |    1540 |
|*  3 |    FILTER             |      |      1 |        |   9998 |00:00:00.16 |    1540 |
|   4 |     TABLE ACCESS FULL |  EMP |      1 |  20000 |  20000 |00:00:00.10 |     220 |
|   5 |     SORT AGGREGATE    |      |      6 |      1 |      6 |00:00:00.06 |    1320 |
|*  6 |      TABLE ACCESS FULL|  EMP |      6 |   3333 |  20000 |00:00:00.14 |    1320 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter("OUTER"."SAL">  )
   6 - filter("INNER"."DEPT_NO"=:B1)

25 rows selected.

You’ll note in passing that the predicate information extracted from the v$sql_plan dynamic performance view manages to lose the subquery from operation 3 – this is an irritating defect of in-memory execution plans.

But there’s a much more significant problem than that if you’re trying to find out where the time went.  Notice how the query elapsed time was 0.14 seconds, which is slightly larger than the actual time (A-time) reported at operation one of the plan. Then look down the plan: the time recorded for an operation should be the sum of the time spent in the operation itself plus the time spent in its child operations (i.e. immediate descendents only).

So how can operation 2 report a larger time than operation 1. How can operation 6 report a larger time than operation 5 ? Which operations are right, and which are wrong?

Someone sent me an email recently pointing out that this problem disappears if you set parameter statistics_level to “all”. Sure enough, when I got rid of the hint and used an alter  session command to set the statistics_level, the execution plan came out with a totally consistent set of timings. Here are the results after the change:

  COUNT(*)
----------
      9998

1 row selected.

Elapsed: 00:00:00.46

PLAN_TABLE_OUTPUT
---------------------------
SQL_ID 393znz62ak5vr, child number 0
-------------------------------------
select    count(*) from (  select /*+ no_merge */ outer.* from emp outer 
where outer.sal > ( select /*+ no_unnest */ avg(inner.sal) from emp inner 
where inner.dept_no = outer.dept_no ) )

Plan hash value: 322796046

----------------------------------------------------------------------------------------
| Id  | Operation             | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
----------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE       |      |      1 |      1 |      1 |00:00:00.46 |    1540 |
|   2 |   VIEW                |      |      1 |    167 |   9998 |00:00:00.44 |    1540 |
|*  3 |    FILTER             |      |      1 |        |   9998 |00:00:00.38 |    1540 |
|   4 |     TABLE ACCESS FULL |  EMP |      1 |  20000 |  20000 |00:00:00.08 |     220 |
|   5 |     SORT AGGREGATE    |      |      6 |      1 |      6 |00:00:00.19 |    1320 |
|*  6 |      TABLE ACCESS FULL|  EMP |      6 |   3333 |  20000 |00:00:00.14 |    1320 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter("OUTER"."SAL">  )
   6 - filter("INNER"."DEPT_NO"=:B1)

25 rows selected.

Note how the elapsed time is consistent with the A-time in the top line of the plan, and how the A-times down the whole plan are self-consistent.

But spot the problem … the elapsed time has just gone up from 0.14 seconds to 0.46 seconds.  There’s an overhead of about  200%. So how do you work out where your time is really going when the overhead of measuring is much larger than the thing you are trying to measure.

I think the problem is one of granularity. The hidden parameter  “_rowsource_statistics_sampfreq” – which defaults to the value 128 – defines a sampling frequency for the collection of rowsource execution statistics. When you set statistics_level to “all” this parameter is (I suspect) invisibly set to 1, which makes the statistics more accurate but much more expensive to collect.

You can circumvent this issue by setting “_rowsource_statistics_sampfreq” back to 128 after you’ve set the statistics_level to “all”. Of course, this will just take your execution plan timings back to their previous inconsistent state – so you’re wrong whatever choice you make.

So what can you do ? I think you have to run the query three times and use a little bit of judicious guesswork. Use the first run to get a base-line, do the second with the gather_plan_statistics hint, and do the third with statistics_level set to “all”.

Combining the three sets of results lets you know the true impact of the overheads – which in some cases may be insignificant, hence ignorable – then combining the second and third sets, you may see a correlation which suggests fairly strongly where most of the overhead is appearing and where most of the useful work is actually being done.

Beyond that, of course, the starts and buffers (and disk reads and memory operations, if they occur) may give you a very good indicator anyway. To date, when it’s been important, I’ve found that I’ve been able to get enough information from the hint-based approach, and not needed to worry about completely self-consistent times.

Footnote 1: The comparative tests above have only been carried out on a system running 10.2.0.3 on Windows XP Pro.  Results may vary with version and operating system. In particular, the operating system may make a huge difference to the overheads. If you try this out on a different platform, and see different results, let me know. All we need to see are version, O/S details, and the three run times (not the plan outputs).

Footnote 2: You may recall that from 9.2.0.2 through to 9.2.0.5, enabling sql_trace gave you some row source execution statistics in the STAT# lines of trace files. This feature disappeared in 9.2.0.6 because of the overheads, re-appearing in 10g when the parameter to set a sampling frequency was introduced.