SQL Server & BI Blog by Andreas Wolter

(DE)
Diesmal soll es um etwas gehen, das Extended Events direkt von Haus aus besser und leichter verfügbar machen, als sämtliche Techniken zuvor:
Speichern von aufgetretenen Deadlock-Ereignissen, und das Analysieren der entsprechenden Deadlock-Graphen.

(EN)
This time it’s about one of the things that Extended Events do better and more easy than all techniques before:
Saving of deadlock-events that occurred and analyzing the respective deadlock-graph.

Deadlocks, die man hier erläutert finden kann, treten zwischen mindestens 2 Arbeits-Threads auf, oft aber sind mehr als 2 beteiligt.
- Ich wähle „Thread“ absichtlich, da Prozess nicht genau genug wäre. Meistens treten Deadlocks zwar zwischen verschiedenen Sessions/Prozessen auf, aber es kann sich auch ein Prozess, der auf parallelen Threads ausgeführt wird, selbst blockieren.
Die Fehlernummer für Deadlocks ist die sicherlich allen SQL Profis bekannte „1205“.

Deadlock, explained here, occur between at least 2 threads but often more than 2 are involved.
- I am using the term “thread” on purpose, since process would not be sufficiently accurate. Mostly Deadlocks in fact do happen between different sessions/processes, but it is also possible that a process running with parallel threads blocks itself.
The error number for deadlocks is “1205” – probably known to all SQL professionals.

Um Deadlocks zu Tracen gab es vor SQL Server 2008 nur die folgenden Möglichkeiten:

1. Eine SQL Trace mit Profiler oder auch ohne GUI mit Protokollierung in trc-Datei oder live in der GUI

2. Trace Flags 1204, 1205 oder 1222, welche in das Errorlog des SQL Servers protokollieren – „wunderbar“ besonders auf „ereignisreichen“ Servern, und denkbar schwierig für die Analyse.

Manch einer mag sich noch an diese grausigen Einträge im Error-Log erinnern:

For tracing deadlocks before SQL Server 2008 there were merely the  following ways:

1. A SQL Trace with Profiler or without GUI with logging in a trace-file or live inside the GUI

2. Trace Flags 1204, 1205 or 1222, which log into SQL Server’s errorlog – „great“ especially  on “eventful” servers.

Some may remember those horrible entries in the error log:

3. Event Notifications, welche die Daten per Service Broker Queue in XML-Format zur Verfügung stellen.
Hier findet sich ein ausführliches Beispiel mit Speicherung in Tabelle und automatischem Mail-Versand mit Info über das Event.

4. Ein WMI-Alert, welcher die Daten ebenfalls per XML bereitstellt und mit einem Auftrag oder einer Benachrichtigung gekoppelt diesen protokollieren bzw. darüber informieren kann.

 3. Event Notifications which provide the data via Service Broker Queue in XML-format.
Here you find an elaborate example with storing in table and automatic email with information about the event.

4. A WMI-Alert which also provides the data via XML und tied to a job can also log respectively inform about it.

All diese Ansätze, so unterschiedliche Vorteile sie auch haben mögen haben eines gemeinsam: Sie müssen erst eingerichtet werden. Im Zweifelsfalle also nachdem die ersten Deadlocks aufgetreten sind.

Seit SQL Server 2008 jedoch werden sämtliche Deadlocks von Hause aus protokolliert.

Das geschieht durch die automatisch laufende system_health Extended Event session.

Diese speichert neben Deadlocks noch weitere wichtige Server-Ereignis- und Fehler-Informationen ab. Hier finden sich Details dazu.

Seit SQL Server 2012 protokolliert die system_health session neben dem Memory-Ziel „Ring_Buffer“ auch in die Ereignisdatei, womit Deadlocks und weitere Fehler auch nach Serverneustart noch eine ganze Weile (bis zu mehreren Tagen) zur Verfügung stehen – bis der Rollover der 5 Dateien stattgefunden hat.

