Im letzten Monat bin ich bei einem Kunden im Einsatz gewesen, der Microsoft Dynamics 365 im Einsatz hat. Trotz optimaler Hardware und sehr gut konfiguriertem Microsoft SQL Server konnten Daten aus dem Änderungsprotokoll für Kundeninformationen nicht eingesehen werden da die Abfragen in einen Timeout liefen. Die Aufgabe bestand darin, die Probleme zu erkennen, analysieren und mit einer probaten Lösung zu beheben. Ich bin kein Experte für Dynamics 365 aber dieser Artikel soll zeigen, wie man Probleme, die im Zusammenhang mit Microsoft SQL Server stehen, angehen kann, um anschließend mögliche Lösungen implementieren zu können.

Inhaltsverzeichnis

Datenbank-Audit
- Server Audit
- Datenbank Audit
Auslesen des Ausführungsplans OHNE “OPTIMIZE FOR UNKOWN”
Erzwingen des Ausführungsplans

Problembeschreibung

Bei der Auflistung von AUDIT-Daten in Dynamics 365 werden in der Weboberfläche Timeouts generiert, wenn Kundeninformationen mit einer großen Anzahl von Änderungen abgefragt werden. Für die Ermittlung der entsprechenden Daten wird in Dynamics 365 eine View [dbo].[Audit] verwendet.

Lösungsschritte

Zunächst musste ermittelt werden, welche Abfrage der Webserver gegen die Datenbank ausführt. Die Idee war, mit Hilfe einer Datenbank-Überwachung alle Abfragen abzufangen, die auf die View [dbo].[AUDIT] ausgeführt werden. Somit können alle mit der View in Verbindung stehenden Abfrageausführungen protokolliert und analysiert werden.

Datenbank-Audit

Mithilfe von SQL Server Audit können Serverüberwachungen erstellt werden, die Serverüberwachungsspezifikationen für Ereignisse auf Serverebene sowie Datenbank-Überwachungsspezifikationen für Ereignisse auf Datenbankebene beinhalten können. Überwachte Ereignisse können in die Ereignisprotokolle oder Überwachungsdateien geschrieben werden. Alle Editionen von SQL Server unterstützen Überwachungen auf Serverebene. Alle Editionen ab SQL Server 2016 (13.x) SP1 unterstützen Überwachungen auf Datenbankebene. Zuvor war die Überwachung auf Datenbankebene auf die Editionen Enterprise, Developer und Evaluation beschränkt. Eine Überwachung besteht aus mehreren Elementen, die in einem einzelnen Paket für eine bestimmte Gruppe von Server- oder Datenbankaktionen zusammengefasst werden.

Server Audit

Das SQL Server Audit -Objekt listet eine einzelne Instanz an Aktionen oder Aktionsgruppen auf Server- oder Datenbank-Ebene auf, die überwacht werden soll.

CREATE SERVER AUDIT [Monitor AuditLog Table]
TO FILE 
(
    FILEPATH = N'F:\TraceFiles'
    ,MAXSIZE = 5 MB
    ,MAX_FILES = 1
    ,RESERVE_DISK_SPACE = OFF
)
WITH
(
    QUEUE_DELAY = 1000
    ,ON_FAILURE = CONTINUE
);
GO

Datenbank Audit

Die Datenbank-Überwachungsspezifikation listet viele Überwachungsaktionen auf Datenbankebene auf, die von erweiterten Ereignissen ausgelöst werden. Überwachungsereignisse sind die unteilbaren Aktionen, die von der SQL Server-Engine überwacht werden können.

CREATE DATABASE AUDIT SPECIFICATION [AuditLog-Table]
FOR SERVER AUDIT [Monitor Audit View]
ADD
(
    SELECT ON OBJECT::[dbo].[Audit] BY [public]
);
GO

