Ausgangslage

In T-SQL können Anweisungen manchmal mehrere Exceptions auslösen. Mit dem TRY/CATCH-Mechanismus von T-SQL lässt sich jedoch normalerweise nur die letzte dieser Exceptions begutachten, die leider nicht immer die informativste ist. Als Beispiel kann ein einfaches BACKUP dienen:

BEGIN TRY
  BACKUP DATABASE Test TO DISK = 'C:	est.bak'
END TRY
BEGIN CATCH
  SELECT ERROR_NUMBER(),ERROR_MESSAGE()
END CATCH

Falls das SQL Server Dienstkonto keinen Zugriff auf C: hat (was der Fall sein sollte) oder dort zufällig schon eine auf Read-Only gesetzte Datei "test.bak" liegt, bekommt man die Ausgabe

Das ist zwar zutreffend, aber wenig hilfreich bei der Fehlersuche.

Deutlich erhellender ist die Ausführung des reinen BACKUP-Codes im Management Studio. Dies produziert folgende Meldungen

Msg 3201, Level 16, State 1, Line 1

Cannot open backup device 'C: est.bak'. Operating system error 5(Zugriff verweigert).

Msg 3013, Level 16, State 1, Line 1

BACKUP DATABASE is terminating abnormally.

Es gibt also mindestens einen hilfreichen Exception-Text, aber wie kommt man von T-SQL aus dort heran?

Extended Events

Die Lösung in diesem Falle lautet "Extended Events". Extended Events (EE) sind der mit SQL Server 2008 eingeführte Nachfolger von SQL Traces, deren bekannteste Anwendung wohl der SQL Profiler sein dürfte. EE bieten aber höhere Flexibilität, mehr Performance und mehr Details aus dem Inneren der Engine. Weitere allgemeine Details gibt es u.a. hier, ich möchte mich jedoch auf den konkreten Anwendungsfall beschränken.

Um EE zu fangen, braucht man eine sog. "Event Session". Diese läuft global auf der SQL Server Instanz, man muss sie also nur einmal einrichten. Für den hier angepeilten Zweck sollte das SQL dafür etwa so aussehen:

CREATE EVENT SESSION ErrorCatcher ON SERVER 
  ADD EVENT sqlserver.error_reported( 
   ACTION(sqlserver.session_id,sqlserver.sql_text) 
     WHERE (severity >= 16)) 
  ADD TARGET package0.ring_buffer(SET max_events_limit=(50)) 
  WITH (STARTUP_STATE=ON, MAX_DISPATCH_LATENCY = 1 SECONDS)

Hierdurch wird eine Session namens ErrorCatcher eingerichtet. Sie lauscht auf den Event error_reported aus dem sqlserver-Event-Package und fängt neben den Basisdaten dieses Events zusätzlich noch die session_id und den auslösenden sql_text ein. Es werden alle Fehler mit severity kleiner als 16 ignoriert und die gefangenen Events werden in einen Ringpuffer im Hauptspeicher geschrieben, der immer die letzten 50 Events hält. Wird der SQL Server gestartet, startet sich auch die Session mit und gefangene Events sollten nach spätestens einer Sekunde in den Ringpuffer geschrieben werden – vorher werden sie ggf. noch vom Eventsystem gepuffert, eine der Performance steigernden Maßnahmen.

Generiert habe ich diesen Code übrigens mit Hilfe des Extended Event Wizards, den es ab dem Management Studio 2012 unter "Management" gibt.

Die frisch generierte Session ist noch nicht gestartet – das STARTUP_STATE=ON bezieht sich nur auf das Verhalten beim Instanz-Neustart. Los geht es mit

ALTER EVENT SESSION ErrorCatcher ON SERVER STATE = START

Führt man nun das fehlerhafte BACKUP noch einmal aus, verhält sich zunächst alles wie gehabt. Im Hintergrund wurden nun aber die geworfenen Exceptions aufgezeichnet. Ein XML mit dem gesamten aktuellen Inhalt des Ringpuffers erhält man mit

SELECT CAST(xet.target_data AS xml) 
FROM sys.dm_xe_session_targets AS xet 
  INNER JOIN sys.dm_xe_sessions AS xe 
    ON (xe.address = xet.event_session_address) 
WHERE xe.name = 'ErrorCatcher' 