Für SQL Server 2008 Instanzen empfehle ich, das Datei-Ziel hinzuzufügen.

All those approaches, as different as their respective advantages may, have ine thing in common: They have to be set up. In case of doubt after the first deadlocks occurred.

But since SQL Server 2008 all deadlocks are being logged by default.

This is done by the automatically running system_health Extended Event session.

This, alongside deadlocks logs further important server events and error-information. Here you find details on it.

Since SQL Server 2012 the system_health session apart from the memory-target “ring_buffer” also logs into an event-file, so that deadlocks and other error stay available even after a server restart for quite a while (up to a few days) – until the rollover of the 5 files has occurred.

For SQL Server 2008 instances I recommend to add the file-target.

Wie kann man diese Daten auslesen?
Das geht per T-SQL relativ einfach, wenn man weiß, dass diese Daten über die DMV sys. dm_xe_session_targets verfügbar sind.
So liest man das Ring-Buffer-Ziel aus:

 How can you read-out that data?
This works quite easily va T-SQL once you know that this data is available via the DMV sys. dm_xe_session_targets.
This is how you read-out the ring_buffer-Target.

„Target_data“ ist XML-text gespeichert als unicode-text-Blob, welches man bei entsprechender Konvertierung zu XML sogar in SSMS direkt öffnen kann.
Um nur die Deadlock-Events dort heraus zu filtern, muss man die XQuery-Erweiterungen von T-SQL bemühen.

Das sieht dann vom Code her so aus:

 „Target_data“ is XML-text stored as unicode-text-blob which can even be opened direct in SSMS after converting to XML.
To filter out only the deadlocks you need to use the XQuery-extensions of T-SQL.
And this is how that looks like in code plus results:

Wenn man einen solchen Deadlock-Report in XML-Format in SSMS anklickt, bekommt man ihn in einem neuen Fenster als XML-Dokument angezeigt:

When klicking at one of those Deadlock-Report reports in XML-format in SSMS it will be opened in a new window as XML-document:

- im Bild habe ich zur Übersicht einige Knoten zugeklappt.

Wichtig hier sind: die victim-list, welche bei einem Multi-Victim-Deadlock dann je Victim eine Prozess-Id enthält, die man wiederum in der process-list näher untersuchen kann.

Im executionStack findet man dann denn ausgeführten SQL-Befehl und ggfl. sogar direkt den Prozedurnamen.

Darunter folgt in der resource-list eine Liste der beteiligten (gesperrten) Ressourcen.

- in the picture I collapsed some nodes for brevity.

Most important here are: the victim-list, which for a multi-victim-deadlock contains one process-id per victim, which again one can investigate more deeply in the process-list.

In the executionStack one can find the executes SQL-command and if applicable even the procedure name.

Below in the resource-list follows a list of all involved (blocked) resources.

All nodes are peppered with details such as row number, objectname, lock-mode, waiting time, spid and of course timestamps.

Wer hier direkt weiter ansetzen möchte, kann das XML natürlich weiter auseinandernehmen und einzelne Knoten versuchen relational in Spaltenform darzustellen.
Dafür muss man zunächst den Deadlock-Graphen extrahieren:

Who wants to start from here can of course take apart the XML and try to break individual nodes relationally into columns.
For that one has to first extract the deadlock-graph.

Von dort aus kann man leicht die einzelnen Knoten parsen.
An das Transaction Isolation Level kommt man z.B. mit der value-Methode, wenn man einmal weiß, auf welcher Ebene/in welchem Knoten des Graphen sie sich befindet:

From there one can parse the individual nodes easily.
The transaction isolation level for example can be reached with the value-method once you know  on which level/in which node in the graph it resides.

Auf die Weise kann man mit fast allen Attributen und Elementen verfahren.
Bei den Sperr-Informationen stößt man dabei jedoch an die Grenzen der statischen relationalen Darstellung, da dort je nach gesperrter Resource völlig andere Attribute auftauchen.

