Tag: "extended events"

Where is that Preemptive Wait coming from? Database Ownership and Performance: a journey through SQL Server internals with XEvents, Windbg and Wireshark


In this article I will bring together several techniques for troubleshooting a performance- and security-related “phenomenon” I recently noticed when doing some tests with Natively Compiled Stored Procedures.

In diesem Artikel zeige ich einige Techniken zum Troubleshooten eines Performance- und sicherheitsrelevanten „Phänomens“, das mir kürzlich aufgefallen ist, als ich ein paar Tests mit Natively Compiled Stored Procedures durchführte.


In SQL Server 2014, Natively Compiled Stored Procedures did not support EXECUTE AS CALLER but EXECUTE AS “SpecificUser” was required. This user could be specified with “Username”, “Self” or simply “Owner” – in which case the owner of the procedure usually reverts to the schema owner, which mostly reverts to the Database Owner altogether.

Hintergrund: In SQL Server 2014 unterstützten Natively Compiled Stored Procedures EXECUTE AS CALLER nicht, sondern es war EXECUTE AS “SpecificUser” erforderlich. Dieser Nutzer konnte mit “Username”, “Self” oder einfach “Owner” spezifiziert werden – in dem Fall kehrt der Besitzer der Prozedurnormalerweise zum „schema owner“ zurück, was meistens ganz auf den Database Owner zurückkehrt. 

The phenomenon I encountered was that I noticed some pretty strange long execution times when running a workload consisting of a very basic stored procedure that does nothing more than insert one row of data into a small, unspectacular table.

The insert itself should run in less than a second for 1000 rows, but I could see up to 5 seconds.
The body of the procedure looks like this:

Das Phänomen, dem ich begegnete, war, dass ich einige ziemlich seltsam lange Ausführungszeiten bemerkte, als ich eine Workload laufen ließ, die aus einer sehr einfachen Stored Procedure bestand, die nichts weiter tat, als eine Datenreihe in eine kleine, unspektakuläre Tabelle einzufügen.
Das Insert selbst sollte weniger als eine Sekunde für 1000 Zeilen laufen, doch ich konnte bis zu 5 Sekunden sehen.
Der Inhalt der Prozedur sieht so aus:



INSERT UserSchema.TableName
(4 columns, int and char)



The analysis:

Since neither the query plan nor “Show Statistics ON” showed anything unusual, I took a step back and started a top-down-analysis with the Waits and Queues Methodology (which, if you are new in this area, has been a proven methodology for performance analysis for over a decade and is explained for SQL Server probably for the first time in detail here: SQL Server 2005 Performance Tuning using the Waits and Queues)
Using the new session-level waits-DMV in SQL Server 2016 (sys.dm_exec_session_wait_stats) I saw the following distribution of waits:

Die Analyse:

Da weder der Abfrageplan noch “Show Statistics ON“ irgendetwas Ungewöhnliches zeigten, ging ich einen Schritt zurück und begann eine Top-Down-Analyse mit der Waits and Queues Methode (die, wenn ihr in diesem Bereich neu seid, eine seit über einem Jahrzehnt bewährte Methode zur Performance-Analyse ist und für SQL Server wahrscheinlich zum ersten Mal im Detail hier erklärt wird: SQL Server 2005 Performance Tuning using the Waits and Queues)
Bei der Anwendung der neuen Session-Level Waits-DMV im SQL Server 2016 (sys.dm_exec_session_wait_stats) sah ich die folgende Waits-Verteilung: 


SELECT dm_exec_session_wait_stats.wait_type
, SUM(dm_exec_session_wait_stats.wait_time_ms) - SUM(dm_exec_session_wait_stats.signal_wait_time_ms) AS resource_wait_time_ms
, SUM(dm_exec_session_wait_stats.signal_wait_time_ms) AS signal_wait_time_ms
, SUM(dm_exec_session_wait_stats.wait_time_ms) AS wait_time_ms
, MAX(dm_exec_session_wait_stats.max_wait_time_ms) AS max_wait_time_ms
, SUM(dm_exec_session_wait_stats.waiting_tasks_count) AS waiting_tasks_count
FROM sys.dm_exec_session_wait_stats AS dm_exec_session_wait_stats
INNER JOIN sys.dm_exec_sessions AS dm_exec_sessions
                ON dm_exec_session_wait_stats.session_id = dm_exec_sessions.session_id
