| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> RE: CPU Pegged at 100%
is all the sessions waiting on latch free waits
-----Original Message-----
Sent: Friday, April 26, 2002 3:44 PM
To: Multiple recipients of list ORACLE-L
All users waiting for latch "cache buffer chains"
-----Original Message-----
Sent: Friday, April 26, 2002 11:59 AM
To: Multiple recipients of list ORACLE-L
>From the statspack report it shows that u have lots of latchfree waits which
is event timing out
can u see in the session_Wait which is the user and what latch he is waiting
on
-----Original Message-----
Sent: Friday, April 26, 2002 2:24 PM
To: Multiple recipients of list ORACLE-L
Hi,
I have a customer who runs an ERP application written using
ORACLE. Almost all code is written using PL/SQL packages. There are about
80-100 users
at any given point of time(6 AM - 11 PM). Oracle version is 8.1.7.1.1
Standard Edition.
All the four CPU's on their server is pegged at 100% for most of the time.
This is resulting
in end users complaning about slow performance and slower log-ons to the
application.
This issue has been occuring consistently for over 2-3 weeks now. Archive
logging is enabled
and the database is normally shutdown once a week for cold backup.
The Admin guys have been monitoring the server using Performance monitor and
find that Oracle.exe is the process consuming 99% of the resource. Memory
usage is
constant and there is plenty of it free. Hard disk drives show no activity.
A normal
assumption would be that disk drives would be going crazy with all
the CPU activity going on, but that does not seem to be the case.
Oracle software and one PRODuction database exist on this server.
Their Server configuration consists of:
Windows 2000 OS (Advanced Server), with 4 Pentium III Xeon processors (each
700 Mhz),
4 Gb RAM and 2 disk drives on seperate disk controllers. Hard drives are of
15,000 RPM's.
MY APPROACH SO FAR:
Step 1:
I started looking into this issue since last week and the first area I
concentrated
was on finding SQL statements that were taking too many hits or taking too
long to complete.
I was able to tune almost 10 of the top SQL statements last week. In most of
the previous performance
issues I have been involved with this has resulted in huge performance gains
and life went on.
In this situation, tuning these top 10 SQL's did result in small gains, but
did not make
any difference to the CPU contention. They still continued to be pegged at
100% most of the times.
Step 2:
The next step I took was to find out if there were hard parsing going on. As
mentioned in a number
of articles here, this would cause the CPU to work extra harder.
My check resulted in only 2 SQL statement that were hard parsed.
Based on the fact that there are a number of very big jobs, user queries
and other activities that go on a daily basis, should I really worry about
it ?
Step 3:
Next step was to increase the number of rollback segments from 5 to 35.
Previously, there
were 5 big rollback segments. Now, there are 35 medium sized rollback
segments spread over
2 rollback tablespaces. This step was taken yesterday and so far there has
been no improvement
as far as CPU pegging goes. It is still pegged at 100%
Step 4:
Certain articles in Metalink suggested that one of the reasons
that would make the CPU spin continously would be SMON working overtime
to clean up a large number of temporary extents, or to coalesce a large
number of free extents.
This can manifest itself by SMON appearing to spin, consuming a high
percentage of CPU for
long periods. I really dont know how to test this statement. PCT_INCREASE is
set to 0 for
all the tablespaces except SYSTEM and one ROLLBACK tablespace.
I will re-set PCT_INCREASE to 0 for the second ROLLBACK tablespace also.
Apart from this I
really dont know what else I can look for. My temporary tablespace is around
3 GB.
Is there a SQL statement that I can run and find out if there is a problem
with SMON?
Step 5:
The final step was to run Statspack on this instance for about 25 minutes.
I have copied extracts from some of the data that would be of interest.
Hard parses and the Top 5 waits seem to be the issue atleast in this report.
Could some one share some of your experience in the area of tuning these
wait events
and what you would recomend me to do next. My CPU is still pegged at 100%.
STATSPACK report for
DB Name DB Id Instance Inst Num Release OPS Host ------------ ----------- ------------ -------- ----------- --- ------------
PROD 3888465932 prod 1 8.1.7.1.1 NO ERP1
Snap Id Snap Time Sessions
------- ------------------ --------
Begin Snap: 31 26-Apr-02 09:21:38 169
End Snap: 41 26-Apr-02 09:46:03 169
Elapsed: 24.42 (mins)
Cache Sizes
db_block_buffers: 131072 log_buffer: 163840
db_block_size: 8192 shared_pool_size: 314572800
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 9,606.78 2,352.32
Logical reads: 5,806.11 1,421.69
Block changes: 59.60 14.59
Physical reads: 62.26 15.24
Physical writes: 8.04 1.97
User calls: 45.08 11.04
Parses: 41.91 10.26
Hard parses: 1.65 0.40
Sorts: 31.24 7.65
Logons: 6.69 1.64
Executes: 751.70 184.06
Transactions: 4.08
% Blocks changed per Read: 1.03 Recursive Call %: 98.11
Rollback per transaction %: 0.40 Rows per Sort: 12.31
Instance Efficiency Percentages (Target 100%)
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 98.93 In-memory Sort %: 99.96
Library Hit %: 99.81 Soft Parse %: 96.06
Execute to Parse %: 94.42 Latch Hit %: 99.53
Parse CPU to Parse Elapsd %: 66.72 % Non-Parse CPU: 100.00
Shared Pool Statistics Begin End
------ ------
Memory Usage %: 73.87 74.79
% SQL with executions>1: 83.50 78.94
% Memory for SQL w/exec>1: 91.68 89.19
Top 5 Wait Events
~~~~~~~~~~~~~~~~~ Wait % Total Event Waits Time (cs) WtTime
-------------------------------------------- ------------ ------------
-------
latch free 40,846 23,727
43.38
log file sync 5,928 11,155
20.39
db file sequential read 7,137 6,486
11.86
db file scattered read 4,979 5,123
9.37
db file parallel write 559 3,592
6.57
-------------------------------------------------------------
Wait Events for DB: PROD Instance: prod Snaps: 31 -41
-> cs - centisecond - 100th of a second
-> ms - millisecond - 1000th of a second
-> ordered by wait time desc, waits desc (idle events last)
Avg
Total Wait wait
Waits
Event Waits Timeouts Time (cs) (ms)
/txn
---------------------------- ------------ ---------- ----------- ------
------
latch free 40,846 29,097 23,727 6
6.8
log file sync 5,928 0 11,155 19
1.0
db file sequential read 7,137 0 6,486 9
1.2
db file scattered read 4,979 0 5,123 10
0.8
db file parallel write 559 0 3,592 64
0.1
log file parallel write 5,922 0 1,574 3
1.0
direct path write 780 0 1,472 19
0.1
direct path read 360 0 725 20
0.1
SQL*Net more data to client 4,301 0 316 1
0.7
buffer busy waits 331 0 240 7
0.1
control file parallel write 489 0 95 2
0.1
log file sequential read 258 0 59 2
0.0
SQL*Net break/reset to clien 98 0 54 6
0.0
control file sequential read 64 0 39 6
0.0
log file switch completion 1 0 19 190
0.0
file open 121 0 9 1
0.0
refresh controlfile command 6 0 6 10
0.0
file identify 5 0 4 8
0.0
enqueue 62 0 2 0
0.0
LGWR wait for redo copy 13 0 1 1
0.0
log file single write 2 0 1 5
0.0
SQL*Net message from client 40,023 0 15,565,837 3889
6.7
SQL*Net more data from clien 1,782 0 3,385 19
0.3
SQL*Net message to client 40,029 0 10 0
6.7
-------------------------------------------------------------
Background Wait Events for DB: PROD Instance: prod Snaps: 31 -41
-> ordered by wait time desc, waits desc (idle events last)
Avg
Total Wait wait
Waits
Event Waits Timeouts Time (cs) (ms)
/txn
---------------------------- ------------ ---------- ----------- ------
------
db file parallel write 559 0 3,592 64
0.1
log file parallel write 5,922 0 1,575 3
1.0
db file scattered read 18 0 96 53
0.0
control file parallel write 489 0 95 2
0.1
log file sequential read 258 0 59 2
0.0
direct path read 16 0 41 26
0.0
db file sequential read 12 0 36 30
0.0
control file sequential read 44 0 34 8
0.0
file identify 5 0 4 8
0.0
direct path write 16 0 2 1
0.0
file open 53 0 1 0
0.0
LGWR wait for redo copy 13 0 1 1
0.0
log file single write 2 0 1 5
0.0
rdbms ipc message 11,667 1,373 734,101 629
2.0
smon timer 5 5 153,604 ######
0.0
pmon timer 484 471 146,444 3026
0.1
-------------------------------------------------------------
Tablespace IO Stats for DB: PROD Instance: prod Snaps: 31 -41 ->ordered by IOs (Reads + Writes) desc
Tablespace
Av Av Av Av Buffer Av
Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits
Wt(ms)
Tablespace Filename
Av Av Av Av Buffer Av
Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits
Wt(ms)
ARCH_IND C:\ORACLE\ORADATA\PROD\ARCIND01PROD.DBF
1 0 0.0 1.0 1 0 0
ARCH_TAB C:\ORACLE\ORADATA\PROD\ARCTAB01PROD.DBF
1 0 0.0 1.0 1 0 0
IAL_DATA C:\ORACLE\ORADATA\PROD\IALDATA01PROD.DBF
1 0 0.0 1.0 1 0 0
IAL_INDEX C:\ORACLE\ORADATA\PROD\IALINDEX01PROD.DBF
1 0 0.0 1.0 1 0 0
INDEXES E:\ORACLE\ORADATA\PROD\INDEXES01PROD.DBF
1,309 1 7.7 1.0 1,126 1 0
E:\ORACLE\ORADATA\PROD\INDEXES02PROD.DBF
929 1 12.4 1.0 1,481 1 0
REPORTS C:\ORACLE\ORADATA\PROD\REPORTS01PROD.DBF
1,736 1 8.0 27.7 65 0 0
ROLLBACK C:\ORACLE\ORADATA\PROD\RBS01PROD.DBF
1 0 0.0 1.0 1,412 1 18
2.8
ROLLBACK2 E:\ORACLE\ORADATA\PRODRBS201PROD.DBF
1 0 0.0 1.0 1,054 1 25
7.2
SYSTEM C:\ORACLE\ORADATA\PROD\SYSTEM01PROD.DBF
180 0 17.8 1.7 196 0 291
7.5
TABLES C:\ORACLE\ORADATA\PROD\TABLES01PROD.DBF
6,006 4 9.0 5.0 640 0 0
C:\ORACLE\ORADATA\PROD\TABLES02PROD.DBF
1,799 1 11.5 4.9 439 0 0
C:\ORACLE\ORADATA\PROD\TABLES03PROD.DBF
166 0 16.0 1.3 919 1 0
TEMP E:\ORACLE\ORADATA\PROD\TEMP01PROD.DBF
467 0 0.0 3.5 1,717 1 0
TOOLS C:\ORACLE\ORADATA\PROD\TOOLS01PROD.DBF
1 0 0.0 1.0 1 0 0
USERS C:\ORACLE\ORADATA\PROD\USERS01PROD.DBF
1 0 0.0 1.0 1 0 0
-------------------------------------------------------------
Buffer Pool Statistics for DB: PROD Instance: prod Snaps: 31 -41
-> Pools D: default pool, K: keep pool, R: recycle pool
Free Write
Buffer
Buffer Consistent Physical Physical Buffer Complete
Busy
P Gets Gets Reads Writes Waits Waits
Waits
Buffer wait Statistics for DB: PROD Instance: prod Snaps: 31 -41 -> ordered by wait time desc, waits desc
Tot Wait Avg
Class Waits Time (cs) Time (cs)
------------------ ----------- ---------- ---------
data block 288 217 1
undo block 31 23 1
undo header 12 0 0
-------------------------------------------------------------
Latch Activity for DB: PROD Instance: prod Snaps: 31 -41
->"Get Requests", "Pct Get Miss" and "Avg Slps/Miss" are statistics for
willing-to-wait latch get requests
->"NoWait Requests", "Pct NoWait Miss" are for no-wait latch get requests
->"Pct Misses" for both should be very close to 0.0
Pct Avg
Pct
Get Get Slps NoWait
NoWait
Latch Name Requests Miss /Miss Requests
Miss
----------------------------- -------------- ------ ------ ------------
------
Token Manager 100 0.0 865
0.0
active checkpoint queue latch 1,034 0.0 0
archive control 2 0.0 0
archive process latch 2 0.0 0
cache buffer handles 5,746 0.0 0
cache buffers chains 13,651,872 0.2 0.3 175,126
0.0
cache buffers lru chain 227,524 0.0 0.0 93,360
0.0
channel handle pool latch 78 0.0 75
0.0
channel operations parent lat 156 0.0 75
0.0
checkpoint queue latch 26,413 0.0 0.0 0
dml lock allocation 30,592 0.0 0.0 0
enqueue hash chains 76,995 0.1 0.0 0
enqueues 126,629 0.0 0.0 0
event group latch 78 0.0 0
job_queue_processes parameter 29 0.0 0
ktm global data 5 0.0 0
latch wait list 25,992 2.6 0.0 25,458
0.1
library cache 11,816,196 0.8 0.3 7,389
3.9
library cache load lock 3,562 0.0 0
list of block allocation 15,785 0.0 0
loader state object freelist 48 0.0 0
longop free list 24 0.0 0
messages 43,113 0.1 0.0 0
multiblock read objects 14,194 0.0 2
0.0
ncodef allocation latch 29 0.0 0
process allocation 78 0.0 78
0.0
process group creation 153 0.0 0
redo allocation 56,319 0.0 0.0 0
redo writing 31,295 0.1 0.1 0
row cache objects 2,109,497 0.7 0.0 1,807
1.2
sequence cache 4,521 0.0 0
session allocation 254,745 0.3 0.9 0
session idle bit 156,902 0.0 0.0 0
session switching 29 0.0 0
shared pool 730,592 0.2 0.7 0
sort extent pool 626 0.0 0
transaction allocation 23,864 0.0 0.0 0
transaction branch allocation 29 0.0 0
undo global data 28,240 0.0 0.0 0
user lock 2,466 0.0 0
-------------------------------------------------------------
Latch Sleep breakdown for DB: PROD Instance: prod Snaps: 31 -41
-> ordered by misses desc
Get Spin &
Latch Name Requests Misses Sleeps Sleeps
1->4
-------------------------- -------------- ----------- -----------
------------
library cache 11,816,196 99,185 33,165
75514/15759/
6572/1340/0
cache buffers chains 13,651,872 21,801 6,025
16002/5580/2
12/7/0
row cache objects 2,109,497 15,580 22
15563/13/3/1
/0
shared pool 730,592 1,547 1,023
1011/214/184
/138/0
session allocation 254,745 669 576
215/334/118/
2/0
latch wait list 25,992 666 2
664/2/0/0/0
enqueue hash chains 76,995 42 2 40/2/0/0/0
redo writing 31,295 21 2 19/2/0/0/0
-------------------------------------------------------------
Latch Miss Sources for DB: PROD Instance: prod Snaps: 31 -41
-> only latches with sleeps are shown
NoWait
Waiter
Latch Name Where Misses Sleeps
Sleeps
------------------------ -------------------------- ------- ----------
-------
cache buffers chains kcbrls: kslbegin 0 5,308
1,183
cache buffers chains kcbgtcr: kslbegin 0 542
4,558
cache buffers chains kcbgcur: kslbegin 0 93
77
cache buffers chains kcbnlc 0 38
29
cache buffers chains kcbchg: kslbegin: bufs not 0 29
116
cache buffers chains kcbchg: kslbegin: call CR 0 8
43
cache buffers chains kcbzwb 0 5
4
enqueue hash chains ksqgtl3 0 2
1
latch wait list kslfre 9 2
2
library cache kglpnal: child: alloc spac 0 9,080
1,703
library cache kglpnal: child: before pro 0 7,673
2,840
library cache kglhdgn: child: 0 3,714
2,445
library cache kglpin 0 3,367
4,698
library cache kglget: child: KGLDSBYD 0 3,350
3,705
library cache kglpnc: child 0 1,648
6,515
library cache kgllkdl: child: cleanup 0 1,350
1,763
library cache kglget: child: KGLDSBRD 0 411
60
library cache kglhdgc: child: 0 400
256
library cache kglupc: child 0 353
6,335
library cache kglic 0 164
37
library cache kgldti: 2child 0 88
206
library cache kglpnp: child 0 88
1,424
library cache kgllkdl: child: free pin 0 48
756
library cache kglobpn: child: 0 10
67
library cache kglrtl 0 9
8
library cache kglati 0 2
6
library cache kgldtld: 2child 0 2
15
redo writing kcrfsr 0 2
0
row cache objects kqrpre: find obj 0 14
22
row cache objects kqreqd: rel enqueue 0 6
0
row cache objects kqreqd 0 2
0
session allocation ksuxds: KSUSFCLC not set 0 571
321
session allocation ksucri 0 5
170
shared pool kghfrunp: clatch: nowait 0 1,327
0
shared pool kghfrunp: alloc: clatch no 0 798
0
shared pool kghfrunp: clatch: wait 0 77
179
shared pool kghfre 0 72
180
shared pool kghalo 0 66
98
shared pool kghfrunp: alloc: wait 0 39
10
shared pool kghfnd: min scan 0 23
0
shared pool kghupr1 0 16
726
shared pool kghfnd: get next extent 0 3
0
shared pool kghalp 0 2
7
shared pool kghfen: not perm alloc cla 0 2
2
shared pool kghfnd: req scan 0 2
0
-------------------------------------------------------------
Dictionary Cache Stats for DB: PROD Instance: prod Snaps: 31 -41
->"Pct Misses" should be very low (< 2% in most cases)
->"Cache Usage" is the number of cache entries being used
->"Pct SGA" is the ratio of usage to allocated size for that cache
Get Pct Scan Pct Mod Final
Pct
Cache Requests Miss Requests Miss Req Usage
SGA
---------------------- ------------ ------ -------- ----- -------- ------
----
dc_constraints 0 0 0 19
95
dc_database_links 0 0 0 0
0
dc_files 0 0 0 9
90
dc_free_extents 89 2.2 4 0.0 4 12
92
dc_global_oids 0 0 0 0
0
dc_histogram_data 0 0 0 0
0
dc_histogram_data_valu 0 0 0 0
0
dc_histogram_defs 13,280 3.1 0 0 461
98
dc_object_ids 15,375 1.5 0 0 431
100
dc_objects 399,318 0.2 0 0 634
99
dc_outlines 0 0 0 0
0
dc_profiles 1,254 0.0 0 0 2
33
dc_rollback_segments 360 0.0 0 0 37
97
dc_segments 11,200 3.2 0 2 403
96
dc_sequence_grants 0 0 0 0
0
dc_sequences 1,728 0.1 0 1,711 28
97
dc_synonyms 22,494 0.1 0 0 17
74
dc_tablespace_quotas 4 25.0 0 1 1
50
dc_tablespaces 164 0.0 0 0 6
86
dc_used_extents 2 100.0 0 2 22
96
dc_user_grants 714 3.1 0 0 39
98
dc_usernames 42,550 0.1 0 0 60
76
dc_users 195,137 0.0 0 0 57
83
ifs_acl_cache_entries 0 0 0 0
0
-------------------------------------------------------------
Library Cache Activity for DB: PROD Instance: prod Snaps: 31 -41 ->"Pct Misses" should be very low
Get Pct Pin Pct
Invali-
Namespace Requests Miss Requests Miss Reloads
dations
BODY 18,433 0.1 15,316 0.6 78
0
CLUSTER 33 0.0 52 0.0 0
0
INDEX 0 0 0
0
OBJECT 0 0 0
0
PIPE 0 0 0
0
SQL AREA 50,725 3.5 1,458,283 0.3 868
1
TABLE/PROCEDURE 466,088 0.1 1,418,995 0.1 949
0
TRIGGER 38 0.0 38 2.6 1
0
-------------------------------------------------------------
SGA Memory Summary for DB: PROD Instance: prod Snaps: 31 -41
SGA regions Size in Bytes
------------------------------ ----------------
Database Buffers 1,073,741,824
Fixed Size 75,804
Redo Buffers 172,032
Variable Size 358,588,416
----------------
sum 1,432,578,076
-------------------------------------------------------------
SGA breakdown difference for DB: PROD Instance: prod Snaps: 31 -41
Pool Name Begin value End valueDifference
----------- ------------------------ -------------- --------------
-----------
java pool free memory 20,000,768 20,000,768
0
shared pool DML locks 480,000 480,000
0
shared pool KGFF heap 11,768 11,768
0
shared pool KGK heap 2,028 2,028
0
shared pool KQLS heap 2,874,304 3,057,788
183,484
shared pool PL/SQL DIANA 5,501,492 5,489,688
-11,804
shared pool PL/SQL MPCODE 18,309,204 17,349,528
-959,676
shared pool PLS non-lib hp 2,096 2,096
0
shared pool SYSTEM PARAMETERS 63,536 63,536
0
shared pool State objects 355,984 355,984
0
shared pool branches 96,240 96,240
0
shared pool character set object 43,892 43,892
0
shared pool db_block_buffers 17,825,792 17,825,792
0
shared pool db_block_hash_buckets 2,228,248 2,228,248
0
shared pool db_handles 150,000 150,000
0
shared pool dictionary cache 1,539,524 912,252
-627,272
shared pool enqueue_resources 293,040 293,040
0
shared pool event statistics per ses 1,152,400 1,152,400
0
shared pool fixed allocation callbac 964 964
0
shared pool free memory 88,469,492 85,339,500
-3,129,992
shared pool ktlbk state objects 171,200 171,200
0
shared pool library cache 43,032,076 44,494,836
1,462,760
shared pool long op statistics array 110,000 110,000
0
shared pool message pool freequeue 124,552 124,552
0
shared pool messages 52,800 52,800
0
shared pool miscellaneous 1,204,540 1,214,988
10,448
shared pool processes 242,400 242,400
0
shared pool sessions 722,260 722,260
0
shared pool sql area 152,405,144 155,450,648
3,045,504
shared pool state objects 649,360 674,560
25,200
shared pool table columns 16,632 17,460
828
shared pool table definiti 3,008 3,648
640
shared pool transaction_branches 73,600 73,600
0
shared pool transactions 356,800 356,800
0
shared pool trigger defini 3,240 3,240
0
shared pool trigger inform 660 540
-120
db_block_buffers 1,073,741,824 1,073,741,824
0
fixed_sga 75,804 75,804
0
log_buffer 163,840 163,840
0
-------------------------------------------------------------
Thanks,
Raghu
-- Please see the official ORACLE-L FAQ: http://www.orafaq.com -- Author: Arun Chakrapani INET: ArunC_at_1800FLOWERS.com Fat City Network Services -- (858) 538-5051 FAX: (858) 538-5051 San Diego, California -- Public Internet access / Mailing Lists -------------------------------------------------------------------- To REMOVE yourself from this mailing list, send an E-Mail message to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in the message BODY, include a line containing: UNSUB ORACLE-L (or the name of mailing list you want to be removed from). You may also send the HELP command for other information (like subscribing).Received on Fri Apr 26 2002 - 15:25:41 CDT
 |
 |