Benutzer mit den meisten Antworten
"killed" exec sp_updatestats aktive Verbindungen?

Frage
-
Guten Morgen,
wir haben heute Morgen auf einem Server die Query "exec sp_updatestats" ausgeführt. Soweit so gut, tut auch alles wie es soll. Was mir aufgefallen ist, dass ich exakt vor Ausführung des Befehls 30 offene Verbindungen auf die betroffene Datenbank hatte.
Nach der Ausführung hatte ich nur noch 2-3 offene Verbindungen. Ist das ein bekannter "Nebeneffekt", oder sind hier zwei Themen vielleicht zeitgleich zu sehen.
Kurz zum Grund für "exec sp_updatestats".
Wir verzeichnen in unregelmäßigen Abständen eine immens hohe Systemlast von >95%, welche sich dann auch hartnäckig hält. Führen wir die oben aufgeführte Query durch, stabilisiert sich das System wieder bei ca. 40%.
Nun stellt sich mir halt die Frage, fällt die Systemlast wieder auf 40% weil mir die ganzen Verbindungen wegfliegen, oder durch Update Statistics?
Server: SQL Server 2012 SP 3
Server: virtueller Server auf VM-Ware
Besten Dank
Grüße
Andreas
Antworten
-
Hallo Andreas,
das eine hat DEFINITV nichts mit dem anderen zu tun. Das nach einem STATISTICS Update unter Umständen andere Ausführungspläne verwendet werden, ist normal. sp_updatestats unterbricht NIE die Ausführung von Abfragen; vom Prinzip wird nur ein
UPDATE STATISTICS <schema>.<table> <name> WITH <options>
durchgeführt. Ansonsten gibt es keine weiteren Aktivitäten. Die von Dir beobachteten CPU-Lasten decken sich mit den Vermutungen von "nicht optimalen" Ausführungsplänen. Das nachfolgende Beispiel (SQL <= 2012) zeigt das von Dir beschriebene Verhalten:
CREATE TABLE dbo.demo_table ( Id int not null identity (1, 1), C1 CHAR(3) not null, C2 CHAR(1000) not null ); GO -- ~ 30.000 records INSERT INTO dbo.demo_table WITH (TABLOCK) (C1, C2) SELECT 'DE', CAST(text AS CHAR(1000)) FROM sys.messages WHERE language_id = 1033 UNION ALL SELECT 'AU', CAST(text AS CHAR(1000)) FROM sys.messages WHERE language_id = 1033 UNION ALL SELECT 'CH', CAST(text AS CHAR(1000)) FROM sys.messages WHERE language_id = 1033; GO -- Create an index on C1 CREATE NONCLUSTERED INDEX nix_demo_table_C1 ON dbo.demo_table (C1); GO
Eine Abfrage auf DE, AU oder CH erzeugt den folgenden Ausführungsplan:
Wie Du erkennen kannst, ist ein TABLE SCAN für Microsoft SQL Server eine bessere Wahl als ein INDEX SEEK mit einem entsprechenden RID-Lookup (HEAP). Nun werden 5.000 weitere Datensätze in die Tabelle eingetragen. Da damit der Schwellenwert von 20% + 500 nicht überschritten wird, werden die Statistiken nicht aktualisiert:
INSERT INTO dbo.demo_table WITH (TABLOCK) (C1, C2) SELECT TOP (5000) 'ES', CAST(text AS CHAR(1000)) FROM sys.messages WHERE language_id = 1033;
Eine Abfrage auf das Prädikat "ES" führt zu folgendem Ausführungsplan:
Wie Du sehen kannst, geht Microsoft SQL Server von 1 (!!!) Datensatz aus. Tatsächlich sind jedoch 5.000 Datensätze vorhanden. Mit Hilfe des NESTED LOOP werden aus der Tabelle selbst fehlende Informationen, die nicht im Index vorhanden sind, ermittelt (RID-Lookup).
Schaut man sich die Statistiken an, wird schnell klar, was hier passiert:
DBCC SHOW_STATISTICS ('dbo.demo_table', 'nix_demo_table_c1') WITH HISTOGRAM;
Da der neue Wert "ES" noch nicht in den Statistiken vorhanden sind, geht Microsoft SQL Server von 1 Datensatz aus (<= 2012). Nachdem die Statistiken aktualisiert wurden, wird die Abfrage erneut ausgeführt. Mit der nächsten Abfragen mache ich sichtbar, welche Statiistiken Microsoft SQL Server für die Abfrage lädt und analysiert:
UPDATE STATISTICS dbo.demo_table nix_demo_table_c1 WITH FULLSCAN;
Sobald die Statistiken aktualisiert wurden, wird folgende Abfrage ausgeführt - achte auf den OUTPUT!
SELECT * FROM dbo.demo_table WHERE C1 = 'ES' OPTION ( QUERYTRACEON 3604, QUERYTRACEON 9204, QUERYTRACEON 9292 );
Wie Du erkennen kannst, hat Microsoft SQL Server nach der Aktualisierung der Statistiken den Plan als "invalide" gekennzeichnet und er musste neu kompiliert werden. Dazu gehört natürlich, die Statistiken neu zu laden und für eine optimale Abfragestrategie zu analysieren.
Das alles in eine einzige Antwort zu quetschen, ist schon recht schwierig - aber vielleicht sehen wir uns ja mal auf einem Usertreffen. Ich bereite gerade zum Thema Statistiken einen entsprechenden Vortrag vor :)
Uwe Ricken (Blog | Twitter)
Microsoft Certiied Master - SQL Server 2008
Microsoft Certified Solution Master - CHARTER Data Platform
Microsoft Certified Solution Expert - Data Platform
db Berater GmbH
Microsoft SQL Server Blog (german only)
- Bearbeitet Uwe RickenMVP Dienstag, 13. September 2016 09:00
- Als Antwort markiert Andreas Kreuzberg Dienstag, 13. September 2016 09:15
Alle Antworten
-
Hallo Andreas,
ich kann mir nicht vorstellen, dass ein EXEC sp_updatestats dazu führt, dass Verbindungen getrennt werden.
Man kann im ersten Schritt nur vermuten, was da passiert. Die Frage ist, sind die 30 Verbindungen auch tatsächlich aktiv, oder sind es nur schlafende Sessions? Hier ein Beispiel, um zu gucken, ob tatsächlich so viel auf dem System los ist.
DECLARE @OpenQueries TABLE (cpu_time INT, logical_reads INT, session_id INT) INSERT INTO @OpenQueries(cpu_time, logical_reads, session_id) select r.cpu_time ,r.logical_reads, r.session_id from sys.dm_exec_sessions as s inner join sys.dm_exec_requests as r on s.session_id =r.session_id and s.last_request_start_time=r.start_time where is_user_process = 1 --and r.cpu_time >0 waitfor delay '00:00:01' select substring(h.text, (r.statement_start_offset/2)+1 , ((case r.statement_end_offset when -1 then datalength(h.text) else r.statement_end_offset end - r.statement_start_offset)/2) + 1) as text , r.cpu_time-t.cpu_time as CPUDiff , r.logical_reads-t.logical_reads as ReadDiff , r.wait_type , r.wait_time , r.last_wait_type , r.wait_resource , r.command , r.database_id , r.blocking_session_id , r.granted_query_memory , r.session_id , r.reads , r.writes, r.row_count, s.[host_name] , s.program_name, s.login_name from sys.dm_exec_sessions as s inner join sys.dm_exec_requests as r on s.session_id =r.session_id and s.last_request_start_time=r.start_time left join @OpenQueries as t on t.session_id=s.session_id CROSS APPLY sys.dm_exec_sql_text(r.sql_handle) h where is_user_process = 1 order by 3 desc
Alternativ würde ich die sp_whoisactive Prozedur von Adam Machanic mal hinzuziehen. Damit bekommt man auch sehr schnell raus, was gerade los ist.
Wenn ich raten müsste, dann würde ich sagen, die Systemlast ist so hoch, da der SQL Server aufgrund veralteter Statistiken suboptimale Abfragepläne nutzt und sich zu viel Arbeit macht. Durch das Aktualisieren der Statistiken mit exec sp_updatestats werden bis dat invovlierte Abfragepläne verworfen und neu kompiliert. Daher ist dann erst einmal die Systemlast auch wieder besser. Wenn sich dies aber immer wiederholt, dann müsste doch noch was genauer auf das System geguckt werden. Welche Abfrage(n) werden mit der Zeit evtl. langsamer?
Werden die betroffenen Tabellen oft mit vielen neuen Daten befüllt oder ändert sich der Inhalt übermäßig oft?
Gruß
Dirk
May you never suffer the sentiment of spending a day without any purpose
-
Hi,
im ERRORLOG steht leider überhaupt nichts drin. Ich denke, es waren aktive Verbindungen, mit "sp_who2 'active' hatten diese zumindest den Status "runnable", und zeigten auch entsprechende Werte bei CPU und IO an.
Ich kann mir auch nicht vorstellen, dass ein Update von Statistiken Verbindungen trennt, das wäre ja fast schon fatal.
Mal sehen, ob jemand noch eine Idee hat.
Danke für das Script, werde ich Zuge der Recherche mal testen.
Grüße
Andreas
-
Hi Andreas,
gab es denn von "Client" Seite aus irgendwelche Fehler? Sofern die Verbindungen tatsächlich getrennt worden wären, müsste es auf Clientseite doch eigentlich einen Hinweis geben...
Gibt es ggf. ein Tracking der Wartestatistiken? Dann könnte man für den Zeitraum mal schauen, worauf der SQL Server zu warten hat und weswegen sich ggf. die Sessions so hochschaukeln.
Wie gesagt, mein Verdacht sind Abfragepläne, die etwas daneben liegen. Daher kommt es ggf. zu mehr Waits im Bereich IO und/oder CPU. Nach dem Aktualisieren der Statistiken ist der SQL Server dann wieder "schlau genug" und kann die Abfragen, sie sich so hochgeschaukelt haben, wieder schneller abarbeiten, da nun die Datenverteilung wieder eher bekannt ist.
Bzgl. der Wartestatistiken kann man ansonsten auch mal das Skript von Glenn Berry verwenden:
-- Isolate top waits for server instance since last restart or wait statistics clear (Query 31) (Top Waits) WITH [Waits] AS (SELECT wait_type, wait_time_ms/ 1000.0 AS [WaitS], (wait_time_ms - signal_wait_time_ms) / 1000.0 AS [ResourceS], signal_wait_time_ms / 1000.0 AS [SignalS], waiting_tasks_count AS [WaitCount], 100.0 * wait_time_ms / SUM (wait_time_ms) OVER() AS [Percentage], ROW_NUMBER() OVER(ORDER BY wait_time_ms DESC) AS [RowNum] FROM sys.dm_os_wait_stats WITH (NOLOCK) WHERE [wait_type] NOT IN ( N'BROKER_EVENTHANDLER', N'BROKER_RECEIVE_WAITFOR', N'BROKER_TASK_STOP', N'BROKER_TO_FLUSH', N'BROKER_TRANSMITTER', N'CHECKPOINT_QUEUE', N'CHKPT', N'CLR_AUTO_EVENT', N'CLR_MANUAL_EVENT', N'CLR_SEMAPHORE', N'DBMIRROR_DBM_EVENT', N'DBMIRROR_EVENTS_QUEUE', N'DBMIRROR_WORKER_QUEUE', N'DBMIRRORING_CMD', N'DIRTY_PAGE_POLL', N'DISPATCHER_QUEUE_SEMAPHORE', N'EXECSYNC', N'FSAGENT', N'FT_IFTS_SCHEDULER_IDLE_WAIT', N'FT_IFTSHC_MUTEX', N'HADR_CLUSAPI_CALL', N'HADR_FILESTREAM_IOMGR_IOCOMPLETION', N'HADR_LOGCAPTURE_WAIT', N'HADR_NOTIFICATION_DEQUEUE', N'HADR_TIMER_TASK', N'HADR_WORK_QUEUE', N'KSOURCE_WAKEUP', N'LAZYWRITER_SLEEP', N'LOGMGR_QUEUE', N'ONDEMAND_TASK_QUEUE', N'PWAIT_ALL_COMPONENTS_INITIALIZED', N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP', N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP', N'REQUEST_FOR_DEADLOCK_SEARCH', N'RESOURCE_QUEUE', N'SERVER_IDLE_CHECK', N'SLEEP_BPOOL_FLUSH', N'SLEEP_DBSTARTUP', N'SLEEP_DCOMSTARTUP', N'SLEEP_MASTERDBREADY', N'SLEEP_MASTERMDREADY', N'SLEEP_MASTERUPGRADED', N'SLEEP_MSDBSTARTUP', N'SLEEP_SYSTEMTASK', N'SLEEP_TASK', N'SLEEP_TEMPDBSTARTUP', N'SNI_HTTP_ACCEPT', N'SP_SERVER_DIAGNOSTICS_SLEEP', N'SQLTRACE_BUFFER_FLUSH', N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP', N'SQLTRACE_WAIT_ENTRIES', N'WAIT_FOR_RESULTS', N'WAITFOR', N'WAITFOR_TASKSHUTDOWN', N'WAIT_XTP_HOST_WAIT', N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG', N'WAIT_XTP_CKPT_CLOSE', N'XE_DISPATCHER_JOIN', N'XE_DISPATCHER_WAIT', N'XE_TIMER_EVENT') AND waiting_tasks_count > 0) SELECT MAX (W1.wait_type) AS [WaitType], CAST (MAX (W1.WaitS) AS DECIMAL (16,2)) AS [Wait_Sec], CAST (MAX (W1.ResourceS) AS DECIMAL (16,2)) AS [Resource_Sec], CAST (MAX (W1.SignalS) AS DECIMAL (16,2)) AS [Signal_Sec], MAX (W1.WaitCount) AS [Wait Count], CAST (MAX (W1.Percentage) AS DECIMAL (5,2)) AS [Wait Percentage], CAST ((MAX (W1.WaitS) / MAX (W1.WaitCount)) AS DECIMAL (16,4)) AS [AvgWait_Sec], CAST ((MAX (W1.ResourceS) / MAX (W1.WaitCount)) AS DECIMAL (16,4)) AS [AvgRes_Sec], CAST ((MAX (W1.SignalS) / MAX (W1.WaitCount)) AS DECIMAL (16,4)) AS [AvgSig_Sec] FROM Waits AS W1 INNER JOIN Waits AS W2 ON W2.RowNum <= W1.RowNum GROUP BY W1.RowNum HAVING SUM (W2.Percentage) - MAX (W1.Percentage) < 99 -- percentage threshold OPTION (RECOMPILE); ------
Am Besten über einen gewissen Zeitraum alle 2-3 Minuten laufen lassen und das Ergebnis in eine Tabelle schreiben. So kann man nachgelagert gucken, was denn da los gewesen ist. Bzw. kann man dann versuchen abzuleiten, warum die Sessions im Status runnable sind. Es bedeutet ja, dass die Session was zu tun hatte, hat dann entweder ihr Quorum erreicht oder musste auf eine Ressource warten...
Andreas Wolter würde jetzt bestimmt den Tipp geben, es mit Extended Events zu versuchen. Vielleicht hilft das dann schon mal weiter (ggf ein wenig anpassen):
https://blogs.msdn.microsoft.com/sqlsakthi/2011/02/20/troubleshooting-slow-running-query-using-extended-events-wait-info-event/
Gruß und viel Erfolg
Dirk
May you never suffer the sentiment of spending a day without any purpose
- Bearbeitet Dirk Hondong Montag, 12. September 2016 10:43
-
Hallo Andreas,
das eine hat DEFINITV nichts mit dem anderen zu tun. Das nach einem STATISTICS Update unter Umständen andere Ausführungspläne verwendet werden, ist normal. sp_updatestats unterbricht NIE die Ausführung von Abfragen; vom Prinzip wird nur ein
UPDATE STATISTICS <schema>.<table> <name> WITH <options>
durchgeführt. Ansonsten gibt es keine weiteren Aktivitäten. Die von Dir beobachteten CPU-Lasten decken sich mit den Vermutungen von "nicht optimalen" Ausführungsplänen. Das nachfolgende Beispiel (SQL <= 2012) zeigt das von Dir beschriebene Verhalten:
CREATE TABLE dbo.demo_table ( Id int not null identity (1, 1), C1 CHAR(3) not null, C2 CHAR(1000) not null ); GO -- ~ 30.000 records INSERT INTO dbo.demo_table WITH (TABLOCK) (C1, C2) SELECT 'DE', CAST(text AS CHAR(1000)) FROM sys.messages WHERE language_id = 1033 UNION ALL SELECT 'AU', CAST(text AS CHAR(1000)) FROM sys.messages WHERE language_id = 1033 UNION ALL SELECT 'CH', CAST(text AS CHAR(1000)) FROM sys.messages WHERE language_id = 1033; GO -- Create an index on C1 CREATE NONCLUSTERED INDEX nix_demo_table_C1 ON dbo.demo_table (C1); GO
Eine Abfrage auf DE, AU oder CH erzeugt den folgenden Ausführungsplan:
Wie Du erkennen kannst, ist ein TABLE SCAN für Microsoft SQL Server eine bessere Wahl als ein INDEX SEEK mit einem entsprechenden RID-Lookup (HEAP). Nun werden 5.000 weitere Datensätze in die Tabelle eingetragen. Da damit der Schwellenwert von 20% + 500 nicht überschritten wird, werden die Statistiken nicht aktualisiert:
INSERT INTO dbo.demo_table WITH (TABLOCK) (C1, C2) SELECT TOP (5000) 'ES', CAST(text AS CHAR(1000)) FROM sys.messages WHERE language_id = 1033;
Eine Abfrage auf das Prädikat "ES" führt zu folgendem Ausführungsplan:
Wie Du sehen kannst, geht Microsoft SQL Server von 1 (!!!) Datensatz aus. Tatsächlich sind jedoch 5.000 Datensätze vorhanden. Mit Hilfe des NESTED LOOP werden aus der Tabelle selbst fehlende Informationen, die nicht im Index vorhanden sind, ermittelt (RID-Lookup).
Schaut man sich die Statistiken an, wird schnell klar, was hier passiert:
DBCC SHOW_STATISTICS ('dbo.demo_table', 'nix_demo_table_c1') WITH HISTOGRAM;
Da der neue Wert "ES" noch nicht in den Statistiken vorhanden sind, geht Microsoft SQL Server von 1 Datensatz aus (<= 2012). Nachdem die Statistiken aktualisiert wurden, wird die Abfrage erneut ausgeführt. Mit der nächsten Abfragen mache ich sichtbar, welche Statiistiken Microsoft SQL Server für die Abfrage lädt und analysiert:
UPDATE STATISTICS dbo.demo_table nix_demo_table_c1 WITH FULLSCAN;
Sobald die Statistiken aktualisiert wurden, wird folgende Abfrage ausgeführt - achte auf den OUTPUT!
SELECT * FROM dbo.demo_table WHERE C1 = 'ES' OPTION ( QUERYTRACEON 3604, QUERYTRACEON 9204, QUERYTRACEON 9292 );
Wie Du erkennen kannst, hat Microsoft SQL Server nach der Aktualisierung der Statistiken den Plan als "invalide" gekennzeichnet und er musste neu kompiliert werden. Dazu gehört natürlich, die Statistiken neu zu laden und für eine optimale Abfragestrategie zu analysieren.
Das alles in eine einzige Antwort zu quetschen, ist schon recht schwierig - aber vielleicht sehen wir uns ja mal auf einem Usertreffen. Ich bereite gerade zum Thema Statistiken einen entsprechenden Vortrag vor :)
Uwe Ricken (Blog | Twitter)
Microsoft Certiied Master - SQL Server 2008
Microsoft Certified Solution Master - CHARTER Data Platform
Microsoft Certified Solution Expert - Data Platform
db Berater GmbH
Microsoft SQL Server Blog (german only)
- Bearbeitet Uwe RickenMVP Dienstag, 13. September 2016 09:00
- Als Antwort markiert Andreas Kreuzberg Dienstag, 13. September 2016 09:15