WHERE dm_exec_sessions.program_name ='Sarpedon-WorkoadSimulation-InsertProcs'
GROUP BY dm_exec_session_wait_stats.wait_type
ORDER BY max_wait_time_ms DESC;


From this list, Latch-contention, blocking and some waiting for IO is to be expected with a very concurrent workload (50 threads trying to insert on the last page).
The wait-types marked red are the ones that caught my attention.
As Preemptive waits are a quite different beast, and I initially thought maybe there was some authentication issue with the client, I decided to take a look at the CMEMTHREAD.

Von dieser Liste sind Latch-contention, Blocking und einiges Warten auf IO bei einer sehr simultanen Workload zu erwarten (50 Threads, die versuchen, sich auf der letzten Page einzufügen).
Die rot-markierten Wait-Typen sind diejenigen, auf die ich aufmerksam wurde.
Da Preemptive Waits ein spezielles Biest sind, und ich anfangs dachte, dass es vielleicht ein Authentifikationsproblem beim Client gab, entschied ich mich, einen Blick auf den CMEMTHREAD zu werfen.  

The CMEMTHREAD is an indicator that many threads are contending simultaneously for a thread-safe memory object.
Now since we are running a highly concurrent workload, I could just leave it at that, but remember: “Never make quick decisions by confusing symptom with cause”. Keep looking for the real cause. (A good article by Paul Randal on exactly this issue: “Avoiding Knee-Jerk Performance Troubleshooting”)

So, the question is, which memory object is so special here.

Der CMEMTHREAD ist ein Indikator dafür, dass viele Threads gleichzeitig um ein thread-safe Memory-Object konkurrieren.
Nun, da wir eine höchst konkurrierende Workload laufen haben, könnte ich es einfach darauf beruhen lassen, doch denkt dran: „Niemals schnelle Entscheidungen treffen, indem man das Symptom mit der Ursache verwechselt.“ Sucht weiter nach der wahren Ursache. (Hier ein guter Artikel von Paul Randal zu genau diesem Thema: “Avoiding Knee-Jerk Performance Troubleshooting”)

Also ist die Frage, welches Memory-Object hier so besonders ist.  

Time for Extended Events

One of the niftiest features of extended events is, that you can get a full stack dump of just a single thread, using the Action “sqlserver.create_dump_single_thread”. ”. Similarly, using “package0.callstack” you can get a callstack of the last 16 frames.
 You can analyze the outcome with Windbg. – Or, using Trace Flag 3656, you can even query the Extended Event targets directly with XQuery from within Management Studio and the callstack will be materialized, provided you have loaded the correct symbols. (Nothing you should do on a production Server!)
(An example how to do that can be found here: Resolving DTC Related Waits and Tuning Scalability of DTC)

With the dump opened in Windbg the following function calls inside the SQL Server engine can be seen:

Zeit für Extended Events

Eine der raffiniertesten Features von Extended Events ist, dass man einen vollständigen Stack Dump von einem einzelnen Pfad erhalten kann, wenn man die Action “sqlserver.create_dump_single_thread” verwendet.
Auf ähnliche Weise kann man einen Callstack der letzten 16 Frames erhalten, wenn man “package0.callstack” verwendet.
Man kann das Ergebnis mit Windbg analysieren – oder, wenn man Trace Flag 3656 verwendet, kann man sogar die Extended Event Targets direkt mit XQuery aus Management Studio heraus abfragen und der Callstack wird materialisiert. (Nichts, das man auf einem Produktions-Server machen sollte!)