Der erste Code erstellt die Server-Überwachung, die anschließend für die Erstellung der Datenbanküberwachung verwendet wird. Die gesammelten Informationen werden in einem Tracefile auf F:\TraceFiles gespeichert.

Identifikation der Abfrage

Durch die Überwachung konnten immer wiederkehrende identische Abfragen identifiziert werden, die gegen die Datenbank ausgeführt wurden. Die Abfrage ist stark gekürzt, da – bedingt durch das Entity-Framework – eine Menge Overhead erzeugt wird, der für die Analyse nicht relevant ist.

SELECT TOP 251
       "audit0".AuditId AS "auditid",
       ...
FROM   Audit AS "audit0" WITH ( NOLOCK )
WHERE  (
          "audit0".ObjectTypeCode = @ObjectTypeCode0
          AND "audit0".ObjectId = @ObjectId0
       )
       OR
       (
          "audit0".Action = @Action0
          AND "audit0".ObjectTypeCode = @ObjectTypeCode1
          AND "audit0".ObjectId = @ObjectId1
       )
       ...
ORDER BY
          "audit0".CreatedOn DESC ,
          "audit0".AuditId DESC
OPTION ( OPTIMIZE FOR UNKNOWN );

Mit Hilfe der Überwachungsaufzeichnung konnte die Abfrage identifiziert werden, die gegen die Tabelle ausgeführt wird; Werte der Parameter werden jedoch im Audit nicht aufgezeichnet. Aus diesem Grund habe ich mich in einer zweiten Phase dazu entschlossen, mit Hilfe des Profilers die Abfragen gegen die View [dbo].[Audit] abzufangen. Dadurch war es möglich, auch die Werte der Variablen zu protokollieren um die vollständige Abfrage inklusive Parameterwerten auswerten zu können.

Die vollständige Abfrage habe ich im Anschluss unmittelbar in Microsoft SQL Server Management Studio ausgeführt und festgestellt, dass die Abfrage fast 6 Minuten benötigte, um 250 Datensätze an den Client zu liefern!!! Die Analyse des Ausführungsplans hat auch schnell gezeigt, an welcher Stelle das Problem zu suchen ist.

Die View [dbo].[Audit] fragt die Tabelle [dbo].[AuditBase] ab. Der obige Ausführungsplan zeigt, dass Microsoft SQL Server für die Ermittlung der Daten einen – performanten (?) – Index Seek auf die Tabelle verwendet. Da der Index jedoch nicht alle benötigten Attribute bereitstellt, muss ein zusätzlicher Key Lookups für jeden gefundenen Indexeintrag weitere Informationen aus der Tabelle lesen.

Wie man erkennen kann, besteht zwischen der “geschätzten” Anzahl von Datensätzen und der tatsächlich ermittelten Anzahl von Datensätzen ein eklatanter Unterschied. Da Microsoft SQL Server mit ca. 20.000 Datensätzen gerechnet hat, hat der Optimizer sich für eine – aus Sicht der tatsächlichen Datenmenge – schlechte Strategie entschieden. Für die Ausführung bedeutete die Analyse, dass Microsoft SQL Server nicht 20.000 mal Werte aus der Tabelle holen muss sondern 9.000.000 Einzelzugriffe durchführen muss!

Die Abbildung zeigt, dass die Abfrage ca. 2,8 TB (!) im Speicher durchsucht hat; dafür hat Microsoft SQL Server knapp 5:30 Minuten benötigt.

Ursache der schlechten Performance

Warum verschätzt sich Microsoft SQL Server so eklatant bei der Ermittlung der Anzahl der Datensätze? Die Überprüfung der Statistiken ergab, dass alle Statistiken aktuell waren und minimale Änderungen seit der letzten Aktualisierung vorhanden waren. Die Untersuchung des Histogramms der betroffenen Statistik hat dann aber sehr schnell gezeigt, dass die Datenmenge ungleichmäßig verteilt ist. Und plötzlich war die Ursache sehr schnell gefunden.

