| Elapsed time not accounted in tkprof file [message #489114] |
Thu, 13 January 2011 05:38  |
OraKaran
Messages: 183
Registered: March 2008
Location: United Kingdom
|
Senior Member |
|
|
Hello,
Please find the attached tkprof'ed file of session
I started the trace after the query started (upon user's complaint)
However even after tracing the session for more than 30 minutes I am not geeting where the 30 minutes are accounted in this file
please suggest
Regards,
OraKaran
|
|
|
|
|
|
| Re: Elapsed time not accounted in tkprof file [message #489117 is a reply to message #489115] |
Thu, 13 January 2011 06:01  |
OraKaran
Messages: 183
Registered: March 2008
Location: United Kingdom
|
Senior Member |
|
|
Hello Michel
Thanks for the quick reply
I have already checked the raw trace file and seeing lot of 'sequential reads' and 'scattered reads'
But not getting what is the culprit!
As the raw trace file has grown too big (beacuse of which I stopped the trace few minutes back)
I am sending last 30k lines in the raw trace files (trying to control 2048k size limit in post)
Please find the attached file
Regards,
OraKaran
|
|
|
|
|
|
| Re: Elapsed time not accounted in tkprof file [message #489127 is a reply to message #489120] |
Thu, 13 January 2011 06:35 |
OraKaran
Messages: 183
Registered: March 2008
Location: United Kingdom
|
Senior Member |
|
|
Hello Michel
The point here is
which is the time consuming query in this session?
(I mean which part of a very big query which in itself made up of small queries)
And if there is any, why the trace is not showing that such query or part of it has consumed more time.
It shows some small queris executing many times of the order of thousands, but timing for that thousands execution is still not accounting for total elapsed time
Regards,
OraKaran
|
|
|
|
|
|
| Re: Elapsed time not accounted in tkprof file [message #489129 is a reply to message #489127] |
Thu, 13 January 2011 06:48 |
cookiemonster
Messages: 13958
Registered: September 2008
Location: Rainy Manchester
|
Senior Member |
|
|
|
The two selects in the tkprof are probably from functions that are called from another select. If you can find the functions and you know what the user was doing when they encountered the problem then it really shouldn't be two difficult to work out the main sql statement. From there you can then start using explain plan and normal tunning techniques to speed it up.
|
|
|
|
| Re: Elapsed time not accounted in tkprof file [message #489154 is a reply to message #489129] |
Thu, 13 January 2011 09:38 |
OraKaran
Messages: 183
Registered: March 2008
Location: United Kingdom
|
Senior Member |
|
|
Michel and Cookimonster
Thanks for your replies
I think I am unable to explain my issue
Now please find the extract of recent trace (I know I this is not the complete detail but my query now pertains to this part only)
This is the only session on the server and we are seeing high "ela" values below
WAIT #16: nam='db file sequential read' ela= 9972 p1=39 p2=576820 p3=1
WAIT #16: nam='db file sequential read' ela= 28 p1=5 p2=3073304 p3=1
WAIT #16: nam='db file sequential read' ela= 10043 p1=39 p2=132950 p3=1
WAIT #16: nam='db file sequential read' ela= 24 p1=6 p2=3493362 p3=1
WAIT #16: nam='db file sequential read' ela= 18 p1=5 p2=3577858 p3=1
WAIT #16: nam='db file sequential read' ela= 7108 p1=38 p2=798732 p3=1
WAIT #16: nam='db file sequential read' ela= 7543 p1=5 p2=3958631 p3=1
WAIT #16: nam='db file sequential read' ela= 83 p1=39 p2=961606 p3=1
WAIT #16: nam='db file sequential read' ela= 10519 p1=40 p2=237374 p3=1
WAIT #16: nam='db file sequential read' ela= 5174 p1=5 p2=3958559 p3=1
*** 2011-01-13 15:29:03.784
WAIT #16: nam='db file sequential read' ela= 11868 p1=33 p2=3376498 p3=1
WAIT #16: nam='db file sequential read' ela= 25 p1=3 p2=3797029 p3=1
WAIT #16: nam='db file sequential read' ela= 7417 p1=5 p2=3958301 p3=1
WAIT #16: nam='db file sequential read' ela= 7631 p1=38 p2=113674 p3=1
WAIT #16: nam='db file sequential read' ela= 29 p1=39 p2=960798 p3=1
WAIT #16: nam='db file sequential read' ela= 7640 p1=6 p2=3781321 p3=1
WAIT #16: nam='db file sequential read' ela= 74 p1=6 p2=2962234 p3=1
WAIT #16: nam='db file sequential read' ela= 8653 p1=38 p2=3830369 p3=1
WAIT #16: nam='db file sequential read' ela= 8451 p1=39 p2=1361661 p3=1
WAIT #16: nam='db file sequential read' ela= 20 p1=6 p2=3780944 p3=1
WAIT #16: nam='db file sequential read' ela= 11165 p1=33 p2=3376052 p3=1
WAIT #16: nam='db file sequential read' ela= 6667 p1=27 p2=3675530 p3=1
WAIT #16: nam='db file sequential read' ela= 11361 p1=38 p2=113000 p3=1
WAIT #16: nam='db file sequential read' ela= 6953 p1=39 p2=576868 p3=1
WAIT #16: nam='db file sequential read' ela= 6108 p1=39 p2=1361514 p3=1
WAIT #16: nam='db file sequential read' ela= 4612 p1=27 p2=3675694 p3=1
WAIT #16: nam='db file sequential read' ela= 9279 p1=38 p2=3829869 p3=1
*** 2011-01-13 15:29:36.876
WAIT #16: nam='db file sequential read' ela= 8661 p1=6 p2=3169448 p3=1
WAIT #16: nam='db file sequential read' ela= 9381 p1=33 p2=1140246 p3=1
WAIT #16: nam='db file sequential read' ela= 18 p1=6 p2=3493630 p3=1
WAIT #16: nam='db file sequential read' ela= 10486 p1=8 p2=3813674 p3=1
WAIT #16: nam='db file sequential read' ela= 8629 p1=3 p2=3305381 p3=1
WAIT #16: nam='db file sequential read' ela= 8418 p1=33 p2=2774924 p3=1
WAIT #16: nam='db file sequential read' ela= 5637 p1=4 p2=3300752 p3=1
WAIT #16: nam='db file sequential read' ela= 10891 p1=5 p2=2985450 p3=1
WAIT #16: nam='db file sequential read' ela= 7321 p1=3 p2=2936470 p3=1
WAIT #16: nam='db file sequential read' ela= 16445 p1=5 p2=3577252 p3=1
WAIT #16: nam='db file sequential read' ela= 6569 p1=6 p2=3169314 p3=1
WAIT #16: nam='db file sequential read' ela= 11513 p1=5 p2=3073060 p3=1
WAIT #16: nam='db file sequential read' ela= 12534 p1=7 p2=2493018 p3=1
WAIT #16: nam='db file sequential read' ela= 23 p1=6 p2=2785711 p3=1
WAIT #16: nam='db file sequential read' ela= 8206 p1=4 p2=3300205 p3=1
WAIT #16: nam='db file sequential read' ela= 15 p1=3 p2=2936548 p3=1
WAIT #16: nam='db file sequential read' ela= 434 p1=5 p2=3073062 p3=1
WAIT #16: nam='db file sequential read' ela= 14126 p1=33 p2=1893014 p3=1
WAIT #16: nam='db file sequential read' ela= 24564 p1=39 p2=132522 p3=1
WAIT #16: nam='db file sequential read' ela= 5768 p1=38 p2=798314 p3=1
WAIT #16: nam='db file sequential read' ela= 21 p1=39 p2=132676 p3=1
WAIT #16: nam='db file sequential read' ela= 10411 p1=6 p2=3781199 p3=1
WAIT #16: nam='db file sequential read' ela= 75 p1=44 p2=397636 p3=1
WAIT #16: nam='db file sequential read' ela= 5211 p1=39 p2=578645 p3=1
WAIT #16: nam='db file sequential read' ela= 20594 p1=27 p2=3676078 p3=1
WAIT #16: nam='db file sequential read' ela= 9211 p1=33 p2=2774909 p3=1
WAIT #16: nam='db file sequential read' ela= 6327 p1=5 p2=3577468 p3=1
WAIT #16: nam='db file sequential read' ela= 21433 p1=41 p2=245991 p3=1
At same time folloiwng is the 'glance' report
Our session is with Pid= 4061 below
------------------------------------------------------------------------------------------------------------------------------
PROCESS LIST Users= 4
User CPU Util Cum Disk Thd
Process Name PID PPID Pri Name ( 400% max) CPU IO Rate RSS Cnt
--------------------------------------------------------------------------------
oracleDBY2KU 4061 1 178 oracle 93.3/81.8 3150.7 6.5/ 2.1 124.5mb 1
emdctl 7652 7650 149 oracle 2.1/ 2.1 0.1 0.1/ 0.1 84kb 1
vxfsd 54 0 134 root 1.5/ 0.9 22034.1 3.0/ 4.2 14.4mb 50
oracleDBY2KT 5290 1 178 oracle 0.8/ 0.5 11.7 0.0/ 0.4 87.8mb 1
ora_qmn2_DBY 22276 1 178 oracle 0.4/ 0.3 1751.0 0.0/ 0.0 38.2mb 1
ora_qmn1_DBY 2577 1 178 oracle 0.4/ 0.1 1611.1 0.0/ 0.0 53.5mb 1
ora_qmn0_DBY 2575 1 178 oracle 0.4/ 0.1 1593.3 0.0/ 0.0 53.7mb 1
ora_qmn1_DBY 25573 1 178 oracle 0.4/ 1.0 6967.0 0.0/ 0.0 87.7mb 1
emagent 3116 3109 154 oracle 0.2/ 0.6 15070.7 0.0/ 0.0 62.1mb 5
ora_reco_DBY 25569 1 178 oracle 0.0/ 0.0 0.3 0.0/ 0.0 85.3mb 1
ora_s002_DBY 25581 1 178 oracle 0.0/ 0.0 1.5 0.0/ 0.0 88.7mb 1
what we can see with these details?
Why the single block access is slow and why there isn't any I/O (but high CPU) on the system?
Also what could be the reason that the following values are inserted in the trace?
*** 2011-01-13 15:29:03.784
*** 2011-01-13 15:29:36.876
Regards,
OraKaran
|
|
|
|
|
|
|
|
| Re: Elapsed time not accounted in tkprof file [message #489166 is a reply to message #489161] |
Thu, 13 January 2011 10:47 |
OraKaran
Messages: 183
Registered: March 2008
Location: United Kingdom
|
Senior Member |
|
|
Hello BlackSwan and Michel
The user has stopped the query now
BlackSwan - we use workflow and queue processes were related to that which interact with yet another database
Michel - Thanks for sending me the link. In fact after I exhausted with all the options (I could think & try) I asked for help.
My question though for the mentioned query, I asked it for general understanding as I could not find what is slow to tune with.
For example while I was printing trace file with 'tail -f'
after printig 3-4 lines with following contents the output was stalling and then again after 5-10 seconds it was printing next lines
with the only oracle session active on the server I could not relate it with my knowledge and understnding
WAIT #16: nam='db file sequential read' ela= 25 p1=3 p2=3797029 p3=1
WAIT #16: nam='db file sequential read' ela= 7417 p1=5 p2=3958301 p3=1
WAIT #16: nam='db file sequential read' ela= 7631 p1=38 p2=113674 p3=1
WAIT #16: nam='db file sequential read' ela= 29 p1=39 p2=960798 p3=1
WAIT #16: nam='db file sequential read' ela= 7640 p1=6 p2=3781321 p3=1
moreover the first line appearing after the resuming the printing wasn't the line with high 'ela' values which I was expecting
Also we haven't changed anything at disk level that something will go slow all of a sudden!
As such I think guidelines are helpful but sometimes it is difficult to think of all and all possibilities
Regards,
OraKaran
|
|
|
|
| Re: Elapsed time not accounted in tkprof file [message #489171 is a reply to message #489166] |
Thu, 13 January 2011 11:17 |
cookiemonster
Messages: 13958
Registered: September 2008
Location: Rainy Manchester
|
Senior Member |
|
|
You're determined to look at this from the wrong angle aren't you.
You can not tell anything from a bunch of wait events in isolation - especially when they're disk reads (ie something the db always has to do).
They could mean that a SQL statement has started reading far more data from disk than it used to (because there's more data, or the stats have changed) so there are more waits. It could mean something else is tying up the disk so each wait takes longer.
There is no way to tell from the information provided.
You need to find the sql statement the user was running and see if there is a problem with it.
If there isn't a problem with it then you need to look at what else is running on the server that might be tying up the disks - like the queue processes maybe.
|
|
|
|
] 
Blog
Search
Help
Members
Register
Login
Home
