Tag: "performance analysis"

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

 

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

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

Background:

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:

 

SET NOCOUNT ON;
SET
XACT_ABORT ON;

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

RETURN 0;

 

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;

 WaitsDMV_withCMEMTHREAD

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:

 Callstack_Windbg_CMEMTHREAD_GetNtGroupsViaAuthZ

 

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):

sqllang!CWindowsSecurityPrimaryInfo::GetNtGroupsViaAuthZ
sqllang!CreateLoginToken
sqllang!CreateLoginTokenForImpersonation

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:  

 

Callstack_XEvent_PREEMPTIVE_OS_LOOKUPACCOUNTSID_edited_2ndstack 

 

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:

 

WaitsPreemptive_XEvents_inOrder

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:

 

 ProcedureStats_by_DBOwner

 

Interpretation:

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.

Interpretation:

  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: 

 

WaitsDMV_OwnerDomainAccount

 

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

 

 WaitsDMV_OwnerDomainAccount

 

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

 

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

Hintergrundinformationen:

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:

 

 WireShark_TGS-REP

 

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. 

 

Andreas

 

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

-> this will lead to the Preemptive Wait: PREEMPTIVE_OS_AUTHZINITIALIZERESOURCEMANAGER

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

EOF

Performance overhead of tracing with Extended Event targets vs SQL Trace under CPU Load

Leistungseinbußen beim Tracing, Extended Event Ziele gegen SQL Trace unter CPU Last

(DE)

Inspiriert durch den Blog Post Post “Measuring Observer Overhead of SQL Trace vs. Extended Events” vont 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.

Especially I was interested in the following aspects:

  • 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 stehtdie 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 en 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 then 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 sind.
Der Server, wie gesagt 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 (that 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:

  • Lock acquired
  • Lock released

 

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:

 

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

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:

 

  • 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, 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:

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

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

All other options were using the defaults for these tests.

 XEvent_PerfComparison_sessions

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:

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:

 

 XEvent_PerfComparison_Runtime_Avg_EvSec

EL = Ereignissverlust. 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:

 

 XEvent_PerfComparison_Runtime_S_N_Avg_EvSec

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 much 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 even more: Tracing with SQL Profiler is absolutely impossible for such a scenario: I filled in 21 hours, but that’s actually an approximation: I stopped those test circle 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 use to 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:

 

 XEvent_PerfComparison_Runtime_Filtered_Avg

  • 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 Teyt-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 circle) 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 starting a session:

PREEMPTIVE_XE_TARGETINIT
PREEMPTIVE_XE_CALLBACKEXECUTE
PREEMPTIVE_XE_SESSIONCOMMIT

Beim Beenden einer Sitzung:

When starting a stopping a session:

PREEMPTIVE_XE_SESSIONCOMMIT
XE_BUFFERMGR_ALLPROCESSED_EVENT
PREEMPTIVE_XE_CALLBACKEXECUTE

 Während Sessions aktiv sind, sieht man:

While running sessions you will see:

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:

For starting the File target you will also see:

PREEMPTIVE_XE_TARGETINIT

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

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, das 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 than to take away (CPU) resources.

 

Happy Tracing

 

Andreas

PS: I just discovered that my MCM and SQLSkills-class buddy Steven Ormrod an 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/

Survey: Which Tracing and Analysis-Tools do you use for SQL Server?

 Umfrage: Welche Tracing und Analyse-Tools verwendet ihr für SQL Server?

(DE)
In meiner Session „Hasta la vista Profiler – Tracing with Extended Events“, die ich nun seit über einem Jahr bei diversen Gelegenheiten gehalten habe, habe ich die Zuhörer meist gefragt, welche Monitoring-Tools sie bisher verwendeten.

Ich möchte diese Stelle einmal nutzen, um einmal breit zu erheben, welche Werkzeuge von SQL Server Professionals zur Protokollierung und Analyse von Performance-Problemen verwendet werden. Um ein differenzierteres Bild zu erhalten, ist auch eine Einordnung in „Administrator“, und „Entwickler“ sicherlich interessant.

Die Ergebnisse werde ich auf dem kommenden SQLSaturday #230 am 12. Juli in St. Augustin auf der PreCon, „From SQL Traces to Extended Events. The next big switch.“, die ich zusammen mit Mladen Prajdic gebe, präsentieren, und später mit Sicherheit noch auf dem PASS Camp sowie bei weiteren Gelegenheiten der deutschen und auch internationalen PASS - und natürlich hier in meinem Blog selber. Die Antworten können natürlich auch anonym abgegeben werden.