(Ein Beispiel dafür, wie das gemacht werden kann, ist hier: Resolving DTC Related Waits and Tuning Scalability of DTC)

Mit dem in Windbg  geöffneten Dump können die folgenden Funktions-Calls in der SQL Server Engine gesehen werden:



The Stack dump rings a bell. Right before allocating the memory (CMemThread<CMemObj>::Alloc (red), several functions with very familiar names were called (orange):

Bei dem Stack Dump läuten doch einige Glocken. Kurz vor dem Zuteilen des Memory (CMemThread<CMemObj>::Alloc (rot) wurden mehrere Funktionen mit sehr bekannt klingenden Namen abgerufen (orange):


And those in turn must have been caused by the sqllang!CAutoExecuteAsContext::Set, sqllang!CMsqlExecContext::FExecute and so on (green).
At this point I pretty much knew where to look. But just to show you an example of how this can be done without even touching Windbg, here is an (accumulated and commented) result from the Extended Event callstack-Action:

Und diese wiederum müssen von sqllang!CAutoExecuteAsContext::Set, sqllang!CMsqlExecContext::FExecute verursacht worden sein, und so weiter (grün).
In diesem Moment wusste ich im Prinzip schon, wo ich suchen musste. Aber um euch ein Beispiel zu zeigen, wie man das auch machen kann, ganz ohne Windbg anzurühren, ist hier ein (gesammeltes und kommentiertes) Ergebnis der Extended Event Callstack-Action:  




This callstack results from the PREEMPTIVE_OS_LOOKUPACCOUNTSID Wait-Type, which I noticed would happen exactly once per procedure call. When analyzing different callstacks together I could draw the conclusion that the following function calls lead to the respective Wait-Types:

Dieser Callstack resultiert vom PREEMPTIVE_OS_LOOKUPACCOUNTSID Wait-Type, was, wie ich bemerkte, genau einmal pro Procedure Call geschehen würde. Beim Analysieren verschiedener Callstacks zusammen konnte ich die Schlussfolgerung ziehen, dass die folgenden Funktions-Calls zu den jeweiligen Wait-Types führen:

sqllang.dll!LookupAccountNameInternal -> PREEMPTIVE_OS_LOOKUPACCOUNTSID
sqllang.dll!CWindowsSecurityPrimaryInfo::GetNtGroupsViaAuthZ -> PREEMPTIVE_OS_AUTHZINITIALIZERESOURCEMANAGER
sqllang.dll!CWindowsSecurityPrimaryInfo::Init -> PREEMPTIVE_OS_AUTHORIZATIONOPS

The Preemptive Waits read from the Extended Events file-target can be ordered in their occurrence (from top to bottom), leading to the following picture:

Die Preemptive Waits, aus dem Extended Events Datei-Ziel gelesen, können nach ihrem Auftreten sortiert werden (von oben nach unten), was folgendes Bild ergibt:



The here unreadable callstack for the call to AUTHORIZATIONOPS (undocumented) on the bottom.

Der hier unlesbare Callstack für den Call AUTHORIZATIONOPS (undokumentiert) unten. 


First outcome:

From those calls one can deduct that not the client is authenticating at SQL Server, but actually the procedure call itself causes Windows API calls (LOOKUPACCOUNTSID, AUTHZINITIALIZERESOURCEMANAGER) for authentication purposes.
Now at the very latest it’s time to check the ownership-chain for the stored procedure.
So I checked the header of the proc, and indeed, just as I expected it contained a “WITH EXECUTE AS OWNER”.
That alone can’t be it, so the question is, who is the owner. I already suspected it and there it was: The database was owned by a LOCAL Windows account.
Now, that is rare, but it all makes sense now: For every execution of the procedure, the ownership had to be verified – and since it is a Windows-Account, it had to go out of SQL Server OS, using a Preemptive call to Windows, wait, and continue only after Windows returns control of this thread back to SQL Server.

Erstes Ergebnis:

Aus diesen Call lässt sich ableiten, dass es nicht der Client ist, der sich bei SQL Server authentifiziert, sondern dass es tatsächlich der Procedure Call selbst ist, der Windows API Calls (LOOKUPACCOUNTSID, AUTHZINITIALIZERESOURCEMANAGER) für Authentifizierungszwecke verursacht.
Spätestens jetzt ist es an der Zeit, die Besitzerkette für die Stored Procedure zu überprüfen. Also habe ich den Kopf der Prozedur geprüft, und tatsächlich, genau wie ich erwartet hatte, enthielt es ein “WITH EXECUTE AS OWNER”.
Das allein kann es nicht sein, also stellt sich die Frage, wer der Owner ist. Ich vermutete es bereits, und da war es: Die Datenbank gehörte zu einem LOKALEN Windows-Konto.
Nun, das ist eher selten, doch jetzt ergibt alles Sinn: Für jede Ausführung der Prozedur musste der Besitz verifiziert werden – und da es ein Windows-Konto ist, musste es raus aus SQL Server OS gehen, indem ein Preemptive Call an Windows verwendet wird, dann warten, und erst dann weitermachen, nachdem Windows die Kontrolle dieses Pfades an SQL Server zurückgegeben hatte.


Testing the improvement options:

Now, obviously, I did not stop here but rather made some more tests. Based on the fact that there are 3 possible types of owner for objects within SQL Server, I compared the execution times (and waits) between those 3 possible
Database owner-types:

1.       SQL Account

2.       Windows DomainAccount

3.       Local Windows Account

- I did also test with Admin vs. non-Admin and NTLM vs. Kerberos but saw no difference.

Testen der Verbesserungsmöglichkeiten:

Natürlich hörte ich nicht hier auf, sondern machte noch weitere Tests. Ausgehend von der Tatsache, dass es mögliche Typen von Owner für Objekte innerhalb SQL Server gibt, verglich ich die Ausführungszeiten (und Wartezeiten) zwischen diesen 3 möglichen Datenbank-Owner-Types:

  1. SQL Account
  2. Windows DomainAccount
  3. Local Windows Account

- Ich testete auch mit Admin vs. non-Admin und NTLM vs. Kerberos, stellte jedoch keinen Unterschied fest. 

So here is the result of the Performance-Comparison with different Database-/Procedure-Owners:

Hier ist also das Ergebnis des Performance-Vergleichs mit unterschiedlichen Datenbank-/Procedure-Owners:





1)      The obvious: Using a local Windows Account results in a huge performance-penalty for such a simple INSERT-statement

2)      Using a Domain Account I could notice that every 10 minutes the next execution would be a bit slower.


  1. Das Offensichtliche: Die Verwendung eines lokalen Windows-Kontos führt zu eine riesigen Performance-Impakt für ein solch simples INSERT-Statement

  2. Beim Verwenden eines Domain-Kontos konnte ich sehen, dass die nächste Ausführung alle 10 Minuten etwas langsamer war. 