In this manner one can proceed with almost all attributes and elements.
For locking-information one will get to the limits of the static relational representation since depending on the locked resource there will be completely different attributes.

Das zweite Problem tritt dann auf, wenn man Multi-Victim-Deadlocks vor sich hat.

Potentiell kann es ja eine Unmenge an gesperrten und gekillten Victim-Prozessen geben, so dass man da kaum ein immer ausreichendes Schema aufbauen kann.

Hier ein Beispiel eines Multi-Victim-Deadlocks, dargestellt mit der XEvents GUI (Profiler beherrschte das, wie so vieles, nicht)

The second problem arises once you are dealing with a multi-victim-deadlock.

Potentially there can be a vast number of locked and killed victim-processes, so that one can hardly prepare an ever sufficient schema.

Here an example of a multi-victim-deadlock, displayed with the XEvents GUI (Profiler could not handle that as many other things)

Letzten Monat habe ich meinen SQL Deadlock-Collector & Parser bei codeplex frei downloadbar veröffentlicht.
- hier der direkte Link: SQL Deadlock Collector & Parser

- Hier zum Artikel mit ausführlicher Beschreibung:

freier Deadlock-Sammler & -Parser basierend auf Erweiterten Ereignissen

Dort habe ich mich so entschieden, immer die beiden ersten Prozesse gegenüberzustellen, was bei den meisten Deadlocks schon sehr weiterhilft.

Das sieht dann so aus:

Last month I published my SQL Deadlock-Collector & Parser freely downloadable at codeplex.
- here the direct link: : SQL Deadlock Collector & Parser

- here the article with detailed explanaition:

free Deadlock-Collector & -Parser based on Extended Events

There I decided always contrast the first two processes , which helps for most deadlocks a lot already.

This is how it looks like:

Wie kann man nun die ja ebenfalls von er system_health-session geschriebenen Event-Dateien einlesen?

Dafür gibt es die Systemfunktion sys.fn_xe_file_target_read_file.
Diese benötigt den Pfad zur xel-Datei und den Namen der ersten Datei, welche eingelesen werden soll.
Die Dateien liegen übrigens im Log-Verzeichnis der SQL Server Instanz.
Wenn man den Dateinamen nicht angibt, werden alle Dateien im Verzeichnis eingelesen.
Was die Funktion jedoch wirklich praktisch macht, ist, dass man bereits den Pfad mit einer Wildcard für den Dateinamen versehen kann, dass man den Dateinamen praktisch kaum noch benötigt.

So kann das dann aussehen:

How is it possible to read-in the eventfiles which are written to as well by the system_health-session?

For that the system-function sys.fn_xe_file_target_read_file is a provided.
It needs the path to the xel-file and the name of the first file which is to be read-in.
The files are located in the log-directory of the SQL Server instance by the way.
If the filename is not specified all files in the directory will be read-in.
What makes the function really handy is, that one can already arm the path with a wildcard, so that practically one does not even need the filename any more.

This is how that can look like:

Wer bereits den Deadlock-Collector zum Parsen und Speichern seiner Deadlocks verwendet, kann damit ebenfalls manuell Deadlocks von X-beliebigen Systemen in die SQL_Analysis_Data-Datenbank importieren.
Dafür verwendet man einfach die Prozedur Locking.ins_DeadLock in der Datenbank SQL_Analysis_Code mit dem Parameter @XESource.

Dieser ist standardmäßig auf die Verwendung des Ring_Buffers geschaltet.
Aber man kann auch einfach den Pfad + Dateinamen der zu importierenden xel-Datei übergeben:

Who is already using the Deadlock-Collector to parse and save ones deadlocks can also use it to import deadlocks from any system at will into the SQL_Analysis_Data-database.

For that simply use the procedure Locking.ins_DeadLock in the database SQL_Analysis_Code with the parameter @XESource.

It is set to use the ring_buffer by default.
But one can simply pass in the path + filename of the xel-file to import:

