Re: cpu usage

From: Charles Hooper <hooperc2000_at_yahoo.com>
Date: 28 Dec 2006 09:44:52 -0800
Message-ID: <1167327892.068481.291380@42g2000cwt.googlegroups.com>

Charles Hooper wrote:
> hopehope_123 wrote:
> > Hi ,
> >
> > I am working on a database system which its cpu usage at the top
> > waiter list in statspack outputs.
> > Each statspack output ( in 60 min. intervals ) show same sql statement.
> > ( in the list of most buffer_gets )
> >
> > After examining the outputs , i came to a conclusion that cpu usage is
> > not problem.
> >
> > note also: log file sync and log file parallel write events are also in
> > the list, i know, my aim is to examine the cpu usage.
> >
> > I will be appreciated if you can comment .
> >
> > The server has 8 cpus.
> >
> >
> > Snap Id Snap Time Sessions Curs/Sess Comment
> > --------- ------------------ -------- ---------
> > -------------------
> > Begin Snap: 652 27-Dec-06 10:00:04 66 257.3
> > End Snap: 653 27-Dec-06 11:00:02 73 356.9
> > Elapsed: 59.97 (mins)
> >
> >
> > Top 5 Timed Events
> > ~~~~~~~~~~~~~~~~~~
> > % Total
> > Event Waits Time (s)
> > Ela Time
> > -------------------------------------------- ------------ -----------
> > --------
> > CPU time 7,084
> > 75.67
> > log file sync 166,839 819
> > 8.75
> > log file parallel write 356,741 529
> > 5.65
> > db file sequential read 38,676 484
> > 5.17
> > latch free 286,350 219
> > 2.34
> >
> > With 8 cpus, in 1 hour , i have total 8*3600=28800 sec. cpu time,
> > only 7084 sec. is spent.
> > So oracle db uses %24 of the total cpu time of the server.
> >
> >
> > Here is the sql list:
> >
> > CPU Elapsd
> > Buffer Gets Executions Gets per Exec %Total Time (s) Time (s)
> > Hash Value
> > --------------- ------------ -------------- ------ -------- ---------
> > ----------
> > 26,870,884 48,108 558.6 42.5 1470.76 1662.69
> > 1647928882
> > Module: JDBC Thin Client
> > BEGIN xxxx(:1,:2,:3,:4) END;
> >
> >
> > This proc is called 48108 in 1 hour , and takes 1470.76 secs. One call
> > takes 1470.76/48108 = 30msec.
> >
> >
> > Since average execution time of this procedure is 30 msec. , i think
> > there is not much thing to do with this sql. If in a way , i achieve
> > to decrease the response time of this sql to 10 msec. ,
> > than total time of this sql is also decreased proprtionaly ( 2/3)
> >
> > So i dont think the cpu time is an important factor and problematic on
> > this server.
> >
> > What do you think?
> >
> > Kind Regards,
> > hope

> Just a question here, do you expect someone to find a problem by
> looking at the portion of the Statspack report that you posted? Is
> there a real problem with the performance of the database?

> You apparently have one SQL statement that is being executed on average
> 13 times per second. The SQL statement likely is not:
> SELECT SYSDATE FROM DUAL;
> Since the above only requires 4 LIOs on 10g, and 8 on older versions of
> Oracle.
> Although it does make me wonder if the following would cause 558 LIOs
> per execution on 10g:
> SELECT SYSDATE FROM DUAL CONNECT BY LEVEL<=140;

> Suggestion: locate the sessions causing the SQL statement to be
> executed 13 times per second, run a 10046 trace on the sessions at
> level 8, and analyze the trace files either manually, or by feeding
> them through TKPROF.

> Looking at the top wait events:
> Of the 60 minute time interval, Oracle spent 13.65 minutes waiting on
> log file sync. Paraphrased from various sources: when a user session
> commits or rolls back, the session's redo information must be flushed
> to the redo log file by LGWR. The server process performing the COMMIT
> or ROLLBACK waits under this event for the write to the redo log to
> complete. If the average time waited is low, but the number of waits
> are high, then the application may be committing on every INSERT. If
> the average time waited is high, then examine the session waits for the
> log writer and see what it is spending most of its time doing and
> waiting for. If log writer's waits are due to slow I/O, reduce other
> I/O activity on the disks containing the redo logs; alternate redo logs
> on different disks to minimize the effects of the archiver on the log
> writer; move the redo logs to faster disks; consider using raw devices
> to speed up writes; batch commits by committing every N rows.

> Of the 60 minute time interval, Oracle spent 8.8 minutes waiting on log
> file parallel write. Paraphrased from Oracle Performance Tuning 101:
> Indicates waits associated with the writing of redo records from the
> redo log buffer to disk. Usually indicates slow devices or contention
> where the online redo logs are located.

> Of the 60 minute time interval, Oracle spent 8 minutes waiting on db
> file sequential read. Paraphrased from various sources: Caused by:
> I/O, SQL statement tuning, Poorly tuned SQL, Slow I/O system. A
> sequential read is a single-block read, where a user process is reading
> a buffer into the SGA buffer cache and waiting for a physical I/O.
> Single block I/Os are usually the result of index scans. Rarely, full
> table scans could get truncated to a single block call due to extent
> boundaries, or buffers already present in the buffer cache.

> After reading the above, ask yourself, is there a real problem with the
> performance of the database? And, if so, what is the cause of the
> performance problem?

> Charles Hooper
> PC Support Specialist
> K&M Machine-Fabricating, Inc.

My original response sent via email. Also posting this here so that my response to the OP may be reviewed by others for accuracy. The OP's database uses a single RAID 5 array:

The seemingly signifcant CPU time may simply be a result of Oracle serializing around a slow flushing of the redo to the log files - some activities cannot continue until Oracle knows that change records have been successfully recorded in the redo logs. RAID 5 is a very bad place for redo logs to be located. See http://www.baarf.com/

There are things that can contribute to this problem. * Too small of a buffer cache may contribute to this problem. Dirty blocks may remain in the buffer cache (this is normal behavior), but the dirty blocks may be forced out of the buffer cache by the next SQL statement that requires additional blocks to exist in the buffer cache. The new blocks cannot be read into the buffer cache until the online redo log file has been updated and the dirty blocks are written to the data files.
* Too small of redo logs may contribute to this problem. A checkpoint is performed every time a log file switch occurs. If the database is running in archive redo log mode, Oracle will try to copy the old redo log file to the archive location while still trying to write new redo entries to the next online redo log file. This increases the contention for the online redo log file. RAID 5 can service only one write request at a time, while RAID 10 can potentially service more than one write request at a time, if the stripe width is sufficiently large.
* Using write-through caching when the RAID controller includes a functioning battery backed cache may contribute to the problem. If the RAID controller has a battery backed cache, consider using write-back caching for writes, and no caching for reads. Write-back caching tells Oracle that the redo logs are updated as soon as the data hits the RAID controller's cache, rather than when the data is physically written to the disk system. This slightly increases the risk of data loss if the server encounters an extended power failure. * Having multiple redo logs in each redo log group, all written to the same RAID 5 array, may contribute to the problem. If this is the case, you are doubling or tripling the amount of work required to write redo entries with no, or very little, benefit of increased crash recovery. * Having too small of a redo log buffer may contribute to the problem. Try increasing the redo log buffer to 1MB to see if it helps. A value larger than 1MB typically has little benefit.

CPU utilization may decrease once the system is not serializing around the writing of redo entries.

Charles Hooper
PC Support Specialist
K&M Machine-Fabricating, Inc.

Received on Thu Dec 28 2006 - 11:44:52 CST