Re: Why is time_waited more than total elapsed time ?

From: Bass Chorng <bchorng_at_yahoo.com>
Date: 21 Jun 2002 11:58:02 -0700
Message-ID: <bd9a9a76.0206211058.2ad29e3f@posting.google.com>

Sybrand Bakker <postbus_at_sybrandb.demon.nl> wrote in message news:<jo54husfii9qkec001l7ejs51jcotj89q4_at_4ax.com>...
>
> No other session running: how about the background processes? Do you
> think they do nothing? Can't they be occupied coalescing your free
> space? If you look at the number of disk reads incurred you have to
> explain for some 9000 reads. So you are comparing apples and pears.
> Your assertion about v$session_event can't be true. Are you sure you
> checked the correct session?
>
> Hth
>

I don't think my background processes will be THAT busy every single time
I ran this test. All my pctincrease are set to 0, so it should not coalesce free space unless I tell it to.

  Below shows what did step by step. You can see the mis-matching part of
  v$session_event and v$system_event. I am 100% positive there is no other
  session running as this is a controlled environment and I am the only one
  using it.

  1st, I bounced the DB,
  2nd, I verified my own sid (note I never change the session thru test )
  3rd, I started trace
  4th, I ran be begin.sql to capture before values of v$system_event.

It creates some temp tables to hold the image. 5th, I selected current value of 'db file sequential read' in v$system_event

( note so far only 1.84 seconds are spent )

  6th, I set term off so the result does not screw up my screen
  7th, I ran the long query
  8th, It finished, so I ran my eng.sql which populates the diff into
my own
       tables.

9th, I queried against current v$system_event for a comparison to step 5.

( Note that time waited is 423.70 seconds now ) 10th, I query against v$session_event and the values are almost zero.

( Note that time waited is only 0.02 seconds ). My session never

changed.

Here is the diff I captured for this event:

TIMESTAMP           EVENT                              TOTAL_WAITS

TIME_WAITED

------------------- ----------------------------------------------
-----------
06-21-2002 11:11:17 db file sequential read                 80965

42192

( Note that the time stamp and value matches my query against v$system_event.

And here is the tkprof portion of that long query: ( Note the elapsed time is only 296.06 seconds. I don't think any background
processes can fill up that 127 second gap - consistently. So my questions
are still back to:

Why is the wait time 42% more than my total elased time ? I don't think any round up or background activity can explain this.
Why is my v$session_event completely off ? )

Version: 8.1.7.2.0
Platform: Solaris 2.8 on 420R

Select push_tbl.push_id, push_tbl.unique_id, push_tbl.push_addr,

push_tbl.push_addr_type, push_tbl.event_time,
push_tbl.delivery_method, push_tbl.network,
push_tbl.bearer, push_tbl.pap_addr, push_tbl.elid,
push_content_tbl.pi, push_content_tbl.source_ref,
push_content_tbl.callbackURL, push_content_tbl.received_time,
push_content_tbl.push_http_hdrs,
push_content_tbl.priority, push_content_tbl.network_required,
push_content_tbl.bearer_required,
push_content_tbl.deliver_before,push_content_tbl.deliver_after,
push_content_tbl.wdp_bearers,
push_content_tbl.sir_allowed, push_content_tbl.is_trusted,
push_content_tbl.is_auth,
push_content_tbl.content_type, push_content_tbl.push_content_len,
push_content_tbl.push_content

from push.PUSH_TBL, push.PUSH_CONTENT_TBL where push_tbl.state=6 and push_tbl.pde=123
and push_tbl.push_id=push_content_tbl.push_id

call     count       cpu    elapsed       disk      query    current  
     rows

------- ------ -------- ---------- ---------- ---------- ----------

Parse        1      0.09       0.04          1         18          0  
        0
Execute      1      0.00       0.00          0          0          0  
        0
Fetch     5807     21.82     296.02      76109     376395         37

87091
------- ------ -------- ---------- ---------- ---------- ----------

total 5809 21.91 296.06 76110 376413 37

87091

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: SYS

10:59:58 opwvdb SQL> startup
ORACLE instance started.

Total System Global Area 965431456 bytes

Fixed Size                    73888 bytes
Variable Size             145879040 bytes
Database Buffers          819200000 bytes
Redo Buffers                 278528 bytes

Database mounted.
Database opened.
11:00:13 opwvdb SQL> select distinct sid from v$mystat;

SID

11:00:50 opwvdb SQL> alter session set events '10046 trace name context forever, level 12';

Session altered.

11:01:47 opwvdb SQL> @begin
Connected.

Table dropped.

Table created.

11:02:04 opwvdb SQL> select * from v$system_event where event = 'db file sequential read';

EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT

-------------- ----------- ------------ db file sequential read 877 0 184 .209806157

11:02:26 opwvdb SQL> set term off
11:02:32 opwvdb SQL> @/tmp/push
11:10:34 opwvdb SQL> set term off
11:11:12 opwvdb SQL> @end
11:11:17 opwvdb SQL>  select * from v$system_event where event = 'db

file sequential read';

EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT

-------------- ----------- ------------ db file sequential read 81835 0 42370 .517749129

11:11:29 opwvdb SQL> select * from v$session_event where sid = 13 and event = 'db file sequential read';

       SID EVENT                                                      
     TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT
---------- ----------------------------------------------------------------

----------- -------------- ----------- ------------ MAX_WAIT

        13 db file sequential read                                    
               8              0           2          .25
         1

Received on Fri Jun 21 2002 - 13:58:02 CDT