Im Folgenden liste ich eine Reihe von geläufigen Tools auf.

Bitte gebt Eure Stimme einfach als Kommentar wie im folgenden Beispiel ab - ich gebe ALLE Antworten (außer reinem Spam und Werbung) frei, auch Oracle-Tools ;-)

(EN-US)
In my session Session „Hasta la vista Profiler – Tracing with Extended Events“, that I have been presenting at several occasions, I used to ask the audience, which tools they used for monitoring so far.

I would like to use this platform to survey on a broader range, which tools are being used by SQL Server professionals for logging and analyzing performance-problems. In order to get a differentiated result, a classification in “Administrator” and “Developer” is certainly also interesting.

The results will be presented first at the upcoming SQLSaturday #230 on the 12th of Juli in St. Augustin/Germany at the PreCon, From SQL Traces to Extended Events. The next big switch.“, which I will be giving together with Mladen Prajdic gebe, and later on certainly also at the PASS Camp and other occasions of the German and international PASS - and of course also here in my blog itself. You can of course also keep your comments anonymously.

In the following I am listing a series of common tools.

Please simply provide your vote as a comment like in the following example – I will publish ALL answers (except plain spam/ads), even Oracle-Tools ;-)

„Administrator and/or Developer“
A 3
B 1
D 2
L 0

Dabei stehen die Zahlen für // The numbers stand for:

3: fast immer // almost all the time
2: manchmal // sometimes
1: selten // rarely
-1: das Tool ist mir unbekannt // I haven't hear of this tool

- Die Auswahl “unbekannt” auf Anregung eines Lesers (Danke!).

Werkzeuge, die nie verwendet werden gerne einfach weglassen.

Und das ist die Auswahl an Tools:

The choice “unknown” at a reader’s suggestion (Thank you!).

Tools that are not used can be simply left out.

And these are the choices of tools:

A) ClearTrace
B) Datenbankoptimierungsratgeber // Database Engine Tuning Advisor
C) Dynamic Management Views (DMV's)
D) Event Notifications
E) Extended Events unter 2008/R2
F) Extended Events unter 2012
G) Management Datawarehouse (MDW) / Data Collection Reports
H) PAL
I) PerfMon
J) RML Utilities / ReadTrace
K) SQL Diag
L) SQL Profiler
M) SQL Trace
N) Software von Drittherstellern – siehe auch O) // Third-Party Tools - also see O)
O) Andere // Other: …

- Die Reihenfolge ist alphabetisch und soll nichts implizieren :-)

Meine Liste enthält ausschließlich mit SQL Server gelieferte, sowie codeplex-Tools, es können aber auch andere angegeben werden. (Punkt „O“)

Mir ist natürlich völlig bewusst, das auch die SQL Server Version und ggf. Edition Einfluss auf die zur Verfügung stehende Auswahl hat, aber ich möchte die Umfrage auch nicht zu komplex gestalten. Das Ziel, einen Eindruck über die Verbreitung der Tracing-Gewohnheiten zu erreichen, wird so sicherlich erreicht werden können :-)

Vielen Dank an dieser Stelle schon einmal für die Beteiligung - ich bin sicher, dass es auch viele andere Community-Mitglieder gern sehen, was andere so für ihre Arbeit einsetzen.

- The order is alphabetical and not supposed to imply anything :-)

My list contains solely tools shipped with SQL Server and from codeplex, but feel free to add others (point “O”)

I am totally aware that also the SQL Server version and possibly edition have an influence on the choices available, but I also do not want to make the survey all too complex. The aim, to gain an impression on the prevalence and practices of tracing-habits will certainly be reached like that, too :-)

Thank you very much for participating – I am sure that many members of the SQL Server Community are also interested to see, what others use for their work.

Andreas

Extended Event File Target size vs SQL Server Trace trace file - a comparison

No big science, more out of curiosity this time..

The Extended Events File Target for SQL Server saves data using xml, which as is well known, is a bit “chatty”. A student in my recent SQL Server Master-Class workshop on extended events came up with the question for how much (more) space he would have to account for using Extended Events with a file target. Although this depends greatly on the specific events and possibly actions, selected, I was a bit curious myself and decided for a small test.

Both, the old and deprecated SQL Server Trace and Extended Events can save the data in a file, so it’s easy to compare what difference in size the new format will make.

I set up a SQL Server Trace that is almost identical to an Extended Events Trace. (You will see why “almost”.)

I had to choose a very simple Trace, so the customizable columns of extended events would not make the comparison unequal and ended up with a trace that captures SP:Starting/SP:Completed with the following columns:

You will see why I collect Source/DatabaseID twice later on.
Of course I used a lightweight Server-Trace, although for the purpose of this comparison it would not have mattered.

The SQL Trace definition:

exec sp_trace_setevent@TraceID, 43, 3, @on
exec
sp_trace_setevent@TraceID, 43, 5, @on
exec
sp_trace_setevent@TraceID, 43, 12, @on
exec
sp_trace_setevent@TraceID, 43, 13, @on
exec
sp_trace_setevent@TraceID, 43, 22, @on
exec
sp_trace_setevent@TraceID, 43, 28, @on
exec
sp_trace_setevent@TraceID, 43, 34, @on
exec
sp_trace_setevent@TraceID, 43, 48, @on
exec
sp_trace_setevent@TraceID, 43, 62, @on
exec
sp_trace_setevent@TraceID, 42, 3, @on
exec
sp_trace_setevent@TraceID, 42, 5, @on
exec
sp_trace_setevent@TraceID, 42, 12, @on
exec
sp_trace_setevent@TraceID, 42, 22, @on
exec
sp_trace_setevent@TraceID, 42, 28, @on
exec
sp_trace_setevent@TraceID, 42, 34, @on
exec
sp_trace_setevent@TraceID, 42, 62, @on 

declare @intfilter int
declare
@bigintfilter bigint

 set @intfilter = 7

exec sp_trace_setfilter@TraceID, 62, 0, 0, @intfilter

As you might see the trace includes a filter, which is for a specific database ID.

The Extended Event Trace session looks like that:

CREATE EVENT SESSION [ModulesStartEnd_ToFile]
ON
SERVER
ADD
EVENT sqlserver.module_start(
    WHERE ([source_database_id]=(7))),

ADD
EVENT sqlserver.module_end(
    WHERE ([source_database_id]=(7)))

ADD
TARGET package0.event_file
   
(SET filename=N'R:\Tracing\XE\ModulesStartEnd.xel', max_file_size=(10240))
WITH
(MAX_MEMORY=
4096 KB, EVENT_RETENTION_MODE=NO_EVENT_LOSS,  MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB, MEMORY_PARTITION_MODE=NONE, TRACK_CAUSALITY=OFF, STARTUP_STATE=OFF)

You may know, that Extended Events include certain columns by default, and for module_start/end, this includes offset and offset_end.
 

Those two columns are not available for SP_Staring/SP:Completed in SQL Trace. Since they are both integers, I decided to include another column, DatabaseID, into the SQLTrace. SQL Trace also includes the SPID by default, which cannot be deselected, therefore those two columns should equalize it.
Both traces were started before the workload which ran for a while. At the end, the same number of events have been logged by both technologies in parallel.

SQL Trace event count:

XEvent Trace event count:



100644 + 100644 = 201288, so both captured the exact same events. :-)

So, and now to the final question: what size are the files?

See yourself:

Size in Megabytes:


 
(The numbers in MB are the real size, whereas windows explorer shows the size on disk.)
That’s a difference of 5.32MB or in other words 29.13%.

And this is what one single module_start-event for a function call in XEvents looks like:

<eventname="module_start"package="sqlserver"timestamp="2013-06-08T18:41:48.780Z">
<
dataname="source_database_id"><value>7</value></data>
<
dataname="object_id"><value>103671417</value></data>
<
dataname="line_number"><value>1</value></data>
<
dataname="offset"><value>0</value></data>
<
dataname="offset_end"><value>-1</value></data>
<
dataname="object_type"><value><![CDATA[TF]]></value></data>
<
dataname="object_name"><value><![CDATA[ufnGetContactInformation]]></value></data>
<dataname="statement"><value></value></data>
</
event>

The content is self-explanatory, as xml is supposed to be, and the overhead in size is no surprise at all.

Keep in mind that this post is purely on comparing file sizes, and not performance or features. There are good reasons that SQL Trace & Profiler have been deprecated, and Extended Events in SQL Server 2012 overcomes SQL Trace & Profiler by far, in performance as well as in flexibility/usability.
For a performance overhead comparision check out my recently published benchmark blog post: "Performance overhead of tracing with Extended Event targets vs SQL Trace under CPU Load".

