db file scattered read

I tested this example on Oracle 11.2.

I wanted to see whether the TIME_WAITED column in V$SESSION_EVENT is only incremented for events such as db file scattered read and db file sequential read if Oracle has to go to disk to satisfy a read request. I decided to check this out using the db file scattered read event, which is associated with full table scans. Before I started, I created a table called ANDREWS_TABLE. Then I checked the total time my session had waited for the event in question:

SQL> select time_waited

  2  from v$session_event

  3  where sid = (select distinct sid from v$mystat)

  4  and event = 'db file scattered read'

  5  /

TIME_WAITED

-----------

        520

SQL>

Next I counted the rows in the table. This was the first time I had done this so Oracle had to get the rows from disk:

SQL> set timing on

SQL> select count(*) from andrews_table

  2  /

  COUNT(*)

----------

     12308

Elapsed: 00:00:00.18

SQL> set timing off

SQL>

I checked the total time waited for the event and it had increased by 0.15 seconds – so far so good:

SQL> select time_waited

  2  from v$session_event

  3  where sid = (select distinct sid from v$mystat)

  4  and event = 'db file scattered read'

  5  /

TIME_WAITED

-----------

        535

SQL>

I counted the rows again. This time Oracle already had the blocks in memory so it did not have to go to disk:

SQL> set timing on

SQL> select count(*) from andrews_table

  2  /

  COUNT(*)

----------

     12308

Elapsed: 00:00:00.01

SQL> set timing off

SQL>

The elapsed time went down from 0.18 seconds to 0.01 seconds because Oracle already had the rows in memory. Finally I checked the time waited for the event again:

SQL> select time_waited

  2  from v$session_event

  3  where sid = (select distinct sid from v$mystat)

  4  and event = 'db file scattered read'

  5  /

TIME_WAITED

-----------

        535

SQL>

It had not increased, showing that the TIME_WAITED for this event only goes up during a full table scan if Oracle has to fetch blocks from disk.

V$SYSTEM_EVENT

This was tested on Oracle 11.2. V$SYSTEM_EVENT shows what an instance has been waiting for since it was last started. You can see the top 10 events (by total time waited) as follows. The times are in hundredths of a second:

SQL> l

  1  select * from

  2  (select event, time_waited

  3   from v$system_event

  4   where wait_class != 'Idle'

  5   order by 2 desc)

  6* where rownum <= 10

SQL> /

 

EVENT                               TIME_WAITED

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

control file sequential read             992637

db file sequential read                  569680

control file parallel write              543468

os thread startup                        515992

log file parallel write                  499896

db file parallel write                   426726

db file scattered read                   202302

log file sync                            159840

Disk file operations I/O                  45765

ADR block file read                       29553

 

10 rows selected.

 

SQL>

 

If you include Idle events, you see the wait events where the database wasn’t doing anything. The SQL*Net message from client event, for example, records how long the database spent waiting for its next instruction. This may not be what you want to see:

SQL> l

  1  select * from

  2  (select event, time_waited

  3   from v$system_event

  4   order by 2 desc)

  5* where rownum <= 10

SQL> /

 

EVENT                                    TIME_WAITED

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

rdbms ipc message                         1956293654

SQL*Net message from client                637129764

DIAG idle wait                             326433989

dispatcher timer                           163322456

shared server idle wait                    163320698

Streams AQ: qmn coordinator idle wait      163318553

Streams AQ: qmn slave idle wait            163315578

smon timer                                 163264804

pmon timer                                 163252749

Space Manager: slave idle wait             163171812

 

10 rows selected.

 

SQL>

 

The TIME_WAITED for SQL*Net message from client works out at almost 74 days. However, the database has been open for less than 20 days:

 

SQL> l

  1  select startup_time, sysdate

  2* from v$instance, dual

SQL> /

 

STARTUP_TIME SYSDATE

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

04-MAY-12    23-MAY-12

 

SQL>

 

That’s because the TIME_WAITED values are the sum of all the TIME_WAITED values for all the sessions which have logged in since the database was opened.

 

If you combine these figures with the CPU time used, you start to get an idea of what your database has been doing:

 

SQL> l

  1  select a.name, b.value

  2  from v$statname a, v$sysstat b

  3  where a.statistic# = b.statistic#

  4* and a.name = 'CPU used by this session'

SQL> /

 

NAME                                     VALUE

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

CPU used by this session               1854863

 

SQL>