Die oben gezeigte Abfrage verwendet folgenden Abfragehinweis:

OPTION ( OPTIMIZE FOR UNKNOWN )

Über die Nachteile dieser Option habe ich bereits im Artikel “OPTIMIZE FOR UNKNOWN eine schlechte Lösung bei schlechter Verteilung von Daten” ausführlich geschrieben. Diese Option wird häufig verwendet, um “Parameter Sniffing” oder “Ascending Key” Probleme zu vermeiden. Diese Option zwingt den Query Optimizer, nicht das Histogramm eines Statistikobjekts sondern den Density Vektor zu verwenden. Der Density Vektor beschreibt die durchschnittliche Datenmenge pro Indexwert.

Abfrage ohne Verwendung des Density Vektors

In einem erneuten Test der Abfrage habe ich den Abfragehinweis entfernt und die Laufzeit konnte eklatant nach unten korrigiert werden. Statt ~6 Minuten benötigte die Abfrage nur noch einen Bruchteil der Zeit.

Implementierung

Nachdem der Fehler erkannt und eine Lösung greifbar war, ist die Implementierung die nächste große Frage gewesen. Problematisch an den Abfragen ist, dass sie nicht in Stored Procedures, Funktionen, etc. innerhalb von Microsoft SQL Server generiert werden, sondern aus der Applikation selbst kommen. Somit war eine Anpassung der Abfrage nicht möglich. Der Kunde setzt auch noch keinen Microsoft SQL Server 2016 ein; dann hätte man mit Hilfe des Query Stores die Abfragen zwingen können, einen besseren Ausführungsplan zu verwenden. Aus diesem Grund wurde Microsoft SQL Server mit Hilfe eines Plan Guides gezwungen, einen Ausführungsplan zu verwenden, der die Option „OPTIMIZE FOR UNKNOWN“ ignoriert.

Auslesen des Ausführungsplans OHNE “OPTIMIZE FOR UNKOWN”

Zunächst muss der optimierte Ausführungsplan aus dem Plan Cache ausgelesen werden. Man kann zwar den Ausführungsplan im XML-Format an einen Plan Guide binden; ist aber nicht zu empfehlen!

DECLARE @xml_showplan nvarchar(max);
SET     @xml_showplan =
        (
            SELECT query_plan
            FROM   sys.dm_exec_query_stats AS qs
                   CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) AS st
                   CROSS APPLY sys.dm_exec_text_query_plan(qs.plan_handle, DEFAULT, DEFAULT
        ) AS qp
        WHERE  st.text LIKE N'%top 251%--OPTION%'
        AND st.text NOT LIKE '%dm_exec_sql_text%'

Der Trick ist trivial. Ich habe aus dem Originalstatement einfach die Option “OPTION (OPTIMIZE FOR UNKNOWN)” mit Spiegelstrichen auskommentiert und suche gezielt im Plan Cache nach dieser Zeichenfolge. Der Ausführungsplan wird in der Variablen @xml_showplan gespeichert. Somit bin ich sicher, dass keine Fehler im XML sein können.

Erzwingen des Ausführungsplans

Im letzten Schritt wird mit Hilfe der Systemprozedur sp_create_plan_guide für das betroffene Statement der zu verwendende Ausführungsplan für de betroffene Abfrage in der Datenbank hinterlegt.

EXEC sp_create_plan_guide
     @name = 'AuditList',
     @stmt = N'select
top 251 "audit0".AuditId as "auditid"
, …
, "audit0".ObjectIdName as "objectidname" 
from
    Audit as "audit0" WITH (NOLOCK)
where
    ....
OPTION (OPTIMIZE FOR UNKNOWN)',
    @module_or_batch = NULL,
    @params = N'@ObjectTypeCode0 int,...',
    @type = N'SQL',
    @hints = @xml_showplan;
GO

Weblinks

Vielen Dank fürs Lesen!

Optimierung von Dynamics 365