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:

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:

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: 

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.

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:

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: