A bug perhaps

OK in talking with Karen Morton and Jonathan Lewis it looked like a bug with the trace mechanism might be the root of the problem with the stat lines for a sort and not some new fancy way Oracle is doing the sorts. And I think that is true. Here is a look at getting the stats directly from v$sql_plan_statistics_all for my test SQL:

Select * from emp, dept where emp.deptno = dept.deptno
/










Now all the times look very nice. So I'm going with the BUG theory for now. (EDIT1 - Sorry I thought I had a way to keep the spacing but NO!) (EDIT 2 - Well let's try this little screen shot, a little small, but the numbers are easier to read.)

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.

Nice surprise...

Imagine that, a bit over a week ago I walk out of the office building and am surprised by this view:


Turns out I stumbled into the 2008 Porsche Parade! That was a nice surprise. The weather wasn't too bad either, so it made for a nice afternoon stroll. Along with a few other people...


If you happen to like old school Porsche's, there were a few of those too:


The judges took their job seriously, they really checked all the nooks and crannies of the cars:



I was told there were around one thousand Porsches in town...

A recent email from a former student

I heard from Ken Deutschmann of Anheuser Busch and he made my day knowing he'd used knowledge and techniques from the Optimizing Oracle SQL, Intensive class. Here's what he had to say.

"I had always considered myself a decent query tuner/writer. But, I will have to say that I did pick up some nice little tidbits that I have been making use of - like using GROUP BY's in subqueries to force no rewrites, etc. One case I did today was to drop a query from 3.5MM I/O's down to 20K with just such a change. Knowing more about the 10046 trace output is very helpful. I have been helping my main application group in tuning their stuff, most often droping run times in half or better. "

Right on Ken, you go brother!!!

Collaborate Tradition

Back in 2005, I attended the IOUG-A show in Toronto. James Thomson, a good friend from Canada, and I wanted to attend the hockey playoff game between the Toronto Maple Leafs and the Carolina Hurricanes. The tickets were extremely expensive so we set off to watch the game over dinner and a beer.

While walking to a sports bar between the 1st and 2nd period, we passed a ticket scalper still trying to unload the last two tickets he had. Long story short, we were in our seats before the puck dropped for about 10% of the pre-game price.
This is turning into a bit of a tradition now.

During my recent visit to Collaborate in Denver, my friends at PIOCON invited some of the Hotsos team to join them at the Pepsi Center to watch Colorado play Minnesota. It was a great game with the home team winning somewhat easily.

Many thanks to Matt Vranicar and Eric Camplin for the invite and a great time - we owe you one!

Recent Brazil Visit

I had the opportunity to visit Brazil last week to meet with our reseller firm Teor. I was also speaking at a Dell Performnace Summit in Porto Alegre and the ENPO-BR event in Sao Paulo. Both events were well organized and enjoyed strong attendance.

It was an amazing visit although it seems we were eating Brazilian BBQ non-stop for my entire stay.
I was also able to attend a local Palmeiras soccer game. There is considerable passion surround soccer in Brazil with amazing loyalty to specific clubs. I was almost denied entry into the hotel gym based on wearing the wrong soccer club jersey :-)

If you ever get the opportunity, I would definitely recommend visiting this great country.

SYM 2008

Another excellent symposium has come to an end. The speakers were great as always and Tom Kyte had a great training day to top everything off. Tuesday night was the party where the theme was "Bike Night"! What a hoot that was. Here I am in my get up. Some folks claim that I was a wild man on the dance floor, we'll have to see if there is any photographic evidence to back up these outlandish claims.

Make sure you make plans for next year. I don't think the dates are set just yet but plan on about this time next year.


(Behind me is Mike E. and Elise B.)