Leistungseinbußen beim Tracing, Extended Event Ziele gegen SQL Trace unter CPU Last
Inspiriert durch den Blog Post Post “Measuring Observer Overhead of SQL Trace vs. Extended Events” von Jonathan Kehayias, war ich neugierig, ein paar weitere Benchmarks durchzuführen. Die Resultate habe ich bereits in meinen SQL Server Master-Class Workshops zu XEvents und auf der PreCon des SQLSaturday #230 präsentiert. Nun teile ich sie endlich hier.
Vor allem folgende Aspekte interessierten mich:
- Was ist der Performance-overhead einer Extended Event Session selber – ohne die Verarbeitung und des Dispatchens zu den Targets
- Wie verhält sich das im Vergleich zu SQL Trace – auch das ohne Overhead für ein Ziel (Keine Datei, kein Profiler: gar kein Konsument)
Da ich einmal das Setup bereit hatte, habe ich mich entschieden, alle anderen Ziele ebenfalls aufzunehmen, sowie einige grundlegende Options-Variationen, um einen kompletten Überblick zu erhalten, der in sich vergleichbar ist.
Ich entschied mich für ein System, das bereits unter CPU Druck steht – die CPU Verwendung liegt fast vollständig bei 100%. Unter diesen Umständen hoffte ich die maximalen Auswirkungen von Extended Events („Erweiterte Ereignisse“) als auch SQL Trace (Zur Erinnerung: SQL Profiler basiert auf SQL Trace) zu erhalten. Man könnte meinen, dass eine E/A(I/O)-lastige Arbeitslast noch mehr beeinflusst werden würde, aber das hängt an den Targets für Extended Events. – 4 davon gehen lediglich in den Arbeitsspeicher, gegenüber einem File-Target (welches man ohnehin auf ein Nicht-Daten-Volume legen sollte). Und da ich auch den reinen Overhead der Trace-Technologien (ohne Ziel) messen möchte, macht das noch mehr Sinn. Abgesehen davon kann I/O in der Regel meist recht einfach getuned werden, indem man auf ein ansonsten unverwendetes und schnelles Device schreibt, wohingegen es für CPU nicht so einfach ist, die Kosten unsichtbar zu halten. Das im Hinterkopf zu behalten hilft, die Resultate, die hier präsentiert werden zu evaluieren und sie in den rechten Kontext zu rücken.
Test Umgebung
“Einfach, aber physikalisch”
1 Windows 2008 R2 Server mit SQL Server 2012 SP1. Keine laufenden Dienste abseits des minimal Notwendigem, um Seiten-Effekte zu verhindern. Ich habe auch die Default-Trace sowie die system_health_session gestoppt. Der Distributed Replay-Client wurde für alle Test local ausgeführt, und Ja, das hat Effekt auf den Server, aber das war gleich für alle Tests. Alle Tests wurden 3 Mal wiederholt (einige sogar öfter), um sicherzustellen, dass der Durchschnitt/Median valide ist. Der Server, wie gesagt, war physikalisch (das kommt praktisch, wenn man Benchmarks mit einer Gesamtzeit von ~50 Stunden durchführt.): 1 Dual Core Intel Xeon mit 8 GB RAM (was bei Weitem genug war), Daten Volumen und Volumen für Trace-Targets auf separate Controllers.
Die Arbeitslast war ein Mix von meist kurzen (Sub-Sekunden) aber auch einigen Abfragen mit mehreren Sekunden Laufzeit, (Ad Hoc und gespeicherte Prozeduren), um eine einigermaßen realistische Decision-Support-System Last zu simulieren – jedoch ohne Datenänderungen. Die Baseline Workload dauerte 00:24:24 Minuten. Die Statistiken blieben für alle Workload-Zyklen identisch. Die verwendete Datenbank war AdventureWorks2012.
Trace-Konfigurationen
Ich habe mich für eine einfache, aber nicht unübliche Trace entschieden, die typischerweise viele Daten sammelt. Die Trace sammelt nur 2 Ereignisse:
- Lock acquired
- Lock released
Ausgefiltert: System-Sitzungen und andere Datenbanken als die, die hier unter Last steht.
Gesammelte Daten:
- Lock:Released BinaryData
- Lock:Released DatabaseID
- Lock:Released TransactionID
- Lock:Released SPID
- Lock:Released ObjectID
- Lock:Released Mode
- Lock:Released BigintData1
- Lock:Released IntegerData2
- Lock:Released ObjectID2
- Lock:Released Type
- Lock:Released OwnerID
- Lock:Released IsSystem
- Lock:Acquired BinaryData
- Lock:Acquired DatabaseID
- Lock:Acquired TransactionID
- Lock:Acquired SPID
- Lock:Acquired Duration
- Lock:Acquired ObjectID
- Lock:Acquired IsSystem
- Lock:Acquired Mode
- Lock:Acquired BigintData1
- Lock:Acquired IntegerData2
- Lock:Acquired ObjectID2
- Lock:Acquired Type
- Lock:Acquired OwnerID
Das gab mir den Vorteil, einen validen Test für alle Extended Event Targets, die bereitgestellt werden, zu haben (lediglich ETW-Tracing wurde ausgelassen) – speziell das Histogramm und die „Ereignispaarbildung“ (Pair-Matching)(Die wenigen Ereignisse von Lock-Escalation störten mich bewusst nicht).
Die folgenden Trace Technologien und -Ziele wurden verwendet:
- XEvent Trace, Target: None
- XEvent Trace, Target: Ring Buffer
- XEvent Trace, Target: File
- XEvent Trace, Target: Counter
- XEvent Trace, Target: Histogram
- Here I chose to filter on lock acquired and to bucketize on the lock mode
- XEvent Trace, Target: Pair Matching
- Guess, what I matched here 😉
- SQL Trace, Target: None (I had to trick a little bit to get this to work, but I made sure, the behavior of this unsupported configuration did not distort the results: It’s just a SQL Trace with no Provider processing anything, so all events are lost by nature.)
- SQL Trace, Target: File
- SQL Profiler, remotely
Für jedes Ziel der Extended Events habe ich 4 Varianten getestet, basierend auf den Sitzungsoptionen:
- Single event loss
- No event loss
- Multiple event loss
- Single event loss with causality tracking on
Alle anderen Optionen verwendeten die Standardwerte für diese Tests.
Picture: the 24 prepared traces
Die Ergebnisse
Ich habe die Gesamtlaufzeit für die Workload sowie Batches pro Sekunde und CPU Zeit % gemessen.
Und hier ist die vollständige Tabelle mit den Ergebnissen:
EL = Ereignisverlust. S = Verlust einzelner Ereignisse, N = Kein Ereignisverlust, M = Verlust mehrerer Ereignisse
CT = Kausalitätsverfolgung (Causality Tracking) Ein
Um Zeit und Platz zu sparen, konzentriere ich mich auf die Benchmarks mit den Optionen single event loss und no event loss ohne Causality Tracking. Tatsächlich waren die Kosten von Causality Tracking weniger als 1% für alle Ziele.
Hier ist daher das komprimierte Ergebnis:
Was wir demnach sagen können, ist: (Erinnern wir uns daran: alles läuft unter Hoher CPU Last. Das ist die Grundlage aller Ergebnisse.)
- Eine blanke XEvent Session alleine, ohne Targets, hat bereits einen spürbaren Einfluss von ~15 % Leistungsverlust.
- Der Aufschlag („Overhead“) der künstlich erzeugten (nicht unterstützten) Version einer blanken SQL Trace, ohne den Aufschlag eines Rowset oder File Providers („Target“), ist nicht allzu weit von dem einer Extended Events Session ohne dem Dispatchen zu einem Target entfernt (~19% gegen ~15%).
- Der Ringpuffer (Ring Buffer) ist das XE-Target mit dem größten Overhead (~40%). (!)
- Das Ereignisdateiziel (“File-Target”) hat, wie erwartet, wirklich den geringsten Overhead, aber dieser beläuft sich immer noch auf 25%.
- Die Unterschiede zwischen den Targets Ereigniszähler („Counter“), Histogramm und Ereignispaarbildung („Pair Matching“) sind irrelevant.
- Ja, sogar der simple Counter hat einen höheren Overhead als das File Target.
- Das File Target mit No Event Loss zu konfigurieren, fügt fast den vierfachen Overhead hinzu.
- Die Unterschiede für die anderen Targets zwischen single, multiple und sogar no event loss ist in diesem Szenario fast negierbar.
- Verglichen mit Extended Events ist der Overhead durch eine SQL Trace fast schon “brutal”: Er vervierfacht die Gesamtlaufzeit.
- Und noch mehr: Tracing mit dem SQL Profiler ist in solch einem Szenario schlicht ein Ding der Unmöglichkeit: Ich habe 21 Stunden eingetragen, aber das ist tatsächlich eine Schätzung: Ich beendete diese Test-Zyklen nach rund 3 Stunden (man möge mir verzeihen, aber es ist schlicht Zeitverschwendung…), zählte die beendeten Events und rechnete aus, wie lange es noch gedauert hätte, grob – aber tatsächlich eher optimistisch. Profiler ist, wie ich es immer sage, ein “No-Go” um für längere Zeiträume zu tracen, vor allem, wenn die Performance ohnehin bereits leidet.
Ein schönes Bild der SQL Trace Architektur findet sich in den BOL: msdn.microsoft.com/en-us/library/hh245121.aspx
Die Extended Events Architektur wird hier bildlich gezeigt: msdn.microsoft.com/en-us/library/bb630318%28v=sql.105%29.aspx
Hinzufügen von Filtern
Wie ändert das Hinzufügen von Filtern den Beobachter-Overhead?
Es ist wichtig, zu wissen, was ich als Filter verwendet habe: Die database_id / source_database_id. – Tatsächlich habe ich einen Filter verwendet, der niemals “true” zurückgeben würde, indem ich einen Filter auf database_id = 77 angelegt habe – da keine Sitzung/Abfrage/Sperre je auf dieser nicht-existenten Datenbank lag. Warum habe ich das gemacht? – Das ist ein rein künstlicher Test/Benchmark. Was mich interessiert, ist der reine Overhead des Tracen, und nicht, was passiert, wenn ein bestimmter Prozentsatz der Aktivität nicht protokolliert wird. (Das könnte vielleicht etwas für einen anderen Benchmark sein. :-))
Dieses Mal konzentriere ich mich nur auf „single“ und „no event loss“.
Die Resultate des gefilterten Tracing, ohne tatsächlich irgendwelche Events zu speichern/protokollieren, ist wie folgt:
- Wie man sehen kann, fällt der Overhead der reinen XEvent Session ohne Target von ~ 15% auf 9% bzw. ~ 16,5% gg. 12,5 % (No Event loss)
- Die anderen Targets zeigen in diesem Setup tatsächlich die größten Unterschiede:
- Das Counter Target mit single event loss profitiert am Meisten von dem Filter und fällt von ~33,5 auf 8,4 % Overhead.
- Nur Ring Buffer und Pair Matching zeigen keinen Unterschied zwischen single und no event loss.
- SQL Trace mit und ohne rowset Provider (Datei) als Target haben fast den gleichen Overhead – keine Überraschung, wenn man die Architektur kennt. Das ist tatsächlich ein weiterer risen Unterschied, der für Extended Events spricht, wo Filters viel früher in der Trace berücksichtigt werden.
- Das der Overhead von SQL Trace ohne Target und zugleich aller Events herausgefiltert sogar höher ist, als der Overhead ohne Target aber auch ohne Filter (von dem vorhergehenden Test-Zyklus), muss an dem Verarbeiten des Ausfilterns selber liegen. Ich werde mich damit aber nicht weiter befassen, da das Setup weder dokumentiert noch unterstützt ist. Und in meinen Augen ist “SQL Trace“ sowieso „tot“ 😉 – Okay, ich übertreibe hier ein wenig, aber ich bin auch ganz offen: Für SQL Server 2012 gibt es fast keinen Grund mehr zu dessen Verwendung. – Benchmarks mithilfe von Distributed Replay durchzuführen, ist so ein Grund – ist das nicht ironisch?
Für diesen Test habe ich SQL Profiler nicht ausgeführt, Pardon. Sie wissen bis hierhin wahrscheinlich schon, warum. 😉
Wait-Types für Extended Events
Ein weiterer Aspekt, der mich interessierte, waren die XEvent Wait-Typen, die auftreten würden, wenn man Extended Event Sessions ausführt. (Die Warte-Statistiken sind oft die Basis für Performance-Analysen)
Allgemein sieht man folgende:
Beim Starten einer Sitzung:
PREEMPTIVE_XE_TARGETINIT
PREEMPTIVE_XE_CALLBACKEXECUTE
PREEMPTIVE_XE_SESSIONCOMMIT
Beim Beenden einer Sitzung:
PREEMPTIVE_XE_SESSIONCOMMIT
XE_BUFFERMGR_ALLPROCESSED_EVENT PREEMPTIVE_XE_CALLBACKEXECUTE
Während Sessions aktiv sind, sieht man:
XE_DISPATCHER_WAIT – From BOL: Occurs when a background thread that is used for Extended Events sessions is waiting for event buffers to process. – You should be able to safely ignore this unless you believe a problem is occurring with processing of events for async targets. Since this works on a queue you can have bursts of high wait times especially when no XEvent sessions are active.
XE_TIMER_EVENT – From BOL: Used to indicate a background task is waiting for „expired“ timers for internal Xevent engine work. – You should be able to safely ignore this one. Just used by the Xevent engine for internal processing of its work. If something was possibly wrong with Xevent processing you might see if this thread ever „wakes up“
Beim Starten eines File-Targets sieht man außerdem:
PREEMPTIVE_XE_TARGETINIT
Wenn man eine Sitzung mit der No Event Loss Option ausführt, sieht man gegebenenfalls:
XE_BUFFERMGR_FREEBUF_EVENT – which by BOL means: An Extended Events session is configured for no event loss, and all buffers in the session are currently full. This can indicate that the buffers for an Extended Events session are too small, or should be partitioned.
So. Ich hoffe das war interessant. Man kann noch weitere und andere Schlüsse aus den Ergebnissen ziehen. Immer im Hinterkopf zu behalten, ist, dass das ein sehr spezielles Szenario ist, wo keine CPU Reserven zur Verfügung stehen, so das der Trace/Beobachter-Overhead sich manifestieren muss – keine Chance, als eben (CPU) Ressourcen wegzunehmen.
Happy Tracing
Andreas
P.S.: I just discovered that my MCM and SQLSkills-class buddy Steven Ormrod also has recently blogged about the performance overhead from a SQL Trace to remote file share on production here: stevenormrod.com/2013/06/remote-trace-slowing-down-server/
Hinterlasse einen Kommentar
An der Diskussion beteiligen?Hinterlasse uns deinen Kommentar!