Monday, September 22, 2008

STAT lines in 11g

My friend and colleague, Ric Van Dyke, has been preparing a presentation for the UKOUG conference and in his work discovered an anomaly in the roll ups for the time values in the STAT lines emitted in 10046 trace data from an 11g database. I had seen this behavior as well but didn't follow up on it for myself since I wasn't using Oracle 11 for anything other than a bit of testing here and there.

A couple of weeks ago, I received an email from Rudi K. as a follow up to my post on Plan Execution Statistics. In some of Rudi's own testing, he came across this anomaly in the rowsource execution statistics as well and asked me about it. So, given Rudi's question and a recent discussion with Ric on the subject, I thought I'd blog about it. Rudi - I apologize it's taken me so long to properly respond to you, but here you go! :)

First, let's look at an example of what the problem looks like. Take a look at the rowsource execution statistics (from the trace file STAT lines) for the following very simple query in Oracle 10g:

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

STAT #3 id=1 cnt=13 pid=0 pos=1 obj=0 op='MERGE JOIN (cr=11 pr=8 pw=0 time=21096 us)'
STAT #3 id=2 cnt=4 pid=1 pos=1 obj=54389 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=4 pr=2 pw=0 time=17342 us)'
STAT #3 id=3 cnt=4 pid=2 pos=1 obj=54390 op='INDEX FULL SCAN DEPT_DEPTNO_PK (cr=2 pr=1 pw=0 time=16060 us)'
STAT #3 id=4 cnt=13 pid=1 pos=2 obj=0 op='SORT JOIN (cr=7 pr=6 pw=0 time=3539 us)'
STAT #3 id=5 cnt=13 pid=4 pos=1 obj=54391 op='TABLE ACCESS FULL EMP (cr=7 pr=6 pw=0 time=3284 us)'

In order to understand the rowsource execution statistics (the information in the parentheses at the end of each line), you need to follow one simple "rule": the values listed in a child operation roll up into their parents. The bottom-line is that the top line should be the roll up of the child operations listed below it. To understand the relationships, take a look at this tree diagram of this query's execution plan.

| |
2 4
| |
3 5