Further analysis

When checking the Wait-stats again, I could see that usually the Windows-Domain-Account had the following simple waits:

Weitere Analyse

Beim erneuten Überprüfen der Warte-Statistiken konnte ich feststellen, dass der Windows-Domain-Account meistens die folgenden einfachen Waits hatte: 




Pretty ok and nothing to worry about. But the first call after 10 minutes would always result in the same wait-types as I observed for the local Windows Account, except that the wait-times are much much lower. (You can compare the below picture with the one from the beginning of the article.)

Ziemlich in Ordnung und nichts, worüber man sich Sorgen machen müsste. Doch der erste Call nach 10 Minuten ergab immer dieselben Wait-Typen, die ich für das lokale Windows-Konto beobachtete, außer dass die Wartezeiten um Vieles geringer sind. (Ihr könnt das Bild unten mit dem am Anfang des Artikels vergleichen.)




Behind the Scenes: Network Tracing

To explain the difference, I ran a Network Trace using Wireshark
And exactly every 10 minutes I saw some additional KERBEROS-traffic going to the Domain Controller. Below you see the opened data frame with the Request for a Ticket Granting Service Ticket (TGS-REQ).

Hinter den Kulissen: Network Tracing

Um den Unterschied zu erklären, führte ich ein Network Trace mit Wireshark aus.
Und genau alle 10 Minuten sah ich einigen zusätzlichen KERBEROS-Traffic zum Domain Controller fließen. Unten seht ihr den geöffneten Datenrahmen mit dem Request for a Ticket Granting Service Ticket (TGS-REQ).




