Das Wait Event Tuning hat sich in den letzten Jahren als

Das Wait Event Tuning hat sich in den letzten Jahren als gegenüber dem
althergebrachten Ratio Tuning als klar überlegen, präziser und effizienter
herausgestellt.
Eine der Kernkompetenzen beim Einsatz von Wait Event Tuning ist die
Fähigkeit extended SQL-Trace Dateien auszuwerten, maschinell ein
Antwortzeitprofil zu erstellen und daraus die notwendigen
Optimierungsmassnahmen abzuleiten.
Der Beitrag erläutert die Prinzipien des Wait Event Tuning, den Aufbau
von extended SQL-Trace Dateien, die Ableitung performance-relevanter
Kenngrößen wie z.B. Antwortzeit, CPU-Verbrauch (Parse/Execute/Fetch),
Wartezeit, Klassifizierung der Latenzzeiten (Think Time) und die
Ableitung der notwendigen Massnahmen zur Performanceoptimierung.
Die maschinelle Auswertung von extended SQL-Trace Dateien mit der
Programmiersprache Perl wird besprochen und in einer Demonstration
gezeigt.
Wait Event Tuning
Antwortzeitprofilerstellung mit Extended
SQL-Trace
Norbert Debes
Diplom-Informatiker (Univ.)
Oracle Certified Professional DBA
[email protected]
Donald K. Burleson
●
Zitate aus dem Artikel "Busting the Oracle Myth
Busters"
–
–
–
–
–
"... there are virtually NO concrete rules for Oracle tuning
..."
"Even today, Oracle tuning remains very much an art
form ..."
"During the late 1990s, a small movement arose among
Oracle professionals who advocated the analysis of
10046 trace dumps [...] The dumps generate a huge hex
dump which reveals all Oracle wait events [...]"
"... Oracle10g Active Session History [ ... makes ... ] the
10046 dump largely obsolete."
"Everything depends on something else and Oracle
tuning will always remain more of an art form than a
science"
Definition
Wait Event Tuning ist ein Optimierungsverfahren für
die Leistungssteigerung von Anwendungen mit der
Zielsetzung aus einer präzisen Messung des
Anwendungsverhaltens ein Antwortzeitprofil zu
erstellen und aus diesem Profil Massnahmen für eine
höchstmögliche Leistungssteigerung abzuleiten,
umzusetzen und durch erneute Messung zu verifizieren.
Das Verfahren
Untersuchungsobjekt
auswählen
Messen
Antwortzeitprofil
berechnen
Performancediagnose
Verbesserungspotential
berechnen
Massnahmen
auswählen
Massnahmen
durchführen
Messung
●
extended SQL Trace
–
–
–
–
Datenbankoperationen (Stufe 1)
● PARSE, EXEC, FETCH, XCTEND
Warteereignisse (Stufe 8)
● WAIT
Werte von Platzhaltern (Stufen 4 und 12)
● BIND
Messdaten
● CPU-Verbrauch, Zeitdauer, Plattenzugriffe, Buffer
Cache Zugriffe, Latch Misses, etc.
Durchführung der Messung
●
●
●
●
●
●
ALTER SESSION SET EVENTS '10046 trace name
context forever, level 8';
DBMS_SYSTEM.SET_EV
DBMS_SUPPORT.START_TRACE_IN_SESSION
(dbmssupp.sql)
DBMS_MONITOR.SESSION_TRACE_ENABLE
(10g)
oradebug event
Empfehlung: LOGON/LOGOFF Trigger & ALTER
SESSION (alternativ: Session Level Statspack)
–
–
–
misst gesamte Sitzung und ist proaktiv einsetzbar
vermeidet Problem der fehlenden SQL-Anweisungstexte
bei nachträglichem Einschalten (Abhilfe: errorstack dump)
kann beim LOGOFF zusätzlich Werte aus V$ Views in die
Protokolldatei schreiben
Protokolldatei
PARSING IN CURSOR #6 len=129 dep=2 uid=0 oct=6 lid=0 tim=637105797174 ...
update seq$ set increment$=:2,minvalue=:3 ... where obj#=:1
END OF STMT
PARSE #6:c=10015,e=85,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,tim=637105797165
EXEC #6:c=0,e=359,p=0,cr=1,cu=2,mis=0,r=1,dep=2,og=4,tim=637105797706
STAT #6 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE '
STAT #6 id=2 cnt=1 pid=1 pos=1 obj=107 op='INDEX UNIQUE SCAN I_SEQ1 '
FETCH #4:c=10015,e=1830,p=0,cr=6,cu=3,mis=0,r=1,dep=1,og=4,tim=637105798114
WAIT #3: nam='db file sequential read' ela= 43401 p1=3 p2=13834 p3=1
WAIT #3: nam='db file sequential read' ela= 390 p1=3 p2=13842 p3=1
WAIT #3: nam='db file sequential read' ela= 11223 p1=3 p2=13850 p3=1
WAIT #3: nam='SQL*Net message to client' ela= 9 p1=1111838976 p2=1 p3=0
EXEC #3:c=20029,e=181918,p=3,cr=17,cu=9,mis=0,r=1,dep=0,og=4,tim=637105899398
*** 2005-08-15 00:24:56.503
WAIT #3: nam='SQL*Net message from client' ela= 12518228 p1=1111838976 p2=1
p3=0
PARSING IN CURSOR #5 len=85 dep=0 uid=79 oct=3 lid=79 tim=637118433031
hv=156408865 ad='7ae95d94'
SELECT produktid, hostname, produkttyp, produkt, standort FROM log_quellen
END OF STMT
PARSE #5:c=0,e=14995,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=637118433018
WAIT #5: nam='SQL*Net message to client' ela= 7 p1=1111838976 p2=1 p3=0
WAIT #5: nam='SQL*Net message from client' ela= 1351 p1=1111838976 p2=1 p3=0
EXEC #5:c=0,e=99,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=637118434912
WAIT #5: nam='SQL*Net message to client' ela= 5 p1=1111838976 p2=1 p3=0
FETCH #5:c=0,e=171,p=0,cr=3,cu=0,mis=0,r=3,dep=0,og=4,tim=637118435125
WAIT #5: nam='SQL*Net message from client' ela= 4859437 p1=1111838976 p2=1
p3=0
XCTEND rlbk=0, rd_only=0
PARSING IN CURSOR, XCTEND
●
PARSING IN CURSOR
–
–
–
●
Text einer SQL-Anweisung
#n: Cursor Nummer
hv: Hash Value entspricht V$SQL.HASH_VALUE
XCTEND
–
–
–
COMMIT oder ROLLBACK
rlbk=[0,1]: 0=commit, 1=rollback
rd_only=[0,1]: 0=Transaktion bestand, 1: keine
Transaktion begonnen
PARSE, EXEC, FETCH
●
●
●
●
●
●
●
●
●
●
●
#n: Cursor Nummer
c: CPU-Verbrauch ab 9i in Mikrosekunden
e: Dauer (elapsed time) ab 9i in Mikrosekunden
p: Plattenzugriffe (physical reads)
cr: Consistent Reads
cu: Current Reads
mis: Cursor Misses
r: verarbeitete Zeilen (rows)
dep: Rekursionsebene (dep=0 summiert dep>0)
og: Optimizer Goal: 1=All_Rows, 2=First_Rows,
3=Rule, 4=Choose
tim: Zeitstempel ab 9i in Mikrosekunden
WAIT
●
●
●
●
●
●
#n: Cursor Nummer (Bezug zur verursachenden
SQL-Anweisung)
nam: Warteereignis (siehe Database Reference)
ela: Wartezeit ab 9i in Mikrosekunden
p1: Parameter 1 des Warteereignisses (siehe
Database Reference)
p2: Parameter 2 des Warteereignisses (siehe
Database Reference)
p3: Parameter 3 des Warteereignisses (siehe
Database Reference)
Antwortzeitprofil berechnen
●
●
Eingabedaten: Protokolldatei aus User Dump
Verzeichnis (user_dump_dest)
Vorsicht
–
–
●
Windows und Wiederverwendung der Protokolldateien
(SESSION ID:(<SID>.<Serial#>))
Shared Server (background_dump_dest)
Ausgabe: Ressourcennutzungsprofil
–
CPU-Verbrauch (EXEC, PARSE, FETCH; e=x)
Warteereignisse (WAIT; ela=y)
Antwortzeit R=∑ edep=0 + ∑ elawaits between calls
–
Statistiken
–
–
Antwortzeitprofil
$ ./esqltrc_profiler.pl mapsvr-17-580-lauf1.trc
Note: Oracle version 9.2 trace file. Timings are in microseconds (1/1000000 sec)
Response time: 2468.587 secs; max(tim)-min(tim): 2489.735
Total wait time time: 2317.096 secs
---------------------------Note: 'SQL*Net message from client' waits for more than 0.020 secs are considered
think time
Wait events and CPU usage:
Duration
Pct
Occurences
Average wait event/CPU usage/think time
-------- ------ ------------ ---------- ----------------------------------1938.709s 78.54%
149 13.011471s think time
377.659s 15.30%
80643 0.004683s SQL*Net message from client
148.062s
6.00%
257278 0.000575s total CPU
3.428s
0.14%
unknown
0.299s
0.01%
80793 0.000004s SQL*Net message to client
0.194s
0.01%
4422 0.000044s SQL*Net more data to client
0.118s
0.00%
120 0.000985s log file sync
0.095s
0.00%
10 0.009487s db file sequential read
0.015s
0.00%
216 0.000071s SQL*Net more data from client
0.006s
0.00%
40 0.000146s latch free
--------- ------- ----------------------------------------------------------2468.587s 100.00% Total response time
Total number of roundtrips (SQL*Net message from/to client): 80792
CPU usage breakdown
-----------------------parse CPU: 8.093750s
exec CPU: 8.859375s
fetch CPU: 131.109375s
Antwortzeitprofil (Fortsetzung)
Statistics:
----------COMMITs (read write): 120 -> transactions/sec 0.049
COMMITs (read only): 0
ROLLBACKs (read write): 0
ROLLBACKs (read only): 0
rows processed: 160073
cursor misses: 472
consistent gets: 314570
db block gets: 1294
physical reads: 8
buffer cache hit ratio: 100.00%
Physical read breakdown:
-----------------------single block: 10
multi-block: 0
Latch wait breakdown
-----------------------library cache pin
shared pool
library cache
waits:
waits:
waits:
1 sleeps:
7 sleeps:
32 sleeps:
Enqueue wait breakdown (enqueue name, lock mode)
-----------------------------------------------HW,X waits:
4
TX,S waits:
7
0
0
0
Think Time
●
●
●
●
●
●
Think Time bezeichnet bei interaktiven
Anwendungen, die Bedenkzeit, die der Benutzer
braucht, um die nächste Aktion auszulösen
nicht optimierbar
erkennbar an 'SQL*Net message from client'
kurze Dauer: normaler Roundtrip (LAN ca. 0,5ms 5ms)
lange Dauer: Anwendung tut andere Dinge
falls Think Time Hauptanteil der Antwortzeit
–
●
dann kein Datenbankperformanceproblem!
Vorsicht: bei überlasteten CPUs kommt Prozess
nicht zum Zug und 'SQL*Net message from client'
steigt
Extended SQL-Trace Profiler
Demonstration
cd /cygdrive/c/home/ndebes/it/perl/esqltrcprof
ls -l aspnet-21.5308-lauf1.trc
./esqltrc_profiler.pl -t 20 aspnet-21.5308lauf1.trc
TKPROF vs. Profiler
●
Zahlen für rekursive und nicht rekursive Wait
Events sowie CPU müssen summiert werden
Antwortzeit fehlt!
TKPROF vs.
Profiler
Extended Trace vs. Sampling
●
Shee ("Oracle Wait Interface") propagiert Sampling
alle 60s ohne Berücksichtigung von SQL*Net
message from client
–
–
●
Problem: Think Time kann nicht abgeleitet werden
ohne Think Time kann Frage, ob es Datenbankproblem
ist, nicht beantwortet werden
10g erstellt automatisch Messproben (Automatic
Session History, Automatic Workload Repository)
–
–
eine Messprobe pro Sekunde
Warteereignis, SQL-Anweisung, Objekt das Warten
verursacht
extended Trace vs. Sampling
extended Trace
proaktiv
–
– historische Daten für
nachträgliche Analyse
–
– vor 10g eigenes
Sampling-Tool
–
erforderlich (Jan van
Mourik:
–
http://www.rhdba.com)
– ab 10g automatisch,
–
aber ASH, AWR sind
kostenpflichtig (Diag.
Fazit:
Pack 2375€/CPU)!
– Sampling ist sinnvoll und v.a. wegen der historischen
Daten auf Sitzungsebene wertvoll
– extended Trace ist die detailreichste und präziseste
Messung
–
●
reaktiv
vollständige Messwerte
Algorithmus der
Anwendung erkennbar
unnötige PARSEs
mitsamt SQL erkennnbar
versionsübergreifend
einsetzbar (8i, 9i, 10g)
Mehraufwand verfälscht
Messung
Sampling
–
Performancediagnose erstellen
●
●
Komponenten mit höchstem Ressourcenverbrauch
sind das Problem und bergen das größte
Verbesserungspotential
Verursachende SQL-Anweisungen durch TKPROF
und/oder Lesen der Protokolldatei finden
–
●
●
TKPROF mit Sortieroption (z.B. fchcpu, fchela) gemäß
Profil aufrufen
Bind-Variablen in SQL-Anweisungen?
Algorithmus der Anwendung meist erkennbar
–
Bewertung des Algorithmus
Häufige Probleme und Symptome
●
zu viele Roundtrips
●
●
keine Bind-Variablen
●
●
●
●
●
●
●
fehlende Indizes, schlechte
Join-Reihenfolge
unnötig wiederholtes Parsen
z.B. in Schleifen
Sequences mit NOCACHE
zu häufiges COMMIT
eigene Zähler (keine
Sequence)
zeilenweises FETCH auf große
Datenmenge
●
●
●
●
●
●
hohe 'SQL*Net message from
client'
hohe WAITs mit Bezug auf den
Library Cache
hohe WAITs auf sequential bzw.
scattered read oder hoher CPUVerbrauch bei FETCH (Cache!)
erhöhte PARSE CPU
rekursives SQL bei jedem Zugriff
auf die Sequence (dep>0)
erhöhtes WAIT auf 'log file sync'
und erhöhte 'SQL*Net message
from client' wg. zus. Roundtrips
erhöhte WAITS auf 'enqueue' im
Mehrbenutzerbetrieb
viele FETCH Aufrufe mit r=1
Verbesserungspotential
berechnen
●
●
●
Verbesserungspotential von Codeänderungen oder
administrativen Eingriffen ist durch Messwerte (tim,
ela, e) berechenbar
evtl. Prototyp mit alter Implementierung und neuer
Implementierung kritischer Anweisungen
vergleichen (Empfehlung: Perl DBI als Client)
Beispiel:
–
–
–
bisher SELECT myseq.nextval, dann INSERT
Maßnahme: Trigger und INSERT ... RETURNING
Potential: Anzahl eingesparte Roundtrips mal
durchschnittliche Dauer eines Roundtrip (SQL*Net
message from+to client)
Massnahmen auswählen
●
●
●
●
●
Soll-Wert der Antwortzeit vom Kunden erfragen
mögliche Massnahmen abwägen
Verbesserung durch Massnahmen voraussagen
Massnahmen durchführen falls Soll-Wert erreichbar
falls Soll-Wert nicht erreichbar kein Zeitverlust
wegen unzureichender Maßnahmen
Massnahmen durchführen
●
●
●
erneute Messung nach Durchführung
Vergleich: Vorhersage - Messwerte
Ziel erreicht?
–
–
Ja: fertig
Nein: neue Iteration
Zusammenfassung
●
Optimierung mit Antwortzeitprofil ist die beste
Methode
–
–
–
–
–
●
klar strukturiert
vorhersagbare und nachprüfbare Ergebnisse
verhindert unzureichende Optimierungsmaßnahmen
Verfahren ohne Profiler durch Verwendung von TKPROF
und Tabellenkalkulation einsetzbar
setzt ineffektivem Ratio-Tuning ein Ende
Ausblick:
–
–
–
10g greift mit V$SESS_TIME_MODEL und
V$SYS_TIME_MODEL Antwortzeitprofile auf
10g Meßdaten erreichen trotz kostenpflichtigem ASH und
AWR nicht die Präzision und Aussagekraft eines
extended SQL Trace
kommt Oracle mit einem eigenen Profiler oder einem
verbesserten TKPROF?
Buchempfehlungen
Cary Millsap, Jeff Holt
Dan Tow
Shee, Deshpande,
Gopalakrishnan