Skip to Main Content

Breadcrumb

Warning

Before you submit your comment...

Remember - this is about feedback to the original question. AskTOM is about building a strong Oracle community, not stealing time away from others needing assistance by sneaking in a brand new question under the guise of "Comment".

If your comment requires a response that might include a query, please supply very simple CREATE TABLE and INSERT statements. Nice simple scripts so we can replicate your issue simply.

Remember to take a look at Legal Notices and Terms of Use before supplying a comment...

Don't forget, your comments are public. If you want to send a comment to just the AskTOM team, please use the feedback option

Comment

Highlight any SQL, PL/SQL, or fixed-width text and click the <code> button
 (will never be published or used to spam you)

Question and Answer

Tom Kyte

Thanks for the question, Doug.

Asked: August 05, 2007 - 4:45 pm UTC

Last updated: April 22, 2013 - 2:29 pm UTC

Version: 9204

Viewed 1000+ times

You Asked

Tom - here are 2 small parts of a 1 hour statspack snapshot - question below.
This is a 9204 database.

            Snap Id     Snap Time      Sessions Curs/Sess Comment
            ------- ------------------ -------- --------- -------------------
Begin Snap:   12835 14-Jun-07 15:00:01      378       3.6
  End Snap:   12837 14-Jun-07 16:00:01      384       4.3
   Elapsed:               60.00 (mins)

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~                                                     % Total
Event                                               Waits    Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
CPU time                                                       19,612    35.04
latch free                                        899,688      14,371    25.68
db file scattered read                         16,333,411      13,105    23.42
SQL*Net message from dblink                       439,535       4,440     7.93
direct path write                                 405,226       1,509     2.70


So this snapshot is 1 hour.. 
that is 3600 seconds.  This is on a 8 cpu box. so that is 28,800 seconds? 
How can 19,612 seconds be 35% of total elapased time?  How can the total 5 events add up to over 50,000 seconds?

and Tom said...

In one hour on an 8 cpu machine, you have 28,800 cpu seconds yes.

Now, in that report, you have a total of:


ops$tkyte%ORA10GR2> select 19612+14371+13105+4440+1509 from dual;

19612+14371+13105+4440+1509
---------------------------
                      53037



53,037 seconds - 35% of that is 19,612 - so that 35% just means "19,612 seconds was 35% of the sum of all of these times"

It is not total ELAPSED time - it is just "time" (if these were all WAITS, it would be more relevant - this just says you spent MOST of your time on the cpu doing something - probably spinning on latches given that your biggest wait was "latch free" which means you spun 2,000 times in a loop and then went to sleep to try again for the latch later).


the wait events could be infinite in duration (not really, but really really big is not out of the question).

If you have a 1 minute snapshot
And you have 1,000 users logged in
and one of them has issued "lock table t in exclusive mode"
and the rest try to insert into that table

then in one minute you will observe 999 minutes of elapsed wait time on enqueue waits as 999 sessions sit there concurrently and wait and wait and wait.


So, don't forget these things are cumulative as well! Over all sessions.

Rating

  (5 ratings)

Is this answer out of date? If it is, please let us know via a Comment