Background infos:

As the User, on whose behalf the service requests the service ticket, is identified using the user name and user realm/domain (SQL\SQLDBOwner in my case), the padata type PA-FOR-USER is used, as you can see in the screenshot. You can even see the Checksum added for protection.

The S4U2self extension of the PA-DATA structure allows a service to obtain a service ticket to itself on behalf of a user. The user is identified to the KDC using the user's name and realm.


Wenn der Nutzer, für den der Service das Service-Ticket anfordert, unter Verwendung des Nutzernamens und user realm/Domäne (SQL\SQLDBOwner in meinem Fall) identifiziert wird, wird der Padata Type PA-FOR-USER verwendet, wie im Screenshot zu sehen. Man kann sogar die Checksum sehen, die zum Schutz hinzugefügt wurde.

Die S4U2self Extension der PA-DATA-Struktur erlaubt einem Service, ein Service-Ticket im Auftrag eines Nutzers für sich selbst zu beziehen. Der Nutzer wird gegenüber dem KCD identifiziert, unter Verwendung des Nutzernamen und Realm. 

Luckily the DC answers right away with a TGS-REP, containing the PA-DATA-structure with ticket for the service that was named in the TGS-REQ from above:

Zum Glück antwortet der DC sofort mit einem TGS-REP, der die PA-DATA-Struktur mit einem Ticket für den oben im TGS-REQ genannten Service enthält:




There is plenty literature available if you want to learn more about the Kerberos Protocol-Elements. Here is a documentation from Microsoft:

Es gibt eine Menge an Literatur, falls ihr mehr über die Kerberos-Protokollelemente erfahren wollt. Hier ist eine Dokumentation von Microsoft:

The 10-minutes puzzle:

1) After doing some extensive testing, I conclude that the 10-minute interval after which a new Ticket Granting Service Ticket-Request is initiated must be a SQL Server specific enhancement for Domain Accounts to avoid making this round trip for every SID-validation. The 10 minutes are consistent and independent from other workload influencers. The cause behind is not documented.

2) The much faster validation for the AD-Account is very fast thanks to some caching in Windows. (Thank you, Jack Richins from formerly SQL Security Team, for reminding me of this)

3) For the local Windows Account, there is no such performance improvement via caching which results in much slower response times.

Das 10-Minuten-Puzzle:

  1. Nach ausgiebigem Testen schließe ich, dass das 10-Minuten-Intervall, nach dem ein neuer Ticket Granting Service Ticket Request eingeleitet wird, eine SQL-Server-spezifische Erweiterung für Domain-Accounts sein muss, um diese Rundreise nicht für jede SID-Validierung machen zu müssen. Die 10 Minuten sind konsistent und unabhängig von anderen Workload-Beeinflussern. Die Ursache dahinter ist nicht dokumentiert.

  2. Die viel schnellere Validierung für das AD-Konto ist so schnell dank einigem Caching in Windows. (Danke, Jack Richins vom ehemaligen SQL Security Team, der mich daran erinnert hat)

  3. Für das lokale Windows-Konto gibt es keine solche Performance-Verbesserung via Caching, was zu viel längeren Antwortzeiten führt.


Final results and learnings:

1)      Using local users for SQL Server can create noticeable impact for short transactions. Yet another reason to stay away from local accounts.

2)      For the SQL Account, naturally no Windows calls are necessary at all, but the performance-advantage compared to the AD-Account is marginal, even for high-speed scenarios.

3)      Network latency matters even between SQL Server and DC. Not just for the initial Login-phase but even for ongoing validations from within SQL-statements.