So whenever performance matters, remember to set session options appropriately and if the amount of events is high, do not use your slowest volume for the file target - same as for all other tracing activities anyways.

happy tracing,

Andreas

Tracing Analysis Services (SSAS) with Extended Events – Yes it works and this is how

Tracing Analysis Services mit Extended Events – Ja, es geht, und zwar so

or: “Hasta la vista, Profiler”... ;-)

(en)
One of the features new in Analysis Services 2012 is the support of the SQL Server Extended Events Framework.

While there is no GUI support for that, yet, it is however possible to set up a XEvent session via DDL commands - just like it was in the “old days” with SQL Server 2008/ 2008 R2, until 2012 brought the GUI.

Since I have been asked a lot at my sessions on Extended Events on how it is done in Analysis Services, and the Books Online sample code is not really working (“Use SQL Server Extended Events (XEvents) to Monitor Analysis Services
http://msdn.microsoft.com/en-us/library/gg492139.aspx”), I will show a quick example here.

The following code creates a session to collect the deadlocks events from the Analysis Services Instance:

(de)
Eines der in Analysis Services 2012 neuen Features ist die Unterstützung des SQL Server Extended Events Frameworks.

Obwohl dafür noch keine grafische Unterstützung da ist, ist es jedoch möglich eine XEvent Session über DDL Kommandos aufzusetzen - genau wie in den alten Zeiten” mit SQL Server 2008/ 2008 R2, bis 2012 die GUI brachte.

Da ich im Zuge meiner Sessions zu Extended Events häufig gefragt wurde, wie das bei Analysis Services funktioniert, und das Books Online Beispiel nicht wirklich funktioniert (“Use SQL Server Extended Events (XEvents) to Monitor Analysis Services
http://msdn.microsoft.com/en-us/library/gg492139.aspx”), zeige ich hier ein kurzes Beispiel.

Der folgende Code erzeugt eine Session um Deadlock Events von einer Analysis Services Instanz mitzuschneiden:

<Create xmlns="http://schemas.microsoft.com/analysisservices/2003/engine"
mlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:ddl2="http://schemas.microsoft.com/analysisservices/2003/engine/2"
xmlns:ddl3="http://schemas.microsoft.com/analysisservices/2003/engine/3"
xmlns:ddl100_100="http://schemas.microsoft.com/analysisservices/2008/engine/100/100"
xmlns:ddl200_200="http://schemas.microsoft.com/analysisservices/2010/engine/200/200"
xmlns:ddl300_300="http://schemas.microsoft.com/analysisservices/2011/engine/300/300">
    <
ObjectDefinition>
        <
Trace>
            <
ID>Sarpedon AS Trace Demo</ID>
            <
Name>Sarpedon AS Trace Demo</Name>
            <
ddl300_300:XEvent>                <event_session name="SQL_AS_XE" dispatchLatency="10" maxEventSize="4" maxMemory="4" memoryPartitionMode="none">
                    <
event package="AS" name="Deadlock" />
                    <
target package="Package0" name="event_file">
<
parameter name="filename" value="D:\SQLData\SarpedonASDeadlockTrace.xel" />
                    </
target>
                </
event_session>
            </
ddl300_300:XEvent>
        </
Trace>
    </
ObjectDefinition>
</
Create>

As one can see, the definition like session configuration and targets, is quite similar to SQL Server, since it is in fact based on the same architecture.
The package containing the events is "AS", whereas targets come from our well known "Package0". The one familiar with XEvents will know, what this implicates - more maybe in a later post.

Via the internal system view $system.discover_traces, we can see the active traces on the instance: the “FlightRecorder” which is still using the old-style Tracing technology (I wonder when Microsoft will add a new one just like system_health in SQL Server) and my sample session. You will also note, that the XEvent session’s trace file name is not visible here.

Wie man sehen kann, ist die Definition wie Session-Konfiguration und Targets recht ähnlich zu SQL Server, da es tatsächlich auf der selben Architektur basiert.
Das Package welches die Events enthält, ist "AS", wohingegen die Targets aus dem bereits bekannten "Package0" stammen. Wer bereits mit XEvents vertraut ist, wird wissen, was das impliziert - mehr vielleicht in einem späteren Post.

Über die interne Systemsicht $system.discover_traces können wir die aktiven Traces auf der Instanz sehen: der “FlightRecorder”, der noch die alte Tracing Technik verwendet (Ich frage mich, wann Microsoft eine Neue, wie die system_health in SQL Server hinzufügen wird), und meine Beispiel-Sitzung. Man sieht auch, das der Trace Dateiname der XEvent-Session hier nicht sichtbar ist.

 Trace Sessions

To access the collected data one can easily stop and delete the session by name as follows:

Um auf die gesammelten Daten zuzugreifen, kann man die Trace session wie folgt bequem über den Namen beenden und löschen:

 <Delete xmlns="http://schemas.microsoft.com/analysisservices/2003/engine"
xmlns:ddl300_300="http://schemas.microsoft.com/analysisservices/2011/engine/300/300"
xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/">
    <
Object>
        <
TraceID>Sarpedon AS Trace Demo</TraceID>
    </
Object>
</
Delete>

The collected data can be viewed, aggregated and filtered as normal with the Extended Events Viewer in Management Studio.
Here a sample with query runtimes:

Die gesammelten Daten lassen sich dann wie gewohnt über den Extended Events Viewer in Management Studio ansehen, aggregieren und filtern.
Hier ein Beispiel mit Query-Laufzeiten:

XEvent Viewer

In the detail pane on the bottom you can notice, that I turned on causality tracking here. Hence the activity ID /GUID correlate activity.

Im Detailbereich kann man sehen, das ich hier auch “Kausalitätstracking” eingeschaltet habe. Daher die activity ID/GUI um Aktivitäten zu korrelieren.

So as you see, for a fact, the Analysis Services engine has been extended to be using the Extended Events architecture for better performing and more flexible Tracing.
I do expect some more GUI-support for Managing XEvents in Analysis Services in the next major release.


Have fun, playing around with the sample. :-)

From now on there is no excuse any more, to burden an Analysis Server that is already on its knees with Profiler...

Wie man sehen kann, sind die Analysis Services tatsächlich erweitert worden um die Extended Events Architektur für performanteres und flexibleres Tracing zu verwenden.
Mit dem nächsten Major-Release des SQL Server erwarte ich mehr GUI-Unterstützung  für die Verwaltung von XEvents in Analysis Services.

Viel Spaß beim Herumspielen mit dem Beispiel. :-)

