OraNA :: Oracle News Aggregator

A friend of mine sent this to me. Oh how true it is! Don't you just hate getting those cutesy emails that promise you to have eternal youth and good fortune if you only would forward the email on to 10 of your friends?

OK, I admit that I've done it once or twice. And for those of you who have been on the receiving end, please allow me to apologize. I guess there have just been moments when I really wanted what was promised to be granted to me. And if it only meant forwarding on one little email, then what's the harm, right?

Harumph! Hope may spring eternal, but there is a line between hope and not being rational.

Not that I'm against hoping and wishing for things that I want to happen, but in regard to this particular method of achieving my dreams, I think from now on I'm simply going to reply to the sender with this graphic. Then, I'll go buy a lottery ticket.

:)

Cary Millsap recently had a great post on the use of active vs. passive voice when writing. Check it out, it's an excellent read.

Anyway, Cary made a reply to one of the comments he received that has sparked much thought on my part. His statement was:

Learning is a state transition between not knowing something and knowing it. For someone to truly learn, he has to have the courage to admit—at least to himself—that there's something he doesn't know. Some people are unwilling to do that.

Think about that for a second. What do you think? Is the capacity to learn rooted in the ability to simply admit there is something you don't know?

I think Cary's spot on with that assessment. I do believe that fear of admitting what you don't know holds you back from learning/knowing what you need to. It's like having blinders on. I prefer to believe it is fear based and not arrogance, but I think arrogance is at the heart of many people's unwillingness to seek out knowledge. I mean, what if they're proved wrong about something they've stated as truth? If you think yourself an "expert" and your ego can't stand the hit it would take if you are proven wrong, aren't you destined to be found lacking knowledge you claim to possess at some point?

Although I can't find the exact quote, I remember reading something to the effect of "A wise man knows he doesn't know everything." For me, my personal goal is to be continually in the process of learning. I love to learn. Sometimes the process is painful or embarrassing when I state something I believe to be fact and am shown that my information is either lacking or just plain wrong. But, even then, I'm glad to learn. Without coming under critique, how do I confirm what I claim I know? In the end, it's empowering for me...and humbling too. I like knowing and I like sharing what I know. But in order to know, I have to first learn. And I think that learning is the real thrill for me. Sharing what I learn is just icing on the cake.

I think it's easy to get complacent and not seek out new knowledge. Many times I see people who do basically the same job and see the same issues day after day, month after month. It's easy to get lazy. It's easy to turn around and your company is considering implementing Oracle 11 and you've never bothered to learn anything more than you knew when you learned back in Oracle 7. It's easy to assume that once you know something, that knowledge stays fixed and there's no need to "upgrade" that knowledge.

For me, I do what I do because not only do I like to mentor and teach, but I primarily love to learn. My first job was in the government sector. I was the new, young kid working with a bunch of guys who had been at their jobs for 20-30 years. When I finished projects ahead of my allotted time, they'd chide me. They told me I needed to learn to "take it easy" and that I "wasn't in school anymore" and didn't need to complete my assignments in record time or try to impress my professors. I just needed to sit back and relax and learn to "not tax my brain". I tried (for a very short while). But, I stagnated. I couldn't stand sitting still. I couldn't stand not learning and not doing more than just what I knew. I wanted more. I wanted challenge. I wanted to expand what I knew so I could do my job better and more efficiently.

In the end, I stayed in my first job for less than a year. And, I know now as I look back, it was the simple fact that I wasn't learning that prompted me to leave. I grew bored and uninterested in my job and I just couldn't stand it.

It takes courage to be a learner. It requires effort. It requires being willing to admit there's a lot I don't know. But I know for me there's no other choice. Learning is like a drug and I'm an addict.

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.

     1
     |
  -------
  |     |
  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.

     1
     |
  -------
  |     |
  2     4
  |     |
  3     5
        |
        6

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!

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!

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.

Canada


Ontario


Near Toronto which is near this gorgeous landmark


In the city of Waterloo



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