SORTs, TIMEs and 11g

A while back I noticed that the TIME values in the STAT lines for an 11g Database weren't adding up right if there was a sort operation in the plan. I talked with several folks and everyone agreed that this was going on but no one seemed to know why. I've just been working with Oracle support and I think I know what is happening.

This was an important issue to me for several reason not the least of which is I'm working on a paper for the upcoming UKOUG meeting about SORT MERGE joins, so knowing where the time was going was critical. Also this really makes the math look a bit odd when a SORT operation appears in a plan you are trying to optimize.

So here is what things would look like in 10, I've put the STAT line times and done the math to show how much time each step took for it self:

Plan and stats in 10g for a sort merge join (I know this is hard to read when all the spacing is mashed, I don't know how to retain the spacing in HTML):

Select /*+ use_merge(e,d) */ * from emp e, dept d
where e.deptno = d.deptno
/

--------------------------------------------------------
| Id | Operation | Name |
--------------------------------------------------------
| 0 | SELECT STATEMENT | |
| 1 | MERGE JOIN | |
STAT Time=821 self=201 (821-183-437)
| 2 | TABLE ACCESS BY INDEX ROWID | DEPT |
STAT Time=183 self=102 (183-81)
| 3 | INDEX FULL SCAN | DEPT_DEPTNO_PK |
STAT Time=81 self=81
|* 4 | SORT JOIN | |
STAT Time=437 self=235 (437-202)
| 5 | TABLE ACCESS BY INDEX ROWID| EMP |
STAT Time=202 self=114 (202-88)
|* 6 | INDEX FULL SCAN | EMP_DEPT_IDX |
STAT Time=88 self=88
---------------------------------------------------------

Total of all selfs = 821us Top Line in STAT = 821us

OK that is all well and good. Now here is what that same plan looks like in 11g, notice in 11 I don't need a hint to get a SORT MERGE:

--------------------------------------------------------
| Id | Operation | Name |
--------------------------------------------------------
| 0 | SELECT STATEMENT | |
| 1 | MERGE JOIN | |
Stat Line=135us SELF=2us (135-35-24-74)
| 2 | TABLE ACCESS BY INDEX ROWID | DEPT |
Stat Line=35us SELF=13us
| 3 | INDEX FULL SCAN | DEPT_DEPTNO_PK |
Stat Line=22us SELF=22us
|* 4 | SORT JOIN | |
Stat Line=24us SELF=24us
| 5 | TABLE ACCESS BY INDEX ROWID| EMP |
Stat Line=74us SELF=49us (74-25)
|* 6 | INDEX FULL SCAN | EMP_DEPT_IDX |
Stat Line=25us SELF=25us
--------------------------------------------------------

Total of all selfs = 135us Top Line in STAT = 135us

Notice that the SORT JOIN (#4) step shows a TIME of 24us, now in the past that time should have included it's children, which is #5 and #6, that would be impossible since 74us is much more then 24us.

What appears to be happening is that the SORT is now done "while" the child steps are accruing. I think the best way to describe this new behavior is that sorts now happen simultaneously with the child steps. I don't believe that this is a parallel action, it is an action that happens simultaneously. There is a subtle but distinct difference.

Well if you want to here more about this, you could come to my talk at the UKOUG meeting in December, or drop me a line and I'd be glad to chat about this more.