So, you could break down the rowsource time stats as follows (I'm only showing the time stats as these are the roll ups that appear to have problems in 11g but all the rowsource statistics roll up the same way):

| Id | Pid | Operation | Name | Time | Self | Kids
| 0 | | SELECT STATEMENT | | 21096 | |
| 1 | 0 | MERGE JOIN | | 21096 | 215 | 17342+3539
| 2 | 1 | TABLE ACCESS BY INDEX ROWID| DEPT | 17342 | 1282 | 16060
| 3 | 2 | INDEX FULL SCAN | DEPT_DEPTNO_PK | 16060 | 16060 | 0
| 4 | 1 | SORT JOIN | | 3539 | 255 | 3284
| 5 | 4 | TABLE ACCESS FULL | EMP | 3284 | 3284 | 0

So far, so good. Now, let's look at the same info from 11g.

STAT #3 id=1 cnt=13 pid=0 pos=1 obj=0 op='MERGE JOIN (cr=6 pr=3 pw=3 time=166 us cost=5 size=767 card=13)'
STAT #3 id=2 cnt=4 pid=1 pos=1 obj=71193 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=4 pr=2 pw=2 time=53 us cost=2 size=80 card=4)'
STAT #3 id=3 cnt=4 pid=2 pos=1 obj=71194 op='INDEX FULL SCAN DEPT_DEPTNO_PK (cr=2 pr=1 pw=1 time=36 us cost=1 size=0 card=4)'
STAT #3 id=4 cnt=13 pid=1 pos=2 obj=0 op='SORT JOIN (cr=2 pr=1 pw=1 time=25 us cost=3 size=507 card=13)'
STAT #3 id=5 cnt=13 pid=4 pos=1 obj=71195 op='TABLE ACCESS BY INDEX ROWID EMP (cr=2 pr=1 pw=1 time=84 us cost=2 size=507 card=13)'
STAT #3 id=6 cnt=13 pid=5 pos=1 obj=71200 op='INDEX FULL SCAN EMP_DEPT_IDX (cr=1 pr=1 pw=1 time=29 us cost=1 size=0 card=13)'

The plan is a bit different in that it used an INDEX FULL SCAN for the EMP table access but otherwise, it's basically the same.

| |
2 4
| |
3 5

Here's the break down of the rowsource time stats:

| Id | Pid | Operation | Name | Time | Self | Kids
| 0 | | SELECT STATEMENT | | 166 | |
| 1 | 0 | MERGE JOIN | | 166 | ?? | 53+??
| 2 | 1 | TABLE ACCESS BY INDEX ROWID | DEPT | 53 | 17 | 36
| 3 | 2 | INDEX FULL SCAN | DEPT_DEPTNO_PK | 36 | 36 | 0
| 4 | 1 | SORT JOIN | | 25 | ?? | ??
| 5 | 4 | TABLE ACCESS BY INDEX ROWID| EMP | 84 | 55 | 29
| 6 | 5 | INDEX FULL SCAN | EMP_DEPT_IDX | 29 | 29 | 0

Hmmmm... Something's wrong here. Notice on step 4, the SORT JOIN operation's total time is only 25 microseconds. How can that be possible if it's child operation takes 84 microseconds? The MERGE JOIN step shows a time of 166 microseconds. How can I be sure of that total since step 4 appears wrong (i.e. it doesn't appear to include it's child operation totals)?

Well, if we go with Ric's theory, the problem is with the SORT step (id = 4). It appears that Oracle is no longer rolling up totals when a SORT type of operation occurs. Instead, it maintains that operation's statistics independent of its children. If that's the case, then to get the correct timing roll up, we'd need to add the time from steps 2, 4 and 5. That would be 162 microseconds. That would mean that the MERGE step would take 4 microseconds.

I'm not sure that's really how it's working, but the math seems to work out fairly close. Ric says:
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.

Regardless of if there's a resolution or not (perhaps we need to change the way the roll ups are done for SORT type operations which include not only SORT-MERGE joins, but queries that have ORDER BY and HASH joins as well), we do need to take note of the change. I've depended on these rowsource stats quite frequently when optimizing SQL and would love to really understand why this behavior is occurring and how to account for it in trace data.

If anyone has anything more concrete on this, I'd love to hear from you and I'm sure Ric would too!

Miracle Open World 2008

I'll be presenting at this year's Miracle Open World in Denmark and was asked to prepare a video about my presentation 'Are you an astronaut or a monkey? The Oracle Advisors from a different perspective'. I sure had fun making it. I have a feeling MOOW will be even more fun!

Sunday, September 21, 2008

Where in the world is Karen?

Sorry to be absent for so long. I've been teaching all day for the past two weeks and have one more week to go before I catch a bit of a break. It's been great, but it doesn't leave me with much energy or brain function to post in the evenings. :)

So, in lieu of something more profound, follow the visuals to know where I've been hanging out.



Near Toronto which is near this gorgeous landmark

In the city of Waterloo

I'm having a terrific visit, eh. :)

Friday, September 5, 2008

Teacher's Day

Today is Teachers' day in India. Every year on this day I receive an email from a student of mine who lives in India sending his thanks and also to ask for my "teacher's blessing" for him and his endeavors. This has been going on for about 4 years now and I look forward to it.

In India September 5th is celebrated as Teachers' day as a mark of tribute to the contribution made by teachers to the society. This date is the birthday of a great teacher, Dr. Sarvapalli Radhakrishnan, who was a staunch believer of education, and was the well-known diplomat, scholar, president of India (elected in 1962) and above all a teacher. You can read more about Teachers' day here.

I love to teach. It's truly a passion. I think it is true that teachers are also the most frequent and enthusiastic students. I know I am. I love to learn. And, even when I am teaching, I'm learning. My students often impart as much helpful information to me as I do to them. How great is that?!?!

In any case, I wanted to take a moment to thank my teachers...all of you. I know my life has been shaped by all the wonderful teachers I have had.

I got to speak to one of my most favorite teachers just last week after more than 25 years. It happened out of the blue when my sister, who is a physical therapist and lives and works in Tennessee, called me during the day and said "I've got someone here for you to say hi to." She then handed the phone to someone who asked if I remembered her. Obviously, I was clueless and so she gave me a hint: "I had you in class for two years in a row." Ah-ha! It was Mrs. Crossno! She was my Latin teacher during my freshman and sophomore years in high school. Wow. As it turns out she was visiting my sister's office for some physical therapy and when she asked about me, Amy just called me up and handed her the phone.

It was very, very sweet to speak to her again after all these years. She retired just a couple of years ago but had remembered me all these years and even kept a little cartoon I drew way back then posted on the bulletin board in her classroom. It was a copy of a Peanuts cartoon showing Charlie Brown with his little sister Sally. Sally was resisting the idea of going to kindergarten and the caption read 'Well, all right, I'll go - but I'm not going to learn Latin.' Mrs. Crossno had laminated it and kept it in her classroom all those years.

She made quite an impact on me that's for sure. Two years of Latin, a "dead" language, equipped me with knowledge I used through college and still find skills I learned then coming in handy now. She taught us etymology (the study of word origins) and from that, I have been able to break many words down into their Latin roots so that I could get at least some understanding of their meaning when the word was new to me. And, it wasn't just what she taught me, it was how she did it. She made it fun. She was encouraging and supportive. She knew her stuff but never made you feel stupid for stumbling. She was an inspiration and gave so much of herself that it made you want to give back all you could.

So, today on this Teachers' day, I want to thank Mrs. Crossno and all my teachers throughout the years. You have blessed me in so many ways.

Thursday, September 4, 2008

I'm truly honored

I received an email this past week with the following (partial) content:
I am pleased to inform you that you have been nominated for the Oracle ACE award. You have been chosen based on your significant contribution and activity in the Oracle technical community. Like your fellow Oracle ACEs, you have demonstrated a proficiency in Oracle technology as well as a willingness to share your knowledge and experiences with the community.

I am pleased and very honored to join the ranks of Oracle ACEs and will make it my continuing goal to be deserving of it.

Monday, September 1, 2008

Too big?

What do you think?

Did I make the wrong choice when I bought the super jumbo size tub of "I Can't Believe It's Not Butter"?

Let me help you visualize the size a bit better. Here's the tub next to a cream cheese container that is the same size (8 oz) as my previous size butter tub.

I'm thinking that my logic was a bit flawed when I decided on the 45 ounce size. I thought it was smart. The super jumbo tub was on sale and only cost 50 cents more than the small size. It seemed to me to be an easy choice. The big tub would equate to over 5 of the smaller size and cost only 50 cents more. Sounds like a great deal, right?

However, the problem with my choice became evident when I got home with my purchase. Where was this gigantic tub o' butter going to fit in my refrigerator? I ended up having to rearrange an entire shelf to get the thing to fit. Of course, the arrangement I came up with meant that if/when I wanted to get out the butter, I'd have to get out several other items just to be able to pull the big guy from its spot. Sigh...

Sometimes I suppose you just shouldn't go for what seems to be the obviously better deal, huh?