Ich habe versucht, Verzögerungen in einer Anwendung zu diagnostizieren. Zu diesem Zweck habe ich die erweiterten SQL Server- Ereignisse protokolliert .

• Für diese Frage schaue ich auf eine bestimmte gespeicherte Prozedur.
• Es gibt jedoch einen Kernsatz von einem Dutzend gespeicherter Prozeduren, die gleichermaßen für eine Untersuchung von Äpfeln zu Äpfeln verwendet werden können
• und wann immer ich eine der gespeicherten Prozeduren manuell ausführe, läuft es immer schnell
• und wenn ein Benutzer es erneut versucht: es wird schnell ausgeführt.

Die Ausführungszeiten der gespeicherten Prozedur variieren stark. Viele der Ausführungen dieser gespeicherten Prozedur werden in <1s zurückgegeben:

Und für diesen "schnellen" Eimer ist es viel weniger als 1s. Tatsächlich sind es ungefähr 90 ms:

Aber es gibt einen langen Schwanz von Benutzern, die 2s, 3s, 4s Sekunden warten müssen. Einige müssen 12s, 13s, 14s warten. Dann gibt es die wirklich armen Seelen, die 22s, 23s, 24s warten müssen.

Nach 30 Sekunden gibt die Clientanwendung auf, bricht die Abfrage ab und der Benutzer musste 30 Sekunden warten .

Korrelation, um die Ursache zu finden

Also versuchte ich zu korrelieren:

• Dauer vs logische Lesevorgänge
• Dauer im Vergleich zu physischen Lesevorgängen
• Dauer vs CPU-Zeit

Und keiner scheint eine Korrelation zu geben; keiner scheint die Ursache zu sein

• Dauer im Vergleich zu logischen Lesevorgängen : Egal, ob einige oder viele logische Lesevorgänge, die Dauer schwankt immer noch stark :

  

• Dauer im Vergleich zu physischen Lesevorgängen : Auch wenn die Abfrage nicht aus dem Cache bereitgestellt wurde und viele physische Lesevorgänge erforderlich waren, wirkt sich dies nicht auf die Dauer aus:

  

• duration vs cpu time : Unabhängig davon, ob die Abfrage 0 s CPU-Zeit oder 2,5 s CPU-Zeit in Anspruch nahm, haben die Zeitdauern dieselbe Variabilität:

  

Bonus : Mir ist aufgefallen, dass die Zeitdauer (Duration v Physical Reads) und die Zeitdauer ( Duration v CPU Time) sehr ähnlich sind. Dies ist bewiesen, wenn ich versuche, die CPU-Zeit mit den physischen Lesezugriffen zu korrelieren:

Es stellt sich heraus, dass die CPU-Auslastung häufig durch E / A-Vorgänge verursacht wird. Wer wusste!

Also, wenn es nichts mit der Hinrichtung zu tun hat der Abfrage gibt, was die Unterschiede in der Ausführungszeit erklären könnte, bedeutet das dann, dass es sich nicht um CPU oder Festplatte handelt?

Wenn die CPU oder die Festplatte der Engpass wäre; Wäre es nicht der Engpass?

Wenn wir davon ausgehen, dass die CPU der Engpass war; dass die CPU für diesen Server unterlastet ist:

• Dann würde die Ausführung mit mehr CPU-Zeit nicht länger dauern?
• wie müssen sie sich mit anderen über die überlastete CPU erledigen?

Ähnliches gilt für die Festplatten. Wenn wir davon ausgehen, dass die Festplatte ein Engpass war; dass die Festplatten nicht genug zufälligen Durchsatz für diesen Server haben:

• Dann würde die Ausführung mit mehr physischen Lesevorgängen nicht länger dauern.
• da sie mit anderen über die überlastete Festplatte I / O vervollständigen müssen?

Die gespeicherte Prozedur selbst führt keine Schreibvorgänge aus und erfordert auch keine Schreibvorgänge.

• Normalerweise werden 0 Zeilen (90%) zurückgegeben.
• Gelegentlich wird 1 Zeile (7%) zurückgegeben.
• In seltenen Fällen werden 2 Zeilen zurückgegeben (1,4%).
• Und im schlimmsten Fall hat es mehr als 2 Zeilen zurückgegeben (einmal 12 Zeilen zurückgegeben)

Es ist also nicht so, als würde es ein verrücktes Datenvolumen zurückgeben.

Server-CPU-Auslastung

Die Prozessorauslastung des Servers liegt im Durchschnitt bei 1,8%, mit einem gelegentlichen Anstieg von bis zu 18%. Die CPU-Auslastung scheint also kein Problem zu sein:

Die Server-CPU scheint also nicht überlastet zu sein.

Aber der Server ist virtuell ...

Etwas außerhalb des Universums?

Das einzige, was ich mir noch vorstellen kann, ist etwas, das außerhalb des Universums des Servers existiert.

• wenn es nicht logisch liest
• und es ist nicht physisch liest
• und es ist nicht CPU-Auslastung
• und es ist keine CPU-Last

Und es ist nicht so, als wären es die Parameter für die gespeicherte Prozedur (da dieselbe Abfrage manuell ausgegeben wird und es keine 27 Sekunden dauert - es dauert ~ 0 Sekunden).

Was sonst noch dazu führen könnte, dass der Server manchmal 30 Sekunden anstatt 0 Sekunden benötigt, um dieselbe kompilierte gespeicherte Prozedur auszuführen.

• Kontrollpunkte?

Es ist ein virtueller Server

• der Host überlastet?
• eine andere VM auf demselben Host?