Anschließend kann man die Deadlocks wie hier beschrieben über Sichten oder Ad-Hoc T-SQL bequem halbwegs in relationaler Struktur analysieren.

Afterwards one can comfortably analyse the deadlocks via views or ad-hoc T-SQL in a half-way relational structure as wie described here.

Hinweis:

Note:

It is possible that deadlocks occur which do not appear in the system_health-session targets. Neither in the ring_buffer not in the filetarget.
This happens when the deadlock-graph is too big for the buffer-memory.

In order to make sure that larger deadlock graphs are also captured, I recommend to increase the maximal work memory of the system_health session.

Und wer jetzt immer noch auf Profiler & SQL Trace setzt (seit SQL Server 2012 aus gutem Grunde deprecated), hier noch ein Tipp:
So sieht ein MultiVictim-Deadlock im Profiler aus:

And who now is still using Profiler & SQL trace (deprecated since SQL Server 2012 for good reasons), here a tip:
This is how a multi-victim-deadlock looks in Profiler:

Das sieht eher wie ein „Multi-Winner-Deadlock“ aus ;-)

Und so stellt sich dieser in der XEvents GUI dar:

Looks more like a „multi-winner-deadlock” ;-)

And this is how the XEvents GUI displays it:

(de)
Dieser Artikel enthält eine Liste der neuen Erweiterte Ereignisse (“Extended Events”), dem Tracing Framework in SQL Server in dem neuen 2014 Release.

Zunächst gibt es 3 neue Pakete („Packages“), die alle zu der neuen Arbeitsspeicher(„In-Memory“) -OLTP Engine: XTP, aufgeteilt auf 3 DLLs:

(en)
This article contains a list of new Extended Events, the tracing framework in SQL Server in the new 2014 release.

To begin with there are 3 new packages, all belonging to the new In-Memory OLTP Engine: XTP, split up into 3 dlls:

Package

description

Module name

XtpRuntime

Extended events for the XTP Runtime

{InstanceDir}\MSSQL\Binn\
hkruntime.dll

XtpEngine

Extended events for the XTP Engine

{InstanceDir}\MSSQL\Binn\
hkengine.dll

XtpCompile

Extended events for the XTP Compile

{InstanceDir}\MSSQL\Binn\
hkcompile.dll

Die Anzahl der Extended Events ist von 625 in SQL Server 2012 (SP1) auf 870 in SQL Server 2014 (RTM) angestiegen. Das sind 245 neue Events! – Reichlich Möglichkeiten, in Internas einzutauchen :-)
2 Events sind umbenannt worden:

recovery_incremental_checkpoint in

recovery_indirect_checkpoint

und hekaton_slow_param_passing in

natively_compiled_proc_slow_parameter_passing

Ja, richtig gelesen. Es gab bereits im SQL Server 2012 eine Anzahl an Events für die XTP Engine. Es kommt recht häufig vor, dass man Bits von zukünftigen Entwicklungen in der aktuellen Release findet.

Nebenbei: SQL Trace wurde nicht im geringsten angefasst. Die Anzahl von SQL Trace Events bleibt mit 180 seit SQL Server 2008 stabil. – Here ist ein Überblick von Extended Events gegen SQL Trace Events in den verschiedenen SQL Server Versionen: Extended Events vs SQL Trace im Vergleich – oder warum SQL Trace & Profiler einfach von gestern sind :-)

Weiter zu XEvents: es gibt keine neuen Prädikate, aber eine Anzahl neuer Maps, was natürlich nicht überrascht bei der Menge neuer Events.
Targets, Actions, Typen und Session Optionen  sind unverändert.

Und hier ist die Liste der neuen Extended Events:

The number of Extended Events increased from 625 in SQL Server 2012 (SP1) to 870 in SQL Server 2014 (RTM). That makes 245 new events! – Plenty of opportunities to look into internals :-)
2 events have been renamed:

recovery_incremental_checkpoint into

recovery_indirect_checkpoint

and hekaton_slow_param_passing into

natively_compiled_proc_slow_parameter_passing

Yes, you read correctly. There have already been a couple of events for the new XTP engine within SQL Server 2012. It’s quite common that you can find bits of future developments within the current release.

By the way: SQL Trace has not been touched by the slightest bit. The number of SQL Trace events stays at 180 since SQL Server 2008. – here you find an overview of the number of Extended Events vs SQL Trace events in the various SQL Server versions: Comparing Extended Events vs SQL Trace – or why SQL Trace & Profiler are just a thing of the past :-)

Continuing with XEvents: There are no new predicates, but a couple more maps, which is of course not surprisingly considering the amount of new events.
Targets, actions, types and session options are unchanged.

And here is the list of all new extended events:

(de)
Zur Erinnerung: Extended Events sind seit SQL Server 2008 in SQL Server integriert. Und seit SQL Server 2012 SP1 sind alle Events verfügbar, die es in SQL Trace gibt. Zudem sind Extended Events seit SQL Server 2012 auch für Analysis Services verfügbar (Tracing Analysis Services (SSAS) with Extended Events – Yes it works and this is how).

Für alle, die noch mit dem alten Werkzeug SQL Server Profiler (Profiler ist das Frontend für SQL Trace, gestartet mit sp_trace_create) arbeiten, und sich noch nicht für die neue Technologie entscheiden konnten, hier eine kleine Entscheidungshilfe.

Was Extended Events (XEvents) besser als SQLTrace machen:

(en)
As a reminder: Extended Events have been integrated in SQL Server since SQL Server 2008. And since SQL Server 2012 SP1, all events existing in SQL Trace have been available. In addition, Extended Events have also been available for Analysis Services since SQL Server 2012 Tracing Analysis Services (SSAS) with Extended Events – Yes it works and this is how).

For those of you who are still working with the old tool SQL Server Profiler (Profiler is the frontend for SQL Trace, started with sp_trace_create) and have not quite been able to decide for the new technology, here is some decision guidance.

What Extended Events (XEvents) do better than SQL Trace:

1. Einzige Möglichkeit neue Features wie FileStream, FileTable, AlwaysOn, ColumnStore, Hekaton/XTP etc. zu Tracen
2. Viel mehr Events tracebar, auch bereits für ältere Releases (siehe *1, *2 unten)
3. Deutlich geringerer Beobachter-Overhead
   siehe auch: Performance overhead of tracing with Extended Event targets vs SQL Trace under CPU Load
4. Performance/Last lässt sich konfigurieren & tunen
5. Events und Filter lassen sich live anpassen – während aktiver Session also
6. Ofiziell 2 µs/Event gg. 4ms/Event in SQLTrace
7. Event-Verlust konfigurierbar
8. Effiziente Filterung durch Architektur
9. Komplexe Prädikate wie z.B. Zähler oder last_error, less_than_min_datatype oder greater_than_max_datatype
10. Korrelation von Events möglich
11. Möglichkeit Events vom Client bis in die Datenbank zu verfolgen
12. Einfache Automatisierung
13. Direkt in Management Studio integriert
14. Viele Analysen direkt in der GUI möglich (Um diese noch zu verbessern, bitte hier bei Microsoft Connect voten: Extended Events UI Export Display Settings: include grouping)
15. Query_hash zum Identifizieren von identischen Abfragen verfügbar
16. Keine 10 Klicks zum Aufsetzen einer simplen Session inkl. Filter
17. Unterschiedliche Speicher-Ziele für EventDaten zur Auswahl (6)
18. „Ergebnisorientierte“ Ziele wie Counter und Histogramm
19. Multiple Ziele lassen sich für “On the fly - Top-Down Analysen” kombinieren
20. Möglichkeiten für ganz neue Einblicke in Interna der Datenbank-Engine (Latching, Spinlocks, Multi-victim-Deadlock, Wait_Infos per session/query, Caching-Vorgänge, Ghost-cleanup, Analyse von Page Splits, Page-Compression Vorgänge, um nur einige zu nennen)
21. Stack Tracen eines einzelnen Prozesses möglich – anstelle eines vollständigen Server Dumps
22. Definition mit Standard DDL-Statements
23. API zur Integration in eigene Tools verfügbar
24. PowerShell-Unterstützung
25. Last but not least: Endlich ein Grund, XML & XQuery zu lernen? ;-)