4)      I can stick to my recommendation for Database Ownerships (SQL Server Database Ownership: survey results & recommendations) :-)

Endergebnis und Gelerntes:

  1. Die Verwendung von lokalen Nutzern für SQL Server kann deutliche Auswirkungen für kurze Transaktionen verursachen. Noch ein weiterer Grund dafür, sich von lokalen Konten fernzuhalten.

  2. Für den SQL Account sind natürlich keine Windows-Calls notwendig, doch der Performance-Vorteil gegenüber dem AD-Account ist geringfügig, selbst für High-Speed-Scenarien.

  3. Netzwerk-Latenz spielt selbst zwischen SQL Server und DC eine Rolle. Nicht nur für die anfängliche Login-Phase, sondern sogar für fortlaufende Validierungen innerhalb von SQL-Statements.

  4. Ich kann meine Empfehlung für Datenbank-Ownerships aufrechterhalten (SQL Server Database Ownership: survey results & recommendations) :-)

I hope you found this an interesting read.

Ich hoffe, dies war eine interessante Lektüre für euch. 




PS: for the geeks among you:

The Stack Dump in Text format together with some comments:

P.S. Für die Geeks unter euch:

Der Stack Dump im Textformat mitsamt einigen Kommentaren:


Child-SP          RetAddr           Call Site

000000e9`2f0b79d8 00007ffe`f9e51118 ntdll!NtWaitForSingleObject+0xa

-> this function is actually deprecated (Hello, Microsoft?)

000000e9`2f0b79e0 00007ff7`04999fef KERNELBASE!WaitForSingleObjectEx+0x94
000000e9`2f0b7a80 00007ff7`04999d7d sqlservr!CDmpDump::DumpInternal+0x22f
000000e9`2f0b7b20 00007ff7`049a15b8 sqlservr!CDmpDump::DumpFilter+0xcd
000000e9`2f0b7c10 00007ffe`ef0ef2cb sqlservr!memset+0x1819
000000e9`2f0b7c40 00007ffe`fc98398d msvcr120!__C_specific_handler+0x93 [f:\dd\vctools\crt\crtw32\misc\amd64\chandler.c @ 162]
000000e9`2f0b7cb0 00007ffe`fc9493a7 ntdll!RtlpExecuteHandlerForException+0xd
000000e9`2f0b7ce0 00007ffe`fc948fbd ntdll!RtlDispatchException+0x197
000000e9`2f0b83b0 00007ffe`f9e58b9c ntdll!RtlRaiseException+0x18d
000000e9`2f0b8b70 00007ff7`04999c9c KERNELBASE!RaiseException+0x68
000000e9`2f0b8c50 00007ffe`f05602c6 sqlservr!CDmpDump::Dump+0x4c
000000e9`2f0b8c90 00007ffe`f105c411 sqllang!SQLDumperLibraryInvoke+0x1f6
000000e9`2f0b8cd0 00007ffe`f105ce94 sqllang!SQLLangDumperLibraryInvoke+0x161
000000e9`2f0b8d80 00007ffe`f102cd0b sqllang!CImageHelper::DoMiniDump+0x475
000000e9`2f0b8f90 00007ffe`f072e9c4 sqllang!stackTrace+0x9db
000000e9`2f0ba9b0 00007ffe`f072f6ae sqllang!XeSqlPkg::IsSystem+0x174
000000e9`2f0bab90 00007ffe`ef2e779a sqllang!XeSqlPkg::CreateDumpSingleThreadActionInvoke+0x1e

-> you can clearly see how this stack dump was created: XEvents

000000e9`2f0babc0 00007ffe`ef2a1b8e sqldk!XeSosPkg::wait_info_external::Publish+0x1a9

-> Now we will see our wait-type when we ask the DMVs or XEvents

