Skip to Main Content
  • Questions
  • Top 5 Timed events seems to exceed available time

Breadcrumb

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 we 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

Comments

gotcha

A reader, August 07, 2007 - 4:24 pm UTC

Thanks a bunch.

Tom Kyte
August 10, 2007 - 2:56 pm UTC

CPU is a timed event

latch free was a wait event.


CPU is CPU is CPU - we cannot time the time you spend "waiting" for CPU

so CPU in here is not a wait event?

A reader, August 07, 2007 - 4:29 pm UTC

Just occurred to me - are you saying that the appearance of CPU in this "top 5" just means it was a timed event, but what it was really *waiting* on was latch free? In other words, is CPU just "an event" or is it a "wait event" where you have to dig to see what it was waiting for? I always assumed if I see "scattered read" it's waiting for an IO, not just processing one.

Resource Constraints

Manikandan, November 03, 2008 - 1:28 pm UTC

Top 5 Timed Events
~~~~~~~~~~~~~~~~~~

Event Waits Time (s) % Total
Ela Time
-------------------------------------------- ---------------- ----------- --------
ARCH wait on ATTACH 2,618 33 -.00
ARCH wait on DETACH 3,177 0 -.00


Please help

Drop and re-create system tablespace

Muhammad Idrees, April 09, 2013 - 1:05 pm UTC

Dear Tom,

we have a Oracle 10g R1 Database.
we shutdown it with shutdown abort option.
and we try to startup, but we face the following problem.
ORA-01110: data file 34: 'G:\ORACLE\DATAFILES_ACADEMY\ACADEMY'
ORA-01115: IO error reading block from file 34 (block # 1)
ORA-27070: async read/write failed
OSD-04016: Error queuing an asynchronous I/O request.
O/S-Error: (OS 23) Data error (cyclic redundancy check).

we investigate the file 34, and it belongs to system tablespace.we have no backup to restore from.
we try the following also,
alter database datafile 34 offline drop;
alter database open;

but of no use.

my question is that how to drop and re-create a system tablespace?
Regards.
Tom Kyte
April 22, 2013 - 2:29 pm UTC

nope, you have just successfully lost all data.

please contact support.

Mistake

Muhammad Idrees, April 09, 2013 - 1:08 pm UTC

I am Sorry,
i was thinking i am posting new question.
i mistakenly post a review.
kindly ignore my mistake.

regards.

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.