1. The only possibility of Tracing new features like FileStream, FileTable, AlwaysOn, ColumnStore, Hekaton/XTP etc.
2. Many more Events traceable, even for older releases (see *1, *2 below)
3. Significantly less Observer-Overhead, also see: Performance overhead of tracing with Extended Event targets vs SQL Trace under CPU Load
4. Performance/Overhead can be configured and tuned
5. Events and Filters can be adapted live – meaning during active session
6. Official 2 µs/Event vs. 4ms/Event in SQLTrace
7. Event-loss is configurable
8. Efficient filtering through architecture
9. Complex predicates such as Counter or last_error, less_than_min_datatype oder greater_than_max_datatype
10. Correlation of Events possible
11. Possibility of following Events from Client into the Database
12. Easy Automation
13. Directly integrated in Management Studio
14. Many analysis directly inside the GUI possible (in order to improve them, please vote at Microsoft Connect: Extended Events UI Export Display Settings: include grouping)
15. Query_hash for identification of identical queries available
16. No 10 clicks to set up a simple session including filter
17. Choice of different destinations for storing EventData (6)
18. “Goal-oriented” destinations such as Counter and Histogram
19. Multiple destinations can be combined for “On the fly – top-down analyses”
20. Possibilities for entirely new insights into internal matters of database engine (Latching, Spinlocks, Multi-victim-Deadlock, Wait_Infos per session/query, Caching-processes, Ghost-cleanup, analysis of Page Splits, Page-Compression processes, to name just a few)
21. Stack Tracing of a single process possible – instead of a complete Server Dump
22. Definition with standard DDL-Statements
23. API for integration into one’s own tools available
24. PowerShell support
25. Last but not least: Finally a good reason to learn XML & XQuery? ;-)

Ich hoffe, das hilft dem einen oder anderen, die alte Gewohnheit abzulegen, und die kleine Lernphase in Kauf zu nehmen.

Eine Liste aller Extended Events in SQL Server 2012 SP1 samt Ihrem Gegenstück in SQL Trace, welche man für Migrationszwecke (SQLTrace -> XEvent Trace) verwenden kann findet sich in dieser Seite. (Aufgrund einer Größenbeschränkung passte sie nicht mehr hier hinein.)

I hope this helps some of you to unlearn the old habit and accept the little learning phase. 

A list of all Extended Events in SQL Server 2012 SP1 including its counter piece in SQL Trace that can be used for migration purposes (SQLTrace-> XEvent Trace) is available on this page. (Due to size restriction, it didn’t fit in here anymore.)

PS: Für 2014 befindet sich mit den SQL Server Master-Classes zum Thema „Tracing mit Extended Events“ auch die nächste Runde der Trainings zu diesem Thema in der Planung :-)

P.S. For 2014, the next round of training in this topic is being developed in conjunction with SQL Server Master-Classes on the topic “Tracing with Extended Events” :-)

(DE)

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.

(EN)

Inspired by the Blog Post “Measuring Observer Overhead of SQL Trace vs. Extended Events” by Jonathan Kehayias, I was curious to do some more benchmarking.
I have already presented the results in my SQL Server Master-Class workshops on XEvents as well as at the PreCon of the SQLSaturday #230. Now I am finally sharing them with you here.

I was interested in the following aspects, in particular:

• What is the Performance-overhead of an Extended Event Session itself – not including the processing/dispatching for the target
• How does this compare to the old-school SQL Trace – again with no Target overhead (No File, no Profiler: no consumer at all)