000000e9`2f0bac20 00007ffe`ef2a63a4 sqldk!SOS_Scheduler::UpdateWaitTimeStats+0x596
000000e9`2f0bb530 00007ffe`f0d94fac sqldk!SOS_Task::PopWait+0xba
000000e9`2f0bb590 00007ffe`f0d9481e sqllang!CWindowsSecurityPrimaryInfo::GetNtGroupsViaAuthZ+0x75c


000000e9`2f0bb890 00007ffe`f0d956ed sqllang!CWindowsSecurityPrimaryInfo::Init+0x2ce
000000e9`2f0bba00 00007ffe`f041a88b sqllang!GetWindowsSecurityPrimaryInfo+0xbe
000000e9`2f0bba60 00007ffe`f041cadb sqllang!CreateLoginToken+0x2d7
000000e9`2f0bbc50 00007ffe`f041dca8 sqllang!CreateLoginTokenForImpersonation+0xcb2

-> an Impersonation is happening (EXECUTE AS)

000000e9`2f0bc400 00007ffe`f0358342 sqllang!CAutoExecuteAsContext::Set+0xe2d
000000e9`2f0bc680 00007ffe`f001245e sqllang!CSECExecAsRuntimeServices::_Set+0x424
000000e9`2f0bc900 00007ffe`f0012041 sqllang!CMsqlExecContext::FExecute+0x336
000000e9`2f0bcc30 00007ffe`f0d1d83d sqllang!CSQLSource::Execute+0x983
000000e9`2f0bcdd0 00007ffe`f0d1d241 sqllang!CStmtExecProc::XretLocalExec+0x26e
000000e9`2f0bce50 00007ffe`f0d19f98 sqllang!CStmtExecProc::XretExecExecute+0x481
000000e9`2f0bd600 00007ffe`f00119ca sqllang!CXStmtExecProc::XretExecute+0x38
000000e9`2f0bd640 00007ffe`f0012933 sqllang!CMsqlExecContext::ExecuteStmts<1,1>+0x40d
000000e9`2f0bd780 00007ffe`f0012041 sqllang!CMsqlExecContext::FExecute+0xa9e
000000e9`2f0bdab0 00007ffe`f0cd3f6d sqllang!CSQLSource::Execute+0x983
000000e9`2f0bdc50 00007ffe`f0ce0e6c sqllang!ExecuteSql+0x93d
000000e9`2f0be7d0 00007ffe`f0ce1549 sqllang!CSpecProc::ExecuteSpecial+0x15c
000000e9`2f0be8d0 00007ffe`f001a82b sqllang!CSpecProc::Execute+0x299
000000e9`2f0bea00 00007ffe`f0021542 sqllang!process_request+0xe61
000000e9`2f0befd0 00007ffe`f00210a3 sqllang!process_commands_internal+0x2df
000000e9`2f0bf050 00007ffe`ef2a5bfd sqllang!process_messages+0x253
000000e9`2f0bf260 00007ffe`ef2a58f5 sqldk!SOS_Task::Param::Execute+0x231
000000e9`2f0bf860 00007ffe`ef2a554d sqldk!SOS_Scheduler::RunTask+0xaa
000000e9`2f0bf8d0 00007ffe`ef2cd7c8 sqldk!SOS_Scheduler::ProcessTasks+0x3cd
000000e9`2f0bf9b0 00007ffe`ef2cdb10 sqldk!SchedulerManager::WorkerEntryPoint+0x2a1
000000e9`2f0bfa80 00007ffe`ef2cdcd7 sqldk!SystemThread::RunWorker+0x8f
000000e9`2f0bfab0 00007ffe`ef2cd9f8 sqldk!SystemThreadDispatcher::ProcessWorker+0x2de
000000e9`2f0bfb60 00007ffe`fc6e13d2 sqldk!SchedulerManager::ThreadEntryPoint+0x1d8
000000e9`2f0bfc10 00007ffe`fc9603c4 kernel32!BaseThreadInitThunk+0x22
000000e9`2f0bfc40 00000000`00000000 ntdll!RtlUserThreadStart+0x34


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


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.

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.





    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


    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: