RSS Feed

Method R Discussion Group

Hi All!

Sorry, I'm not sure that the best place to discuss my question, but I cannot find better :)

I read "Optimizing Oracle Performance " by Cary Millsap and try to play with my oracle10gR2.

My example sql script looks like this:
ALTER SESSION SET max_dump_file_size=unlimited;
ALTER SESSION SET timed_statistics=true;
ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';
SELECT 'Hello, world; today is ' || SYSDATE FROM dual;
EXIT;

After script execution I got trace (skip uninteresting info):
=====================
PARSING IN CURSOR #2 len=53 dep=0 uid=61 oct=3 lid=61 tim=1151519905950403 hv=2296704914 ad='4e50010c'
SELECT 'Hello, world; today is ' || SYSDATE FROM dual
END OF STMT
PARSE #2:c=4000,e=1540,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1151519905950397
BINDS #2:
EXEC #2:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1151519906034782
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1151519906034809
FETCH #2:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1151519906034864
WAIT #2: nam='SQL*Net message from client' ela= 215 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1151519906035133
FETCH #2:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1151519906035165
WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1151519906035188
WAIT #2: nam='SQL*Net message from client' ela= 192 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1151519906035400
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=3 us)'

Sum of all CPU time is 4000, sum of all e time is 1628, and sum of all ela time in waits is 410. As a result for that cursor I got this funny statistics:

SELECT 'Hello, world; today is ' || SYSDATE FROM dual
 Duration    Pct Oracle kernel event                   
--------- ------ ----------------------------------------
    3.00s  0.2% SQL*Net message to client             
  407.00s  25.0% SQL*Net message from client           
 1218.00s  74.8% unaccounted-for                       
 4000.00s 245.7% total CPU             

So, my a bit stupid questions are:
1 what is a reason for such wrong statistics?
2 On oracle server I have 2 Intel Xeon CPUs (top shows me 4 CPUs). What is a correct way to calculate statistics in my case?

Thanks a lot!

Hey, I think it's a /great/ place to discuss this kind of thing. Thank you for your questions.

A couple of observations that may help you:

- The duration described by your trace file excerpt is 86,543us (microseconds). That's the difference between the time stamp at the tail end of your trace file and the time stamp of the first parse minus its 1,540us duration.

- The vast majority of this 86,543us is the 84,385us of unaccounted-for time between the end of the parse call (tim=...5950397) and the beginning of the exec call (tim=...6034782 - 58). This is some kind of uninstrumented code path in the kernel: 84,385us worth!

- The story behind "c=4000,e=1540" is explained on pages 161-165 of the "Optimizing Oracle Performance" book you mentioned. One thing I've not seen before: I would have expected CPU time to move in increments of 10000us, so seeing a c=4000 is a bit of a surprise to me. What OS are you running?

- Your real profile for the 86,543us looks something like this:

84,505  98% unaccounted-for between calls
 4,000  5% CPU parse
  407  0% SQL*Net message from client
    3  0% SQL*Net message to client
-2,372  -3% unaccounted-for within dbcalls
------ ---- ------------------------------
86,543 100% total elapsed time

It's not pretty, but for a sample this small, it's pretty common.

Thanks a lot for your replay!!! :)

I use gentoo linux:

ash ~ # uname -a
Linux ash 2.6.20-gentoo-r8 #1 SMP Tue May 8 15:55:03 NOVST 2007 i686 Intel(R) Xeon(TM) CPU 3.40GHz GenuineIntel GNU/Linux

Hi All,

I'm also following the "Optimizing Oracle Performance" book and the above explanation was immensely helpful. My question is with regard to the trace shown below. This a simple insert.

PARSING IN CURSOR #2 len=26 dep=0 uid=57 oct=2 lid=57 tim=1156803210756417 hv=3761103747 ad='247d3184'
insert into a values ('n')
END OF STMT
PARSE #2:c=2000,e=1343,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1156803210756396
BINDS #2:
EXEC #2:c=0,e=422,p=0,cr=1,cu=3,mis=0,r=1,dep=0,og=1,tim=1156803210756985
WAIT #2: nam='SQL*Net message to client' ela= 12 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1156803210757193
WAIT #2: nam='SQL*Net message from client' ela= 2798389 driver id=1650815232 #bytes=1
 p3=0 obj#=-1 tim=1156803213555671
XCTEND rlbk=0, rd_only=0
WAIT #0: nam='log file sync' ela= 689 buffer#=554 p2=0 p3=0 obj#=-1 tim=1156803213557303               

As you can see there’s a wait event listed after the XCTEND line.
Should I consider that as well? Or response times are only concerned with values between PARSING IN CURSOR and XCTEND lines?

Another thing I want to get clarified is that most of the time we only see the value of ‘c’ set only on the parse line. But if there are any values set to ‘c’ in exec and fetch that should be also considered as CPU time?

Thank you for your help.
Asanga Pradeep