Home » RDBMS Server » Performance Tuning » Elapsed time not accounted in tkprof file (Oracle 9.2 on HP-UX)
Elapsed time not accounted in tkprof file [message #489114] Thu, 13 January 2011 05:38 Go to next message
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 #489115 is a reply to message #489114] Thu, 13 January 2011 05:42 Go to previous messageGo to next message
Michel Cadot
Messages: 68625
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Nowhere if the query was already started tkprof ignore it.
Look at the raw trace file.

Regards
Michel

[Updated on: Thu, 13 January 2011 05:43]

Report message to a moderator

Re: Elapsed time not accounted in tkprof file [message #489117 is a reply to message #489115] Thu, 13 January 2011 06:01 Go to previous messageGo to next message
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 #489120 is a reply to message #489117] Thu, 13 January 2011 06:07 Go to previous messageGo to next message
Michel Cadot
Messages: 68625
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Quote:
But not getting what is the culprit!

I don't understand what you mean. Both events are normal, Oracle reads the disks and Oracle returns the information you asked it from what it read.

Don't focus on wait events, try to optimize the query, if it is possible.

Regards
Michel

Re: Elapsed time not accounted in tkprof file [message #489127 is a reply to message #489120] Thu, 13 January 2011 06:35 Go to previous messageGo to next message
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 #489128 is a reply to message #489127] Thu, 13 January 2011 06:47 Go to previous messageGo to next message
Michel Cadot
Messages: 68625
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Quote:
which part of a very big query which in itself made up of small queries

What do you mean? a query is a whole.

Quote:
It shows some small queris executing many times of the order of thousands

Then you call these queries thousand times, this is not a lone query that executes them.

Quote:
timing for that thousands execution is still not accounting for total elapsed time

Did you sum up all the times in the raw trace?
If no, how do you know?

Regards
Michel
Re: Elapsed time not accounted in tkprof file [message #489129 is a reply to message #489127] Thu, 13 January 2011 06:48 Go to previous messageGo to next message
cookiemonster
Messages: 13917
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 Go to previous messageGo to next message
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 #489157 is a reply to message #489154] Thu, 13 January 2011 09:46 Go to previous messageGo to next message
BlackSwan
Messages: 26766
Registered: January 2009
Location: SoCal
Senior Member
>ora_qmn*
are Active Queueing processes.
Provide details about why they are busy on the system
Re: Elapsed time not accounted in tkprof file [message #489161 is a reply to message #489157] Thu, 13 January 2011 10:21 Go to previous messageGo to next message
Michel Cadot
Messages: 68625
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Quote:
Why the single block access is slow and why there isn't any I/O (but high CPU) on the system?

Once again use the standard way to optimize a statement.
Read http://www.orafaq.com/forum/mv/msg/84315/433888/102589/#msg_433888 and post the required information.

Regards
Michel
Re: Elapsed time not accounted in tkprof file [message #489166 is a reply to message #489161] Thu, 13 January 2011 10:47 Go to previous messageGo to next message
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 Go to previous message
cookiemonster
Messages: 13917
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.
Previous Topic: How to partition tables and indexes in this scenario?
Next Topic: AWR report
Goto Forum:
  


Current Time: Fri Mar 29 01:09:16 CDT 2024