Detektivarbeit mit Statspack
Verfasst von Tenebrias am 14.02.2008 - 17:12
Edit: Narv. Morgen mal gucken, wie man diese überbreiten Sachen ohne Informationsverlust in das Blog bekommt. Hier fehlt ja die Hälfte. -.-
Seit zwei Tagen rattert eine unsere Datenbanken wie irre, macht die CPU ihrer Zone vollständig dicht. Bis jetzt scheint zwar alles glatt zu laufen, denn vom Kunden kam noch keinerlei Beschwerde über Wartezeiten, aber ich schaue mir das dennoch mal an. Im GridControl sehe ich faktisch: Nichts.
Mhm. Die Sessions sehen allesamt völlig normal aus, aber dennoch drehen wir mit der CPU an der Obergrenze. Also werde ich mal einen Blick in den Statspack-Report werfen.
Und der kommt nicht zurück. Mhm. Da muss doch etwas blockieren. Ok…
SQL> select sid, event, wait_time, seconds_in_wait, state from v$session_wait where sid = 88;
SID EVENT WAIT_TIME SECONDS_IN_WAIT STATE
---------- ------------------------------ ---------- --------------- ---------------------------------------------------------
88 db file scattered read 0 0 WAITING
1 row selected.
Hum. Ein paarmal hintereinander zeigt mir: Der tut schon. Keine anderen Waits als db_file_scattered_read, der mir sagt: Da rutscht er mit Full-Table-Scans auf Tabellen rum.
Also eher IO als CPU. Aber warum wird der einfach nicht fertig?
Warten .. und dann ist der Lauf endlich fertig. Schauen wir mal
Load Profile
~~~~~~~~~~~~ Per Second Per Transaction
--------------- ---------------
Redo size: 43,273.30 5,539.68
Logical reads: 15,801.36 2,022.83
Block changes: 310.33 39.73
Physical reads: 14.00 1.79
Physical writes: 9.94 1.27
User calls: 1,331.36 170.43
Parses: 526.48 67.40
Hard parses: 97.84 12.53
Sorts: 146.20 18.72
Logons: 0.14 0.02
Executes: 1,871.40 239.57
Transactions: 7.81
Wir haben also 1871 Statements, die pro Sekunde ausgeführt werden, 526 Parses und 97 Hardparses. Das sieht schonmal nicht gut aus, aber letztlich sind das immer Werte zum Vergleichen. Eine Woche zurückgeschaut finde ich: 1918 Statements, 542 Parses und 95 Hardparses.
Faktischer Unterschied also Null.
Gucken wir also mal weiter.
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Buffer Nowait %: 100.00 Redo NoWait %: 100.00
Buffer Hit %: 99.91 In-memory Sort %: 100.00
Library Hit %: 95.03 Soft Parse %: 81.42
Execute to Parse %: 71.87 Latch Hit %: 99.92
Parse CPU to Parse Elapsd %: 26.50 % Non-Parse CPU: 73.06
Sieht soweit gut aus und unterscheidet sich nur an einem Punkt wesentlich zur Woche vorher: Parse CPU to Parse Elapsd war da bei 54%. Das lasse ich für den Moment aber mal zur Seite und schaue weiter.
Top 5 Timed Events
~~~~~~~~~~~~~~~~~~ % Total
Event Waits Time (s) Ela Time
-------------------------------------------- ------------ ----------- --------
log file sync 524,599 77,394 32.91
CPU time 39,471 16.78
enqueue 89,730 39,021 16.59
log file parallel write 1,168,951 20,537 8.73
latch free 1,826,071 19,317 8.21
-------------------------------------------------------------
Das sieht doch schonmal Scheisse aus. 32% Waits auf log_file_sync – normalerweise sollte das auf einen zu großen log_buffer hindeuten, wäre er zu klein würden wir log_buffer_space-Waits bekommen. Mal schauen
SQL> show parameter log_buffer NAME TYPE VALUE ------------------------------------ --------------------------------- ------------------------------ log_buffer integer 2097152 SQL>
2 MB kann man nicht als Welt bezeichnen, allerdings hatten wir den erst am 31.01.2008 von 500K hochgedreht. Das war möglicherweise ein Stück zu viel.
Ich behalte das mal im Kopf und schaue weiter.
Die Wait-Events sehen entsprechend auch richtig schlecht aus. Die Waits für log_file_sync waren vor einer Woche bei 17, für db_file_parallel_write immerhin bei 97 und die buffer_busy_waits bei 19.
Avg
Total Wait wait Waits
Event Waits Timeouts Time (s) (ms) /txn
---------------------------- ------------ ---------- ---------- ------ --------
log file sync 524,599 40,688 77,394 148 0.8
enqueue 89,730 7,729 39,021 435 0.1
log file parallel write 1,168,951 0 20,537 18 1.7
latch free 1,826,071 59,743 19,317 11 2.7
buffer busy waits 40,075 11,103 16,423 410 0.1
db file sequential read 334,602 0 9,963 30 0.5
db file parallel write 26,831 0 7,271 271 0.0
Na schön. Mal noch gucken, was die Platten generell so machen
------------------------------
Av Av Av Av Buffer Av Buf
Reads Reads/s Rd(ms) Blks/Rd Writes Writes/s Waits Wt(ms)
-------------- ------- ------ ------- ------------ -------- ---------- ------
LAM_INDEX
306,564 4 30.6 1.4 533,907 6 19,935 180.5
UNDOTBS1
89 0 23.7 1.0 217,187 3 18,923 674.7
QIP_INDEX
14,995 0 30.1 1.5 46,062 1 49 920.2
LAM_DATA
28,523 0 14.0 20.6 22,017 0 1,097 339.0
QIP_DATA
2,632 0 26.3 8.3 23,207 0 60 601.7
PERFSTAT
8,514 0 43.3 16.4 3,287 0 0 0.0
SYSTEM
2,666 0 29.9 2.2 633 0 12 848.3
UGH?
Mal ganz davon abgesehen, dass die Zugriffsgeschwindigkeit beim lesen vor einer Woche nahezu doppelt so hoch war, sind die Avg Bufferwaits ja wohl die Hölle. 920 ms?
Vor einer Woche waren wir bei 39, was auch nicht toll, aber noch im Rahmen ist.
Was mach ich damit nun?
Spontan würde ich mit einem kleineren log_buffer und mehr buffercache ansetzen, auch wenn die HitRatio von 99,91 mehr als optimal ist.
Morgen muss ich das noch ein wenig genauer anschauen.