Durchlaufen der erweiterten Ereignisse des Servers; Es passiert nichts Besonderes, wenn eine Abfrage plötzlich 20 Sekunden dauert. Es läuft gut und entscheidet sich dann, nicht gut zu laufen:

• 2 Sekunden
• 1 Sekunde
• 30 Sekunden
• 3 Sekunden
• 2 Sekunden

Und es gibt keine anderen besonders anstrengenden Gegenstände, die ich finden kann. Es ist nicht während der Sicherung jedes 2-stündigen Transaktionsprotokolls.

Was sonst könnte es noch sein?

Was kann ich außer "dem Server" noch sagen? ?

Bearbeiten : Korrelieren Sie nach Tageszeit

Mir wurde klar, dass ich die Dauer mit allem in Beziehung gesetzt habe:

• logische Lesevorgänge
• physische liest
• CPU auslastung

Aber das einzige, womit ich es nicht in Beziehung gesetzt habe, war die Tageszeit . Vielleicht ist die jeder-2-Stunden - Transaktionsprotokollsicherung ist ein Problem.

Oder vielleicht die Verlangsamungen Sie treten in Futter während Checkpoints?

Nee:

Intel Xeon Gold Quad-Core 6142.

Bearbeiten - Es wird eine Hypothese zum Ausführungsplan für Abfragen aufgestellt

Die Leute gehen davon aus, dass die Ausführungspläne für Abfragen zwischen "schnell" und "langsam" unterschiedlich sein müssen. Sie sind nicht.

Und das sehen wir sofort an der Inspektion.

Wir wissen, dass die längere Fragendauer nicht auf einen "schlechten" Ausführungsplan zurückzuführen ist:

• eine, die logischer gelesen wurde
• eine, die durch mehr Joins und Schlüsselsuchen mehr CPU verbraucht

Denn wenn eine Zunahme der Lesezugriffe oder eine Zunahme der CPU eine Ursache für eine längere Abfragedauer gewesen wäre, hätten wir dies bereits oben gesehen. Es besteht keine Korrelation.

Versuchen wir jedoch, die Dauer mit der Produktmetrik des CPU-Lesebereichs zu korrelieren:

Es kommt zu einer noch geringeren Korrelation - was paradox ist.

Bearbeiten : Die Streudiagramme wurden aktualisiert, um einen Fehler in Excel-Streudiagrammen mit einer großen Anzahl von Werten zu umgehen.

Nächste Schritte

Meine nächsten Schritte werden sein, jemanden dazu zu bringen, Ereignisse für blockierte Abfragen zu generieren - nach 5 Sekunden:

EXEC sp_configure 'blocked process threshold', '5';
RECONFIGURE

Es wird nicht erklärt, ob Abfragen für 4 Sekunden blockiert sind . Aber vielleicht blockiert alles, was eine Abfrage für 5 Sekunden blockiert, auch einige für 4 Sekunden.

Die Zeitlupenpläne

Hier ist der Zeitlupenplan der beiden gespeicherten Prozeduren, die ausgeführt werden:

• EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04: 00: 00.000', @EndDate = '20190726 04: 00: 00.000'
• EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04: 00: 00.000', @EndDate = '20190726 04: 00: 00.000'

Dieselbe gespeicherte Prozedur mit denselben Parametern wird hintereinander ausgeführt:

| Duration (us) | CPU time (us) | Logical reads | Physical reads | 
|---------------|---------------|---------------|----------------|
|    13,984,446 |        47,000 |         5,110 |            771 |
|     4,603,566 |        47,000 |         5,126 |            740 |

Anruf 1:

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Rufen Sie 2 an

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Es ist sinnvoll, dass die Pläne identisch sind. Es wird dieselbe gespeicherte Prozedur mit denselben Parametern ausgeführt.

Schauen Sie sich die wait_stats an und Sie werden sehen, was die größten Engpässe auf Ihrem SQL Server sind.

Vor kurzem trat ein Problem auf, bei dem eine externe Anwendung zeitweise langsam war. Das Ausführen gespeicherter Prozeduren auf dem Server selbst war jedoch immer schnell.

Die Leistungsüberwachung zeigte, dass SQL-Caches oder die RAM-Auslastung und die E / A-Vorgänge auf dem Server überhaupt keine Probleme bereiteten.

Was dazu beigetragen hat, die Untersuchung einzugrenzen, war die Abfrage der Wartestatistiken, die von SQL in gesammelt werden sys.dm_os_wait_stats

Das exzellente Skript auf der SQLSkills-Website zeigt Ihnen die, die Sie am meisten erleben. Sie können dann Ihre Suche eingrenzen, um die Ursachen zu identifizieren.

Sobald Sie wissen, welche Wartezeiten die Hauptprobleme sind, können Sie mit diesem Skript eingrenzen, in welcher Sitzung / Datenbank die Wartezeiten auftreten:

SELECT OSW.session_id,
       OSW.wait_duration_ms,
       OSW.wait_type,
       DB_NAME(EXR.database_id) AS DatabaseName
FROM sys.dm_os_waiting_tasks OSW
INNER JOIN sys.dm_exec_sessions EXS ON OSW.session_id = EXS.session_id
INNER JOIN sys.dm_exec_requests EXR ON EXR.session_id = OSW.session_id
OPTION(Recompile);

Die obige Abfrage und weitere Details stammen von der MSSQLTips-Website .

Das sp_BlitzFirstSkript von Brent Ozars Website zeigt Ihnen auch, was die Verlangsamung verursacht.