Das ist noch etwas unhandlich, man kann es aber mit XQuery bequem auf ein Tabellenformat herunterbrechen. In der Gesamtheit sieht das Backup-Statement samt Fehleranalyse dann wie folgt aus:

DECLARE @startzeit datetime2 = GETUTCDATE() 

BEGIN TRY 
  BACKUP DATABASE Test TO DISK = 'C:	est.bak' WITH INIT 
END TRY 
BEGIN CATCH 
  WAITFOR DELAY '00:00:01' -- Wait for MAX_DISPATCH_LATENCY 

  DECLARE @target_data XML 
  SELECT @target_data = CAST(xet.target_data AS xml) 
  FROM sys.dm_xe_session_targets AS xet 
    INNER JOIN sys.dm_xe_sessions AS xe 
      ON (xe.address = xet.event_session_address) 
  WHERE xe.name = 'ErrorCatcher' 

  SELECT 
    n.value('(@timestamp)[1]', 'datetime2') 
      AS [timestamp], 
    n.value('(data[@name="error_number"]/value)[1]', 'int') 
      AS Error,
    n.value('(data[@name="message"]/value)[1]', 'nvarchar(max)') 
      AS Message
  FROM @target_data.nodes('RingBufferTarget/event') AS q(n) 
  WHERE 
    @@SPID = n.value('(action[@name="session_id"]/value)[1]', 'int') 
    AND n.value('(@timestamp)[1]', 'datetime2') >= @startzeit 
END CATCH

Man beachte, dass die Basiswerte des Events aus den data-Elementen kommen, während die über die ACTION-Klausel der Session zusätzlich eingefangenen Werte sich in den ansonsten gleich aufgebauten action-Elementen finden.

Da die Eventsession dauernd und serverweit Fehlermeldungen einfängt, ist in dem finalen WHERE noch eine Einschränkung auf die aktuelle Session-ID gesetzt, sowie eine zeitliche Einschränkung, damit man keine alten Events zu sehen bekommt.

Das Ergebnis dieses Codes sieht dann so aus:

Timestamp	Error	Message
2013-12-03 20:44:38.0440000	18204	BackupDiskFile::CreateMedia: Backup device ‚C: est.bak‘ failed to create. Operating system error 5(Zugriff verweigert).
2013-12-03 20:44:38.0440000	3201	Cannot open backup device ‚C: est.bak‘. Operating system error 5(Zugriff verweigert).
2013-12-03 20:44:38.0440000	3041	BACKUP failed to complete the command BACKUP DATABASE Test. Check the backup application log for detailed messages.
2013-12-03 20:44:38.0440000	3201	Cannot open backup device ‚C: est.bak‘. Operating system error 5(Zugriff verweigert).
2013-12-03 20:44:38.0450000	3013	BACKUP DATABASE is terminating abnormally.

Wie man sieht, gibt es intern gleich eine ganze Error-Kaskade, aber man kann sich ja über die Fehlernummern die passenden herausfischen. Es gehen jedenfalls keine Meldungen mehr verloren 🙂

Alternative Einstellungen

Um keine dauernd mitlaufende Session zu haben, bzw. um auf einem vielbeschäftigten Server nicht zu viele Events zu bekommen, sind noch verschiedene Varianten denkbar.

• Auf einem Server mit vielen Datenbanken kann man noch eine Event-WHERE-Bedingung auf die Datenbank(-ID) setzen und ggf. mehrere Sessions für verschiedene Datenbanken einrichten.
• Der Ringpuffer kann auf vergrößert werden, wobei das nicht ganz unproblematisch ist, weil man bei jeder Abfrage immer den gesamten Inhalt zurückbekommt.
• Bei längerlaufenden Operationen wie dem BACKUP im Beispiel kommt es auf ein paar Millisekunden nicht an. Man könnte daher auch direkt im Code ein passgenaues CREATE SESSION mit einem WHERE (session_id = @@SPID) machen und würde so der "Verschmutzung" des Puffers durch Fehler anderer User entgehen. Allerdings braucht man für die Ausführung des Codes dann ALTER SERVER STATE-Rechte.

Fazit

Extended Events sind flexible, mächtige und nützliche Diagnosewerkzeuge. Es ist ein wenig wie mit der Powershell: Man hat anfangs eine gewisse Lernkurve, weil das Thema nicht intuitiv zugänglich ist, hat dann aber nach etwas Übung jeweils ein sehr mächtiges Werkzeug an der Hand.