Excessive CPU Usage in Oracle 11.2.0.1.0

I had a problem with excessive CPU usage in Oracle 11.2.0.1.0. One piece of SQL in particular, which runs quickly on other versions, was taking up to 30 seconds to finish. While it was running, two waits could be seen in the database:

SQL> l

  1  select sid, event, seconds_in_wait

  2  from v$session_wait

  3  where wait_class <> 'Idle'

  4* order by sid, event

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   101 SQL*Net more data from client                7

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   101 asynch descriptor resize                     3

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   101 asynch descriptor resize                     7

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   101 asynch descriptor resize                    10

   156 SQL*Net message to client                    0

 

SQL> /

 

   SID EVENT                          SECONDS_IN_WAIT

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

   156 SQL*Net message to client                    0

 

SQL>

 

At this stage, I was not concerned with the SQL*Net more data from client event, just the asynch descriptor resize event. I looked on My Oracle Support and decided it could be caused by bug 9829397. Oracle has various patches available to fix the problem. The workaround is to set disk_asynch_io to false.

 

According to Oracle:

 

DISK_ASYNCH_IO controls whether I/O to datafiles, control files, and logfiles is asynchronous (that is, whether parallel server processes can overlap I/O requests with CPU processing during table scans). If your platform supports asynchronous I/O to disk, Oracle recommends that you leave this parameter set to its default value. However, if the asynchronous I/O implementation is not stable, you can set this parameter to false to disable asynchronous I/O. If your platform does not support asynchronous I/O to disk, this parameter has no effect.

 

First I checked that it was set to true:

 

SQL> l

  1  select value from v$parameter

  2* where name = 'disk_asynch_io'

SQL> /

 

VALUE

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

TRUE

 

SQL>

 

Then I set it to false to check if this was causing my problem (I had to bounce the database to do so):

 

SQL> l

  1  select value from v$parameter

  2* where name = 'disk_asynch_io'

SQL> /

 

VALUE

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

FALSE

 

SQL>

 

Then I read elsewhere in the Oracle documentation that:

 

If you set DISK_ASYNCH_IO to false, then you should also set DBWR_IO_SLAVES to a value other than its default of zero in order to simulate asynchronous I/O.

 

So I set it to 1 (I had to bounce the database to do this):

 

SQL> l

  1  select value from v$parameter

  2* where name = 'dbwr_io_slaves'

SQL> /

 

VALUE

----------

1

 

SQL>

 

After this, the performance was much better and the worst performing piece of SQL took an average of 3 seconds to run instead of 30. This showed that I had identified the problem correctly. However, as a long term solution it might be better to move to a version of Oracle which is not affected by this problem at all.

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>

AVERAGE_WAIT

The AVERAGE_WAIT column in V$SYSTEM_EVENT records how long Oracle has had to wait (on average) for a given event. The value is in hundredths of a second:

 

SQL> l

  1  select event, average_wait

  2  from v$system_event

  3  where event in

  4  ('db file sequential read',

  5*  'db file scattered read')

SQL> /

 

EVENT                          AVERAGE_WAIT

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

db file sequential read                1.67

db file scattered read                 5.16

 

SQL>

 

The example above was run on an Oracle 11.2 test database running on Solaris with datafiles on a Celerra filer. The first line relates to single block reads and the second to multiblock reads. Here are the same values from an Oracle 11.2 production database, also running on Solaris but with datafiles on dedicated disks:

 

SQL> l

  1  select event, average_wait

  2  from v$system_event

  3  where event in

  4  ('db file sequential read',

  5*  'db file scattered read')

SQL> /

 

EVENT                          AVERAGE_WAIT

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

db file sequential read                  .2

db file scattered read                  .58

 

SQL>

Finally, here are the figures from an Oracle 10.2.0.1.0 database running on Windows XP SP3 on a PC I assembled myself:

SQL> l
  1  select event, average_wait
  2  from v$system_event
  3  where event in
  4  ('db file sequential read',
  5*  'db file scattered read')
SQL> /

EVENT                          AVERAGE_WAIT
------------------------------ ------------
db file sequential read                6,49
db file scattered read                 5,88

SQL>