Ab jetzt gibt es keine Entschuldigung mehr, einen Analysis Server, der bereits auf den Knien ist, weiter mit dem Profiler zu belasten...

                      “Hasta la vista, Profiler” ;-)

Hopefully by MCM buddy and friend Reeves Smith will soon write his promised post on Tracing Analysis Services, maybe with a Performance Comparison.
”So, now you have to get going, Reeves!” :-D

Hoffentlich wird mein MCM Kollege und Freund seinen versprochenen Post über XEvent Tracing Analsis Services bald einlösen – vielleicht mit einem Performance-Vergleich.
”So, nun musst Du aber loslegen, Reeves!” :-D

Meanwhile I’d like to refer you to this article from another fellow MCM, Jonathan Kehayas, where you can see the enormous difference in terms of negative performance-impact of tracing via Profiler and SQL Trace vs XEvents:

Bis dahin verweise ich gerne auf diesen Artikel eines andern MCM Kollegen, Jonathan Kehayas, wo man den gewaltigen Unterschied des negativen Performance-Einflusses von Tracing mittels profiler aund SQL Trace gegenüber Extended Events sieht:

 www.sqlperformance.com/2012/10/sql-trace/observer-overhead-trace-extended-events

Update: I conducted an excessive benchmarking on Extended Events and SQL Trace & Profiler myself now. The results ar now public and can be found here:

Update: Ich habe nun selber ein exzessives Benchmarking zu Extended Events und SQL Trace & Profiler durchgeführt. Die Ergebnisse sind hier nun auch öffentlich und können hier gefunden werden:

www.insidesql.org/blogs/andreaswolter/2013/08/performance-overhead-tracing-extended-events-sql-trace-under-cpu-load

 

Andreas

 

Hinweis: es wird noch im 1. HJ 2013 einen zweiten Termin für die Master-Class Seminare zu Extended Events geben (13. und 14. Juni). 

Die nächste Möglichkeit ist am 22.11. bzw. 25.11.2013!

http://www.sarpedonqualitylab.com/SQL_Master-Classes.htm