Langsame temporäre Tabelle fällt in SQL 2005

7

Auf unserem SQL-Produktionsserver ist ein Problem aufgetreten, bei dem das Löschen temporärer Tabellenobjekte lange dauert (offensichtlich, wenn ein kleiner und synchroner Drop verwendet wird). Ich kann dies nicht auf anderen SQL-Servern reproduzieren (ähnlich spezifiziert mit der gleichen Anzahl von Spindeln, die Tempdb-Datendateien bedienen (aufgeteilt in die gleiche Anzahl von Dateien (1 pro physischem Kern)). Unter SQL 2005 Enterprise (SP2 - 3042).

Update: ein weiterer Faktor - der am wahrscheinlichsten aussieht. Auf diesem Server befinden sich> 500 Datenbanken. Ein anderer Server mit> 800 führt diese Tropfen ebenfalls langsam aus. Das ist der einzige andere Server, den ich mit vielen DBS habe.

Zweites Update: Durch einen Neustart der Problemserver können die Anweisungen create und drop sofort ausgeführt werden. Die Leistung des Tests verschlechtert sich in den nächsten Stunden (während die Anwendung ausgeführt wird), bis er ein Plateau erreicht (was zu sein scheint). Ich habe einen Job im Hintergrund, der dies alle 30 Minuten testet. Ich werde nach ein paar Tagen sehen, welche Ergebnisse erzielt werden und ob die Ausführungszeiten gleich sind. Ich denke sie werden es sein.

Drittes Update: Während keine der ausführenden Anweisungen Latch-Wartezeiten für CPU-Ressourcen angezeigt hat, sehe ich bei Verwendung von sp_whoisactive, dass während eines Laufs mit delta_interval = 30 (Sekunden) bei laufender Abfrage das CPU_delta ungefähr 30.000 (Millisekunden?) Meldet und wenn ich während der Ausführung perf beobachte Während der Ausführungszeit scheint es einen Kernwert der CPU-Spitze zu geben. Diese befinden sich auf 16 CPU-Boxen, so dass es etwas schwierig sein kann, über perfmon zu sehen, wenn anderer Datenverkehr auftritt, aber es scheint, als würde sich bei der Ausführung von Drop-Anweisungen ein CPU-Wert erhöhen.

Das Erstellen und Zerstören von 20 winzigen temporären Tabellen mit eindeutigen Namen (eine Spalte, keine Zeilen) dauert auf den meisten Servern, auf denen ich es teste, weniger als 20 ms. Auf einem Server dauert es> 5 Sekunden. Die überwiegende Mehrheit (> 95%) der Zeit wird für die Drop-Anweisungen aufgewendet.

Während der Ausführung werden keine expliziten Wartezeiten und keine Blockierungen gemeldet, und perfmon zeigt weder für Daten- noch für Protokolldateien eine Belastung des E / A-Subsystems an.

Ich habe mir Spitzen- und niedrige Nutzungszeiten angesehen, wenn eine hohe Anzahl von Tabellen für die Zerstörung markiert und niedrig ist. Der Vorgang dauert ungefähr 5 Sekunden, um die 20 drop-Anweisungen zu verarbeiten, egal was passiert. Das Problem führt zu einer wahrnehmbaren (von Kunden) verlangsamten Reaktionsfähigkeit.

Beispielcode, ich habe 20 ähnliche Objekte erstellt, um das 5-Sekunden-Timing zu erhalten. Es scheint ungefähr 300 ms pro Tropfen zu sein.

PRINT CONVERT(varchar(30),GETDATE(),113)


CREATE TABLE [#Objects1]
(
  [Id] uniqueidentifier NOT NULL
)


CREATE TABLE [#Objects12]
(
  [Id] uniqueidentifier NOT NULL
)
...
DROP TABLE [#Objects1]
DROP TABLE [#Objects12]
...
PRINT CONVERT(varchar(30),GETDATE(),113)

Timing konsistent 5 bis 6 Sekunden für die Ausführung

11 Nov 2011 12: 56: 52: 073 - Beginnen Sie mit der Erstellung der temporären Tabelle

11 Nov 2011 12: 56: 52: 090 - Temporäre Tabellenerstellung beenden

11 Nov 2011 12: 56: 52: 090 - Beginnen Sie mit dem Löschen der temporären Tabelle

11 Nov 2011 12: 56: 57: 230 - Vollständiges Löschen der temporären Tabelle

Könnten Sie auch USE tempdb ausführen? DBCC LOGINFO; und notieren Sie die Anzahl der zurückgegebenen Zeilen. Bitte fügen Sie alle Ausgaben der Skripte Ihrer ursprünglichen Frage hinzu.

Ich bemerkte ursprünglich, dass ich ungefähr 271 Vlogs hatte, also schrumpfte ich und zog nach, um zu sehen, ob Fragmentierung ein Problem war. Machte keinen Unterschied. Aktuelle DBCC Loginfo

FileId,FileSize,StartOffset,FSeqNo,Status,Parity,CreateLSN
2,253952,8192,101603,2,64,0
2,262144,262144,101604,2,64,0
2,262144,524288,101605,2,64,85000000038300574
2,262144,786432,101606,2,64,85000000038300574
2,262144,1048576,101578,2,128,86000000001600001
2,262144,1310720,101579,2,128,86000000001600001
2,262144,1572864,101580,2,128,86000000001600001
2,262144,1835008,101581,2,128,86000000001600001
2,262144,2097152,101582,2,128,86000000001600001
2,262144,2359296,101583,2,128,86000000023400002
2,262144,2621440,101584,2,128,86000000023500756
2,327680,2883584,101585,2,128,86000000023500756
2,327680,3211264,101586,2,128,86000000023500756
2,393216,3538944,101587,2,128,86000000023500756
2,393216,3932160,101588,2,128,86000000023500756
2,458752,4325376,101589,2,128,86000000023500756
2,253952,4784128,101590,2,128,86000000023500756
2,270336,5038080,101591,2,128,86000000023500756
2,253952,5308416,101592,2,128,86000000023500756
2,270336,5562368,101593,2,128,86000000023500756
2,253952,5832704,101594,2,128,86000000023500756
2,335872,6086656,101595,2,128,86000000023500756
2,253952,6422528,101596,2,128,86000000023500756
2,401408,6676480,101597,2,128,86000000023500756
2,253952,7077888,101598,2,128,86000000023500756
2,466944,7331840,101599,2,128,86000000023500756
2,253952,7798784,101600,2,128,86000000023500756
2,253952,8052736,101601,2,128,86000000023500756
2,278528,8306688,101602,2,128,86000000023500756
2,133627904,8585216,101607,2,64,101336000000013600462
2,133627904,142213120,101563,0,128,101336000000013600462
2,133627904,275841024,101564,0,128,101336000000013600462
2,133627904,409468928,101565,0,128,101336000000013600462
2,133627904,543096832,101566,0,128,101336000000013600462
2,133627904,676724736,101567,0,128,101336000000013600462
2,133627904,810352640,101568,0,128,101336000000013600462
2,133627904,943980544,101569,0,128,101336000000013600462
2,133627904,1077608448,101570,0,128,101336000000013600462
2,133627904,1211236352,101571,0,128,101336000000013600462
2,133627904,1344864256,101572,0,128,101336000000013600462
2,133627904,1478492160,101573,0,128,101336000000013600462
2,133627904,1612120064,101574,0,128,101336000000013600462
2,133627904,1745747968,101575,2,128,101336000000013600462
2,133627904,1879375872,101576,2,128,101336000000013600462
2,134479872,2013003776,101577,2,128,101336000000013600462

Ausgabe der E / A-Statistiken :

Database Name,physical_name,io_stall_read_ms,num_of_reads,avg_read_stall_ms,io_stall_write_ms,num_of_writes,avg_write_stall_ms,io_stalls,total_io,avg_io_stall_ms
msdb,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\MSDBData.mdf,47691565,817329,58.4,10747142,533509,20.1,58438707,1350838,43.3
tempdb,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\templog.ldf,54457,30177,1.8,145691717,8235651,17.7,145746174,8265828,17.6
model,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\modellog.ldf,547,122,4.4,2273,239,9.5,2820,361,7.8
tempdb,P:\tempdb_data3.mdf,2606066,1112043,2.3,17829023,1919954,9.3,20435089,3031997,6.7
tempdb,P:\tempdb_data2.mdf,2484793,1111808,2.2,17270161,1922735,9.0,19754954,3034543,6.5
tempdb,P:\tempdb_data5.mdf,2514469,1112086,2.3,17066589,1919802,8.9,19581058,3031888,6.5
tempdb,P:\tempdb_data7.mdf,2542070,1112551,2.3,17049649,1920204,8.9,19591719,3032755,6.5
tempdb,P:\tempdb_data6.mdf,2517767,1112237,2.3,17043756,1924983,8.9,19561523,3037220,6.4
tempdb,P:\tempdb_data0.mdf,2476811,1113570,2.2,17084779,1926333,8.9,19561590,3039903,6.4
tempdb,P:\tempdb_data4.mdf,2462179,1111649,2.2,17073336,1920058,8.9,19535515,3031707,6.4
tempdb,P:\tempdb_data1.mdf,2456317,1111859,2.2,16997589,1922438,8.8,19453906,3034297,6.4
model,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\model.mdf,5194,798,6.5,612,240,2.5,5806,1038,5.6
master,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\master.mdf,40640,7326,5.5,2868,1548,1.9,43508,8874,4.9
msdb,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\MSDBLog.ldf,8015,950,8.4,1012107,312084,3.2,1020122,313034,3.3
master,H:\Microsoft SQL Server\MSSQL.1\MSSQL\DATA\mastlog.ldf,640,141,4.5,198283,99134,2.0,198923,99275,2.0

Waitstats-Ausgabe :

wait_type,wait_time_s,pct,running_pct

PAGEIOLATCH_EX,0.02,100.00,100.00

Die TokenAndPermUserStore-Größe beträgt 2952 KB.

SELECT SUM(single_pages_kb + multi_pages_kb) AS "SecurityTokenCacheSize(kb)" FROM sys.dm_os_memory_clerks WHERE name = 'TokenAndPermUserStore' 
JorgeSandoval
quelle
Tempdb ist 8 Datendateien auf einem Raid 10 SAN Lun. Nirgendwo in der Nähe des Platzdrucks auf Datendateien (normalerweise etwa 500 MB mit 48 GB ...) verfügt die SQL-Box über 4 Quad-Core-Prozesse. Die Protokolldatei befindet sich auf separaten Spindeln. Leider können temporäre Tabellen nicht ohne massive Umstrukturierung umgangen werden und sind ein Artefakt einer Masseneinfügungsstrategie, mit der Daten in die temporären Tabellen übernommen werden, um sie gespeicherten Prozessen zur Bearbeitung zur Verfügung zu stellen.
1
Gleiche @@ VERSION auf allen SQL Servern? Überprüfen Sie dann die
Startschalter
3
Überprüfen Sie jetzt die Trace-Flags ... die kein Code sind
gbn
4
Wenn Sie zuerst TRUCATEdie temporären Tabellen verwenden, wird dies die beschleunigen DROP. Ha, nur ein Scherz.
Nick Chammas
1
Nur wenn die Tabelle> 8 MB ist. Für gespeicherte Proc-Temp-Tabellen gibt es einen Cache der Metadaten. Hier liegt mein Verdacht ... Aber ich bin mir nicht sicher, wo ich nach diesen zwischengespeicherten Tabellen suchen soll. Wenn es nur sys.objects in tempdb ist, gibt es nur 2k Objekte oder so. Ich kann mir nicht vorstellen, warum das Hinzufügen / Löschen so langsam ist.
JorgeSandoval

Antworten:

8

Sie haben die von der Tempdb-LUN verwendeten IOPS nicht erwähnt. Werden auf dem LUN-Gerät E / A-Wartezeiten angezeigt? Ist noch etwas auf dieser LUN? Verwendet ein anderes System die Datenträgergruppe / den Pool, aus der die LUN erstellt wurde?

Ditto master db - gleiche q's.

Verwenden Sie auch lokale temporäre Tabellen (#Tabellenname) oder globale temporäre Tabellen (## Tabellenname)? Wenn global, könnte eine andere SPID die gemeinsame Sperre für die globalen temporären Tabellen beibehalten, wenn Sie versuchen, sie zu löschen?

bretlowery
quelle
Tempdb-Datendateien befinden sich auf einer LUN, die sich auf einer eigenen 4-Platten-RAID-10-Gruppe befindet (dh dedizierte Spindeln). Es wird keine E / A-Last angezeigt (dh 98% oder mehr Leerlaufzeit auf der logischen Festplatte). temporäre Tabellen sind lokale temporäre Tabellen (wie in meinem Beispiel im ursprünglichen Beitrag). Kann reproduziert werden, wenn es nicht unter Last zu sein scheint.
JorgeSandoval
Auch tempdb ldf ist auf Raid 5
JorgeSandoval
Ich denke, @bretlowery hat etwas vor. Können Sie tempdb in eine andere LUN ändern, neu starten und prüfen, ob sich etwas ändert? Außerdem hätte ich keine LDFs auf RAID 5: Sie sind zu 100% schreibbar und besser für R1 oder R10 geeignet. Überprüfen Sie
abschließend
Hätte ich dort keine Konflikte um die Festplatte gesehen, die Auslastung in der Leerlaufzeit% der Luns lag bei 98/99%? Ich meine, wir sprechen über einen Tropfen einer temporären Tabelle mit einer Spalte. Dies sollten höchstens zwei oder drei Schreibvorgänge sein, aber es dauert 300 ms, nachdem der Server über einen längeren Zeitraum ausgeführt wurde, während die Anwendung ausgeführt wird. Wenn Sie die Instanz neu starten, erhalten Sie superschnelle Drops, die sich in den ersten Stunden der Anwendung verlangsamen.
JorgeSandoval
7

Die Antwort auf mein Perf-Problem ist ein wenig bekanntes (obwohl ich es vor langer Zeit gesehen hatte) Problem im Zusammenhang mit der Erfassung von dmv-Statistiken auf Systemen mit vielen Datenbanken, in denen Code häufig temporäre Tabellen verwendet (oder vermutlich haben Sie viele Tabellen). . Auf unseren langsamsten Servern hatte sys.dm_db_index_usage_stats> 200.000 Datensätze, wobei Server, die 10.000 Datensätze zurückgeben, immer noch eine messbare Verzögerung aufweisen.

KB-Artikel beschreibt das Problem. http://support.microsoft.com/kb/2003031

Die Abfrageleistung nimmt ab, wenn sys.dm_db_index_usage_stats eine große Anzahl von Zeilen enthält

Stellen Sie sich das folgende Szenario vor:

  • In Microsoft SQL Server 2005 führen Sie häufig DDL-Vorgänge aus, bei denen viele Tabellen gelöscht und neu erstellt werden (insbesondere temporäre Tabellen in der Tempdb-Datenbank).
  • Sie haben eine große Anzahl von Einträgen (100.000 oder mehr) in der dynamischen Verwaltungsansicht (DMV) von sys.dm_db_index_usage_stats.

Dieses Problem wurde in SQL 2008 behoben, kann jedoch erst 2005 durch Codeänderungen behoben werden, um die Abhängigkeit von temporären Tabellen zu verringern, oder durch Aktivieren des Ablaufverfolgungsflags 2330.

Diese KB hat meinen Speck gerettet. Durch einen Neustart nach dem Hinzufügen dieses Trace-Flags zum Starten von Parametern wurden die Drop-Zeiten auf <100 ms (von 40000 ms!) Reduziert, und ich kann auch auf diesen Servern andere Leistungsgewinne erwarten!

Zusätzliche Lektüre, die mich zu dem Schluss führte, dass dies das Problem war

http://www.pythian.com/news/5211/sql-server-more-light-shed-on-non-yielding-scheduler-and-indexes-stats/

Dank all derer, die zu dieser Frage beigetragen haben, habe ich einige sehr nützliche Werkzeuge für die Diagnose von Perf-Problemen gewonnen.

JorgeSandoval
quelle
1
Freut mich zu hören, dass Sie eine Lösung gefunden haben und danke, dass Sie die Details veröffentlicht haben.
Mark Storey-Smith
1
Vielen Dank für Ihre Hilfe, das Problem schien (zu Recht) wie Voodoo. Ein einzelner Thread, der eine CPU belegt, ist auf einer großen Box kaum wahrnehmbar, und ohne Wartezeiten tuckerte er wirklich nur durch den riesigen Speichercache für diese Statistiken. Ich bin froh, dass sie dies in SQL 2008 behoben haben. Jetzt müssen wir nur noch die lange Zeit abwarten, bis wir tatsächlich ein Upgrade durchführen können ...
JorgeSandoval
6

Wenn eine Drop-Tabelle länger als ein oder zwei Sekunden wartet, führen Sie Adam Machanics sp_WhoIsActive aus . Es ist ein großartiges Tool, um herauszufinden, warum eine Abfrage langsam ausgeführt wird. In der Spalte "Wartezeiten" werden die Wartezeiten für die jeweilige Aufgabe angezeigt. Wenn die Wartezeit auf der CPU nicht mehr besteht (was in sys.dm_os_wait_stats nicht angezeigt wird), wird dies auch angezeigt.

Außerdem wäre ich mir nicht sicher, wenn ich nicht darauf hinweisen würde, dass Ihr Build nicht unterstützt wird. Als Berater sage ich meinen Kunden: "Ich würde es hassen, stundenlang Fehler zu beheben, nur um festzustellen, dass es in einem Service Pack behoben wurde - und Ihnen am Ende Tausende von Dollar für etwas in Rechnung zu stellen, das Sie kostenlos hätten reparieren können. Und Sie" Ich habe sowieso keine Unterstützung mehr. " Die neuesten SQL Server-Service Packs und kumulativen Updates finden Sie unter http://sqlserverbuilds.blogspot.com . Build 3042 ist Art und Weise veraltet - die unterstützte Version SP4 ist.

Brent Ozar
quelle
Ja, ich wünschte, es wäre so einfach wie ein Update auf ein späteres Service Pack ... Ich habe bereits die kumulativen Updates und SP-Notizen gescannt und nichts im Zusammenhang mit diesem Problem gesehen. Leider hindert uns die Abteilungsrichtlinie daran, SQL SPs ohne einen vollständigen Regressionstest der Anwendung zu installieren, der Monate dauern kann. Unit-Tests auf dieser App decken etwa 20% ab ... es ist schmerzhaft. Es ist ein langsamer Zug, um in Bewegung zu kommen, und wir bereiten uns auf genau diese Aktivität vor, um die Migration nach Denali zu unterstützen (oder wenn nicht bald SQL2008 R2 veröffentlicht)
JorgeSandoval
Ich habe den Prozess sp_whoisactive heruntergeladen, aber um aussagekräftige Statistiken zu erhalten, muss ich die Ausführung erweitern, um 50 temporäre Tabellen zu erstellen und diese zu löschen. Die gesamte Ausführung des Stapels dauerte 43 Sekunden. Ich habe sp_whoisactive gestartet und mit delta = 30 Sekunden ausgeführt, um sicherzustellen, dass Start und Stopp diesen Stapel enthalten. Es scheint, dass die Anweisungen die CPU während der Ausführungszeit unter Druck setzen (also einen Kern).
JorgeSandoval
Es ist nicht klar, ob die CPU-Zeit von sp_whoisactive Millisekunden oder Mikrosekunden beträgt. Es sieht aus wie Millisekunden, da es mit dem Delta-Intervall korreliert, aber wenn ich viele der DMVs nachschlage, melden sie in Mikrosekunden
JorgeSandoval
Yeha, Adam hat es in Millisekunden gemeldet. Verwenden Sie das Delta nicht - Sie möchten nur sp_WhoIsActive ausführen, wie ich im Video zeige, und Sie möchten es abfangen, während es auf die temporäre Tabelle wartet. Das bedeutet, dass Sie es wie jede Sekunde in einer engen Schleife ausführen und die Ausgabe jedes Mal in einer temporären Tabelle erfassen. Gehen Sie dann zurück und untersuchen Sie die temporären Tabellen, um festzustellen, worauf die Spid jedes Mal gewartet hat und ob sie blockiert ist. Auch zu den Notizen - sie decken nicht alle Korrekturen ab, die in der SP / CU enthalten sind, und denken Sie daran, dass Sie eine nicht unterstützte Version verwenden.
Brent Ozar
Vielen Dank für die Eingabe. Das Problem war die Statistiksammlung einer Verwaltungsansicht (siehe meine Antwort für weitere Informationen).
JorgeSandoval
5

Bearbeiten: 2011-11-12 13:00

Da TokenAndPermStore eine "normale" Größe zu haben scheint, ist es unwahrscheinlich, dass dies ein Faktor ist. Der nächste Ort, an dem Sie suchen müssen, sind wahrscheinlich Spinlock-Statistiken . Können Sie auch (wie im Chat erwähnt ) feststellen, ob das Problem weiterhin besteht, wenn Sie die expliziten drop-Anweisungen entfernen und stattdessen die Tabellen aus dem Gültigkeitsbereich fallen lassen.

Bearbeiten: 2011-11-12 01:00

Während Sie sich auf 2005SP2 befinden, frage ich mich, ob dies möglicherweise ein TokenAndPermUserStore-Problem ist . Dies würde erklären, warum das Problem durch einen Neustart der Instanz behoben wird und warum das Problem auf Servern mit einer großen Anzahl von Datenbanken auftritt.

Können Sie die folgende Abfrage ausführen und die Ausgabe zu Ihrer Frage hinzufügen?

SELECT SUM(single_pages_kb + multi_pages_kb) AS "SecurityTokenCacheSize(kb)"
FROM sys.dm_os_memory_clerks
WHERE name = 'TokenAndPermUserStore'

Die schnelle Hack-Lösung hierfür besteht darin, einen Job zu erstellen, der die Größe des Caches überwacht und ausgeführt wird, DBCC FREESYSTEMCACHE ('TokenAndPermUserStore')wenn er eine bestimmte Größe überschreitet. IIRC (ich werde morgen nachsehen und aktualisieren) Ich habe das Limit auf 100 MB auf Servern festgelegt, auf denen dies ein Problem verursacht hat. SP3 führt einen Mechanismus zur Steuerung der Cache-Größe ein , ohne sie mit brutaler Gewalt löschen zu müssen.

Ursprüngliche Antwort:

Könnte ein bisschen hin und her gehen, aber können wir mit einem Blick auf die E / A beginnen und Statistiken abwarten ? (Skripte in GIST)

Ändern Sie Ihr Erstellungs- / Löschskript so, dass es DBCC SQLPERF("sys.dm_os_wait_stats",CLEAR);beim Start ausgeführt wird, gefolgt vom Wartestatistikskript nach dem letzten Löschen. Das Ergebnis ist wahrscheinlich leichter zu lesen, wenn Sie es als CSV veröffentlichen (damit es nach Excel kopiert werden kann).

Könnten Sie auch USE tempdb; DBCC LOGINFO;die Anzahl der zurückgegebenen Zeilen ausführen und aufzeichnen?

Mark Storey-Smith
quelle
Zu Ihrer Information, nach ungefähr 6 oder 7 Hinrichtungen scheint es nur auf PAGEIOLATCH_SHPAGEIOLATCH_SH 0.02 100.00 100.00
JorgeSandoval
Durchschnittlich 6,5 für Datendateien und 17,6 für Protokolldateien scheinen nicht zu den 300 ms pro abgelegter Tabelle beizutragen.
JorgeSandoval
Interessanterweise gibt das Testskript (Erstellen / Löschen der temporären Tabellen) keine Wartezeiten auf anderen Servern zurück. (Wartet, dass CTE tatsächlich einen Fehler durch Teilen durch Null meldet).
JorgeSandoval
@JorgeSandoval könnten Sie die Daten zu Ihrer ursprünglichen Frage als Bearbeitung bitte hinzufügen. Auf diese Weise ist es für alle einfacher zu sehen (und daran zu arbeiten).
Mark Storey-Smith
Ergebnisse wurden hinzugefügt
JorgeSandoval