Besides that, once I had the setup ready, I decided to include all the other targets and some basic option-variations, to have a complete overview that is comparable in itself.

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.

I also decided for a test of a system that’s already under CPU pressure - so the Processor Usage is almost constantly hitting 100%.
Under these circumstances I was hoping to get the maximum impact of Extended Events as well as SQL Trace. (Remember: SQL Profiler is based on SQL Trace) One could think that an I/O driven workload would be even more influenced, but that depends on the targets of Extended Events. - 4 of which only go to memory, vs. one file target (which one should put onto a non-data volume anyways). And since I also want to measure the pure overhead of the tracing technologies (without any target), this makes even more sense.
Besides that, I/O usually can be tuned quite easily by writing to an otherwise idle and fast device, whereas for CPU it is not as simple to keep the costs invisible. Keeping this in mind helps to evaluate the results presented here and bringing them into the right context.

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.

Test Environment

“Simple but physical”

1 Windows 2008 R2 Server with SQL Server 2012 SP1. No running services above the minimum required, to avoid side-effects.
I also shut down the default trace as well as the system_health_session.
The Distributed Replay-client was run locally for all tests, so yes, this has effect on the server, but it was equally for all tests. All tests have been repeated 3 times (some even more) to make sure the average/median is valid.
The server, as I already said, was physical (which comes in handy when you are running benchmarks for a total of ~50 hours): 1 Dual Core Intel Xeon with 8 GB of RAM (which was by far enough), Data Volumes and Volumes for Trace-Targets on separate Controllers.

The workload was a mixture of mostly short (sub-second) but also several queries of several second runtime, (Ad Hoc and stored procedures) to simulate a somehow realistic decision-support-systems’ load – no data changes though.
The baseline workload took 00:24:24 minutes. The statistics stayed the same for all workloads cycles. The database used was 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:

Trace-Configurations

I decided for a simple but not uncommon trace that typically collects a lot of data. The trace collects only 2 events:

Ausgefiltert: System-Sitzungen und andere Datenbanken als die, die hier unter Last steht.

Gesammelte Daten:

Filtered out: System-sessions and other databases than the one under load here.

CollectedData:

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:

This gave me the advantage to have a valid test for all Extended Event Targets that are provided (only ETW-Tracing was left out) - specifically histogram and Pair Matching (I did not care about the few occasions of lock escalation on purpose).

The following Trace technologies and -Targets were used:

Für jedes Ziel der Extended Events habe ich 4 Varianten getestet, basierend auf den Sitzungsoptionen:

For each Extended Event Target I tested 4 variations, based on the session options:

Alle anderen Optionen verwendeten die Standardwerte für diese Tests.

All other options were using the defaults for these tests.

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:

The Results

I measured the total time for the workload to take as well as batches per second and CPU time %.

And here is the complete Table of Results:

EL = Ereignisverlust. S = Verlust einzelner Ereignisse, N = Kein Ereignisverlust, M = Verlust mehrerer Ereignisse

CT = Kausalitätsverfolgung (Causality Tracking) Ein

EL = Event Loss. S = Single event loss, N = No event loss, M = Multiple event loss

CT = Causality Tracking On

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:

For the sake of saving space and time, I will focus on the benchmarks with the options single event loss and no event loss without causality tracking. In fact, the cost of causality tracking was less than 1% for all targets.

So this is the more condensed result:

Was wir demnach sagen können, ist:
(Erinnern wir uns daran: alles läuft unter Hoher CPU Last. Das ist die Grundlage aller Ergebnisse.)

What we can tell from that, is:
(Remember: Everything is running under High CPU Load, so that’s the base of all results.)

• 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.

