high load averages on box oracle consuming 100%

[Scunningham99]

Hi

We are experiencing problems on our prod 9.2.0.1 database. After instance re-boot, users have logged in and the load averages seem to be creaping up ever so slightly!, well now they have managed to creap up to 78.00.

Initially Users complained when load was at about 15.00 or so, but ever since then the load has creapt up, sometimes by the min. The system is not at peak usage hours and there doesnt seem to be mothing going on.

I have checked the obvious v$session_wait, and also for mass updates/deletes/inserts which there is nearly non.

SQLWKS> select sid, seq#, event, seconds_in_wait
2> from v$session_wait
3>
SID SEQ# EVENT SECONDS_IN
---------- ---------- ---------------------------------------------------------------- ----------
8 7181 null event 1
11 26568 null event 1
16 8866 null event 2
19 9666 null event 12
14 1705 null event 12
21 10369 null event 4
22 25616 null event 4
27 14810 null event 7
33 4624 null event 1
55 17935 null event 4
54 25660 null event 4
47 24545 null event 4
46 15890 null event 7
45 12902 null event 7
44 11890 null event 4
42 25249 null event 2
41 9292 null event 12
32 21565 null event 1
96 14228 null event 8
91 14778 null event 2
86 16984 null event 7
85 7471 null event 5
84 18718 null event 2
82 15420 null event 3
76 15148 null event 5
75 17161 null event 5
71 13 null event 0
128 13030 null event 4
127 14156 null event 12
125 16119 null event 3
122 14148 null event 4
121 15684 null event 3
120 15824 null event 12
116 17024 null event 5
114 19342 null event 1
113 18457 null event 8
159 971 null event 4
158 744 null event 5
156 221 null event 5
155 2026 null event 1
152 2156 null event 4
147 6535 null event 5
145 1176 null event 4
144 2751 null event 3
143 5463 null event 5
142 9812 null event 2
139 7843 null event 4
138 4786 null event 4
136 12588 null event 5
134 7634 null event 3
132 5322 null event 1
130 15032 null event 4
112 13320 null event 0
109 17935 null event 4
108 18509 null event 4
106 10779 null event 4
103 16807 null event 13
102 18580 null event 9
99 18861 null event 4
97 22453 null event 5
70 20808 null event 5
67 20758 null event 4
65 19601 null event 9
62 2246 null event 0
61 23672 null event 2
60 21560 null event 5
12 512 latch free 0
24 22691 latch free 0
98 16963 latch free 0
95 16629 latch free 0
94 15929 latch free 0
93 14001 latch free 0
90 22834 latch free 0
89 15606 latch free 0
88 18677 latch free 0
87 18668 latch free 0
80 17744 latch free 0
150 2111 latch free 0
149 282 latch free 0
141 5340 latch free 0
131 12724 latch free 0
126 13585 latch free 0
118 11492 latch free 0
115 15017 latch free 0
111 11583 latch free 0
110 16935 latch free 1
105 17842 latch free 0
104 23180 latch free 0
101 12214 latch free 0
66 16121 latch free 0
64 552 latch free 0
25 12018 latch free 0
37 13204 latch free 0
1 8915 pmon timer 0
2 7273 rdbms ipc message 1
3 7236 rdbms ipc message 1
4 16963 rdbms ipc message 0
10 1565 rdbms ipc message 205
9 2871 rdbms ipc message 37
7 92 rdbms ipc message 1183
5 8041 rdbms ipc message 2
146 51739 sbtwrite2 0
15 12985 log file sync 0
6 1378 smon timer 5
17 7 SQL*Net message from client 5655
34 16820 SQL*Net message from client 543
53 34645 SQL*Net message from client 14
52 20810 SQL*Net message from client 821
51 22523 SQL*Net message from client 470
50 21510 SQL*Net message from client 90
49 25901 SQL*Net message from client 537
48 15882 SQL*Net message from client 84
43 12366 SQL*Net message from client 895
40 25581 SQL*Net message from client 897
39 27 SQL*Net message from client 1428
38 29227 SQL*Net message from client 190
36 26704 SQL*Net message from client 531
35 70 SQL*Net message from client 3
162 82 SQL*Net message from client 25
148 6 SQL*Net message from client 2110
140 6562 SQL*Net message from client 271
135 12321 SQL*Net message from client 72
133 6788 SQL*Net message from client 897
129 1714 SQL*Net message from client 4
124 5728 SQL*Net message from client 543
123 4958 SQL*Net message from client 5280
119 2680 SQL*Net message from client 2189
100 10826 SQL*Net message from client 425
92 11003 SQL*Net message from client 75
83 101 SQL*Net message from client 9113
81 3881 SQL*Net message from client 5089
79 1697 SQL*Net message from client 7318
78 18644 SQL*Net message from client 117
77 24398 SQL*Net message from client 897
74 11531 SQL*Net message from client 571
73 12320 SQL*Net message from client 549
107 10537 SQL*Net message from client 100
72 59 SQL*Net message from client 9110
69 22833 SQL*Net message from client 122
68 11316 SQL*Net message from client 78
63 20972 SQL*Net message from client 314
59 21922 SQL*Net message from client 0
58 760 SQL*Net message from client 2
57 59905 SQL*Net message from client 90
56 23830 SQL*Net message from client 26
31 14044 SQL*Net message from client 0
23 11335 SQL*Net message from client 1345
28 17944 SQL*Net message from client 174
29 165 SQL*Net message from client 5198
30 26584 SQL*Net message from client 506
26 26589 SQL*Net message from client 897
20 17484 SQL*Net message from client 312
152 rows selected.
there sems to be alot of writing going on .. heres output from vxstat ( anything above 30 is a performance hit:-
U01 is where the database is:-

root@euratlsunx02#vxstat
OPERATIONS BLOCKS AVG TIME(ms)
TYP NAME READ WRITE READ WRITE READ WRITE
vol u01 107963991 2523146 2353546683 76361395 5.3 86.2
vol u01-L01 23214892 529769 471741436 14467938 5.3 83.9
vol u01-L02 23207983 737026 471525477 17886718 5.5 77.4
vol u01-L03 23184093 589676 471167953 15593794 5.4 78.2
vol u01-L04 23182940 489259 471147091 13971403 5.2 82.5
vol u01-L05 22985266 517332 467964726 14441542 5.4 73.6

the instance has not long been up a few hours:--
SQLWKS> select * from v$waitstat
2>
CLASS COUNT TIME
------------------ ---------- ----------
data block 5824 8642
sort block 0 0
save undo block 0 0
segment header 6 8
save undo header 0 0
free list 0 0
extent map 0 0
1st level bmb 0 0
2nd level bmb 0 0
3rd level bmb 0 0
bitmap block 0 0
bitmap index block 0 0
file header block 0 0
unused 0 0
system undo header 0 0
system undo block 0 0
undo header 9 150
undo block 5 0

I have also checked the filestat in oracle which doesnt really seem a great deal.

SQLWKS> select d.name, f.PHYRDS, f.PHYWRTS, f.MAXIOWTM
2> from v$datafile d, v$filestat f
3> where d.file# = f.file#
4> order by PHYWRTS desc
5>
NAME PHYRDS PHYWRTS MAXIOWTM
-------------------------------------------------------------------------------- ---------- ---------- ----------
/u01/oradata/AEULIVE/RBS.dbf 2933 17619 195
/u01/oradata/AEULIVE/PAUDIT02.dbf 335435 8986 209
/u01/oradata/AEULIVE/PAUDIT.dbf 214753 7980 195
/u01/oradata/AEULIVE/PAUDIT03.dbf 128400 4829 196
/u01/oradata/AEULIVE/PREMIND_LG.dbf 93967 3731 192
/u01/oradata/AEULIVE/system01.dbf 27527 2711 194
/u01/oradata/AEULIVE/PREMDAT.dbf 431564 2420 191
/u01/oradata/AEULIVE/PREMIND.dbf 12578 2035 197
/u01/oradata/AEULIVE/PREMIND_MED.dbf 11462 973 186
/u01/oradata/AEULIVE/PREMIND_XLG.dbf 3630 616 166
/u01/oradata/AEULIVE/undotbs01.dbf 127 420 164
/u01/oradata/AEULIVE/users01.dbf 78 43 81
/u01/oradata/AEULIVE/PREMIND_SM.dbf 243 8 198
/u01/oradata/AEULIVE/CCIDAT.dbf 19 7 7
/u01/oradata/AEULIVE/CCIIND.dbf 19 7 4
/u01/oradata/AEULIVE/drsys01.dbf 19 7 6
/u01/oradata/AEULIVE/SQLTIND.dbf 43 7 12
/u01/oradata/AEULIVE/logmnrts.dbf 19 7 9
/u01/oradata/AEULIVE/QUEST.ora 21 7 6
/u01/oradata/AEULIVE/SQLTDAT.dbf 104 7 5
/u01/oradata/AEULIVE/ORAFINDAT.dbf 19 7 5
/u01/oradata/AEULIVE/ORAFININD.dbf 19 7 5
22 rows selected.


Please can someone help or sched some light/ pointers as i am puzzled!!

Thanks in advance

SIMON



Sy UK

 

[Scunningham99]

Have checked filestats in oracle which dont seem to bad:-

SQLWKS> select d.name, f.PHYRDS, f.PHYWRTS, f.MAXIOWTM
2> from v$datafile d, v$filestat f
3> where d.file# = f.file#
4> order by PHYWRTS desc
5>
NAME PHYRDS PHYWRTS MAXIOWTM
-------------------------------------------------------------------------------- ---------- ---------- ----------
/u01/oradata/AEULIVE/RBS.dbf 2933 17619 195
/u01/oradata/AEULIVE/PAUDIT02.dbf 335435 8986 209
/u01/oradata/AEULIVE/PAUDIT.dbf 214753 7980 195
/u01/oradata/AEULIVE/PAUDIT03.dbf 128400 4829 196
/u01/oradata/AEULIVE/PREMIND_LG.dbf 93967 3731 192
/u01/oradata/AEULIVE/system01.dbf 27527 2711 194
/u01/oradata/AEULIVE/PREMDAT.dbf 431564 2420 191
/u01/oradata/AEULIVE/PREMIND.dbf 12578 2035 197
/u01/oradata/AEULIVE/PREMIND_MED.dbf 11462 973 186
/u01/oradata/AEULIVE/PREMIND_XLG.dbf 3630 616 166
/u01/oradata/AEULIVE/undotbs01.dbf 127 420 164
/u01/oradata/AEULIVE/users01.dbf 78 43 81
/u01/oradata/AEULIVE/PREMIND_SM.dbf 243 8 198
/u01/oradata/AEULIVE/CCIDAT.dbf 19 7 7
/u01/oradata/AEULIVE/CCIIND.dbf 19 7 4
/u01/oradata/AEULIVE/drsys01.dbf 19 7 6
/u01/oradata/AEULIVE/SQLTIND.dbf 43 7 12
/u01/oradata/AEULIVE/logmnrts.dbf 19 7 9
/u01/oradata/AEULIVE/QUEST.ora 21 7 6
/u01/oradata/AEULIVE/SQLTDAT.dbf 104 7 5
/u01/oradata/AEULIVE/ORAFINDAT.dbf 19 7 5
/u01/oradata/AEULIVE/ORAFININD.dbf 19 7 5
22 rows selected.


INstance has not been up long.. a few hours and there's not much overall waits..

SQLWKS> select * from v$waitstat
2>
CLASS COUNT TIME
------------------ ---------- ----------
data block 5824 8642
sort block 0 0
save undo block 0 0
segment header 6 8
save undo header 0 0
free list 0 0
extent map 0 0
1st level bmb 0 0
2nd level bmb 0 0
3rd level bmb 0 0
bitmap block 0 0
bitmap index block 0 0
file header block 0 0
unused 0 0
system undo header 0 0
system undo block 0 0
undo header 9 150
undo block 5 0

ANY HELP OF POINTERS WOULD BE GREATLY APPRECIATED!

Sy UK

 

[Scunningham99]

SORRY FORGOT TO INCLUDE, VXSTAT SHOWS HIGH WRITE WAITS, ON U01 (ANYTHING ABOVE 30 IS A PERFORMANE HIT):-

root@euratlsunx02#vxstat
OPERATIONS BLOCKS AVG TIME(ms)
TYP NAME READ WRITE READ WRITE READ WRITE
vol u01 108432218 2575237 2408597270 77956550 5.3 86.4
vol u01-L01 23378677 540846 482752654 14771146 5.3 84.1
vol u01-L02 23373643 751893 482565867 18254958 5.5 77.8
vol u01-L03 23348629 601564 482191057 15915533 5.4 78.4
vol u01-L04 23346409 499500 482151773 14266909 5.2 82.6
vol u01-L05 23146464 528095 478935919 14748004 5.4 73.6

THESE DONT SEEM TO TYE UP WITH ORACLE STATS AS NOT REALLY MUCH GOING ON IN ORACLE... HOW WEIRD!

Sy UK

 

[Scunningham99]

more info... cpu's is spending all or most of its time on user process with large run queue:-
root@euratlsunx02#vmstat 5 5
procs memory page disk faults cpu
r b w swap free re mf pi po fr de sr m1 m1 m1 m2 in sy cs us sy id
3 1 0 8713448 5046952 255 968 104 2 2 0 0 5 4 4 0 2158 4780 1458 46 5 50
82 2 0 8082368 4554072 102 539 0 0 0 0 0 0 0 0 0 2935 9582 2104 96 4 0
71 1 0 8082288 4553376 98 596 0 0 0 0 0 25 20 20 0 2652 9820 1965 96 4 0
76 2 0 8083384 4556104 70 337 0 0 0 0 0 0 0 0 0 2667 9633 1997 97 3 0
79 0 0 8084304 4555056 102 558 0 1 1 0 0 0 0 0 0 2825 9545 2001 97 3 0

root@euratlsunx02#psrinfo
0 on-line since 12/10/04 23:26:41
1 on-line since 12/10/04 23:26:41
2 on-line since 12/10/04 23:26:41
3 on-line since 12/10/04 23:26:26

there is also nothing aparent in messages file's

Sy UK

 

[Scunningham99]

problem resolved..... thanks anyway!

Ran the following:-


select * --a.sql_text, aa.name, b.sid, b.serial#, b.username, b.schemaname, b.osuser, b.machine
from v$sqlarea a, <-- THIS IS THE ONLY DIFFERENCE FROM ABOVE!
v$session b,
audit_actions aa
where a.address = b.SQL_address
and a.hash_value = b.sql_haSH_VALUE
and a.command_type = aa.action
AND B.USERNAME = 'WEB'

DEVELOPERS HAVE IMPLEMENTED A NEW PRODUCT WHICH WAS HAMERING THE SYSTEM WITH SELECT QUERIES OVER A DB LINK FROM UK TO USA. THESE QUERIES HAD AN EXTREMELLY HIGH CPU_TIME AND ELAPSED_TIME. THERE WAS 100+ OF THESE WHICH KILLED THE BOX.

I GUESS WE SHOULD SET UP CONSUMER GROUPS TO AVOID POTENTIAL FOR THIS IN THE FUTURE.



Sy UK

 

[KenCunningham]

Or sack the 'developers'!! Glad you tracked it down.

 

[Scunningham99]

alright Ken... Yeh I agree in Vegas (parent company) nornally in UK.. bad communication... if they would have informed my I would have known where to look.
Had a bit of a panic on 1000's of users complaining.. u know the one..

Found it eventually.. really strange... load average grept up in to the low hundreds.. normally only between 1.00 and 2.00.

I was baffled at first there was not much going on in session wait, it was hardly archiving so not much DML... they hey presto someone decided to mention WEB stuff!

Ive only been working on prod system's as big as this for 3 years, but i guess its all a larning curve!





Sy UK