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>

V$EVENT_NAME

This was run in an Oracle 11.2 database. What is in V$EVENT_NAME?

SQL> desc v$event_name

Name                       Null?    Type

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

EVENT#                              NUMBER

EVENT_ID                            NUMBER

NAME                                VARCHAR2(64)

PARAMETER1                          VARCHAR2(64)

PARAMETER2                          VARCHAR2(64)

PARAMETER3                          VARCHAR2(64)

WAIT_CLASS_ID                       NUMBER

WAIT_CLASS#                         NUMBER

WAIT_CLASS                          VARCHAR2(64)

 

SQL>

 

Despite its name, this is not a dynamic view like V$SESSION, for example. It contains details of all the wait events being recorded by your database. In Oracle 11.2 there are over 1000 wait events:

 

SQL> select count(*) from v$event_name

  2  /

 

  COUNT(*)

----------

      1118

 

SQL>

 

Each event has a number and name. These can change between Oracle versions:

 

SQL> l

  1* select event#, name from v$event_name

SQL> /

 

    EVENT# NAME

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

         0 null event

         1 pmon timer

         2 logout restrictor

         3 VKTM Logical Idle Wait

         4 VKTM Init Wait for GSGA

         5 IORM Scheduler Slave Idle Wait

         6 Parameter File I/O

         7 rdbms ipc message

         8 remote db operation

         9 remote db file read

        10 remote db file write

        11 Disk file operations I/O

        12 Disk file I/O Calibration

        13 Disk file Mirror Read

        14 Disk file Mirror/Media Repair Write

        15 direct path sync

        16 Datapump dump file I/O

Etc.

 

Each event also has a hash value based on the name. This will not change between Oracle versions if the name remains the same. It is stored in the EVENT_ID column:

 

  1* select event_id, name from v$event_name

SQL> /

 

  EVENT_ID NAME

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

2516578839 null event

3539483025 pmon timer

3934444552 logout restrictor

939791390 VKTM Logical Idle Wait

1513856046 VKTM Init Wait for GSGA

1421578053 IORM Scheduler Slave Idle Wait

1179235204 Parameter File I/O

866018717 rdbms ipc message

3222461937 remote db operation

2171045634 remote db file read

538064841 remote db file write

166678035 Disk file operations I/O

2215689832 Disk file I/O Calibration

  13102552 Disk file Mirror Read

2577606720 Disk file Mirror/Media Repair Write

2093619153 direct path sync

4155572307 Datapump dump file I/O

etc

 

Each event has a WAIT_CLASS. This allows you to exclude Idle events, for example. Each WAIT_CLASS has a hash value based on its name. This is stored in the WAIT_CLASS_ID column:

 

SQL> l

  1  select wait_class, wait_class_id, count(*)

  2  from v$event_name

  3* group by wait_class, wait_class_id

SQL> /

 

WAIT_CLASS           WAIT_CLASS_ID   COUNT(*)

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

Network                 2000153315         35

Configuration           3290255840         24

Queueing                 644977587          9

Other                   1893977003        719

Concurrency             3875070507         32

Idle                    2723168908         94

Scheduler               2396326234          7

User I/O                1740759767         45

System I/O              4108307767         30

Commit                  3386400367          2

Cluster                 3871361733         50

Administrative          4166625743         54

Application             4217450380         17

 

13 rows selected.

 

SQL>