• A plain XEvent Session itself, with no Targets, already does have a noticeable impact of ~15 % performance decrease.
• The overhead of the artificial (not supported) version plain SQL Trace, without the overhead of a rowset or file provider (aka target), is not too far off the Extended Events Session without the dispatching to any target (~19% versus ~15%).
• The Ring Buffer is the XE-Target with the greatest overhead (~40%). (!)
• The File-Target really does have the lowest overhead as expected, but it’s still 25%.
• The differences between the Targets Counter, Histogram and Pair Matching are irrelevant.
  • Yes, even the simple Counter has a higher overhead than the File Target.
  • Configuring the file target with no event loss adds approximately 4 times as much performance overhead.
  • The difference for the other targets between single, multiple and even no event loss is mostly negligible in this scenario.
  • Compared to Extended Events, the overhead through SQL Trace is almost “brutal”: It quadruplicated the total runtime.
  • And there's even more: Tracing with SQL Profiler is absolutely impossible for such a scenario: I filled in 21 hours, but that’s actually an estimate: I stopped those test cycles after around 3 hours (forgive me, but it’s just a waste of time...), counted the finished events and calculated how much else it would have taken, roughly – in an actually rather optimistic manner. Profiler, as I always say, is a “no go” for tracing longer periods of time, especially if performance is already at stake.

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

You have a nice picture of the SQL Trace Architecture in BOL: msdn.microsoft.com/en-us/library/hh245121.aspx
The Extended Events Architecture is depicted here: 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. :-))

Adding Filters

How does adding filters change the observer overhead?

Now it is important to note what I actually used as a filter: The database_id / source_database_id.
- I essentially added a filter that would never return “true” by adding a filter on database_id = 77 – since no session/query/lock was on this non-existing database.
Why did I do that? – This is a totally artificial test/benchmark. I am interested what the pure overhead of tracing is, and not what happens if a certain percentage of activity is not logged. (That might be something for a different benchmark. :-))

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:

This time I only focused on “single” and “no event loss”.

The results of Filtered Tracing, without actually storing/logging any events is as follows:

• 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. ;-)

• As one can see, the overhead of the pure XEvent session without target drops from ~ 15% to 9% respectively ~ 16.5% vs. 12.5 % (no Event loss)
• The other targets do in fact show more differences in this setup:
• The Counter Target with single event loss benefits most of the filter and drops from ~33.5 to 8.4 % overhead.
• Only Ring Buffer and Pair Matching show no difference between single and no event loss.
• SQL Trace with and without rowset provider (file) as target have almost the same overhead – no surprise if you know the architecture. This is in fact another huge difference which counts for Extended Events, where filters get honored much sooner within the Trace.
• That the overhead of SQL Trace without target and at the same time all events being filtered out is actually higher than the overhead without target but no filtering (from the former test cycle) must be caused by the processing of for filtering out. I will not dive more into this though, since this setup is not documented and or supported.
  And in my eyes, “SQL trace is dead” anyways ;-) – okay, I am exaggerating a bit here, but I am also just being frank: For SQL Server 2012 there is almost no need to use it any more. – Running benchmarks using Distributed Replay is such a reason – isn’t that ironic?

I did not run SQL Profiler for this Test, forgive me. You probably know why by now. ;-)

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:

Wait-Types for Extended Events

Another aspect I was interested in were the specific XEvent wait-types which would occur when running Extended Event sessions.
(Wait-Statistics are often the base for performance analysis)

In general, you will see the following:

Beim Starten einer Sitzung:

When starting a session:

Beim Beenden einer Sitzung:

When stopping a session:

 Während Sessions aktiv sind, sieht man:

While running sessions you will see:

Beim Starten eines File-Targets sieht man außerdem:

When starting the File target you will also see:

Wenn man eine Sitzung mit der No Event Loss Option ausführt, sieht man gegebenenfalls:

If you run a session with the no event loss option you might see

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.

So, I hope this was interesting for you. You may draw more and other conclusions out of these results. Remember though: this is a very specific scenario with no CPU reserves, so the Tracing/observer overhead has to show up – no choice but to take away (CPU) resources.