How to import Extended Events session file target and parse deadlock-graph / Import von Extended Events Ereignisdateien und Parsen von Deadlock-Graphen

 

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

 

SELECT

    target_data

FROM

    sys.dm_xe_session_targets AS dm_xe_session_targets

INNER JOIN sys.dm_xe_sessions AS dm_xe_sessions

    ON dm_xe_session_targets.event_session_address = dm_xe_sessions.address

WHERE

    dm_xe_sessions.name = 'system_health'

    AND target_name = 'ring_buffer'

 

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

Sämtliche Nodes sind mit Details wie der Zeilennummer, Objektname, Lock-Modus, Wartezeit, SPID und natürlich Zeitstempeln gespickt.

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

 CAST(XEventData.XEvent.query('(data/value/deadlock)[1]') AS xml) AS DeadlockGraph

 

 

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.

 XMLCol.value('(/deadlock/process-list/process)[1]/@isolationlevel', 'varchar(100)')

 

 

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:

 

USE SQL_Analysis_Code;

DECLARE @DeadlocksCollected int;

EXECUTE Locking.ins_DeadLock

                @XESource = 'D:\LogFiles\SQLServer\SQL2012Dev\system_health_*.xel'

    ,   @DeadlocksCollected = @DeadlocksCollected OUTPUT;

SELECT @DeadlocksCollected AS [Number of new Deadlocks collected:];

 

 

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:

Es ist möglich, dass Deadlocks aufreten, die nicht in den system_health_session-Speicherzielen, also weder in Ring_Buffer noch in der Eventdate zu finden sind. Das geschieht, wenn der Deadlock-Graph zu groß für den Puffer-Speicher ist.
Um sicherzustellen, dass auch größere Deadlocks gesammelt werden können, empfehle ich, den Puffer-Speicher der system_health-session zu erhöhen.

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:

 

 

HappyXEvent Parsing

 

Andreas