Logging-Framework für MSSQL 2.0: Läufe, Laufzeiten und Fehler, die sonst niemand sieht

Mein Logging-Framework für MSSQL hat eine zweite Version bekommen, und der Anlass war ein Review meines eigenen Codes, kein Feature-Wunsch. Die erste Version aus dem Beitrag Ein Logging "Framework" für MSSQL reicht für einfaches Protokollieren. Sobald ich damit Auswertungen bauen wollte, stieß ich auf drei Grenzen, und beim genauen Hinsehen fanden sich auch echte Fehler.

In diesem Beitrag zeige ich, was neu ist: Läufe mit Lauf-ID und Laufzeit, strukturierte Fehlerdaten, einen Puffer, der ein ROLLBACK überlebt, eine Extended-Events-Session als Sicherheitsnetz und ein einziges Installationsscript mit Migration. Am Ende steht, was das Ganze bewusst nicht kann.

Was an Version 1 nicht gut war

Drei Schwächen haben Auswertungen erschwert, und dazu kamen vier echte Fehler im Code.

Die drei Schwächen

1. Keine Lauf-ID. Start- und Ende-Einträge ließen sich nur über Prozedurname und Benutzer zuordnen. Laufen zwei Instanzen derselben Prozedur parallel unter demselben Login, vermischen sich die Läufe.
2. Dauer nur im Freitext. Ein Dauer: 123ms in AdditionalInfo lässt sich per SUBSTRING parsen, ist aber fragil.
3. Fehler nur als Text. Fehlernummer, Zeile und Prozedur standen im Freitext. Nach Fehlertyp gruppieren ging nur über Message, und die enthält oft variable Anteile wie IDs oder Werte.

Die vier Fehler

• Aufruferkennung: sys.dm_exec_calls mit caller_id und call_stack_id gibt es in SQL Server nicht, der Weg über die Call-Stack-Abfrage konnte also nie funktionieren. Der Fallback mit @@PROCID liefert die Logging-Prozedur selbst, nicht den Aufrufer.
• Fehlende Schemas: INSERT INTO EventLog und EXEC LogEvent in Logging.Error nannten das Schema nicht und landen damit im Default-Schema des Benutzers.
• Fehlendes GO vor der ersten CREATE OR ALTER PROCEDURE.
• Resultset bei jedem Aufruf: LogEvent schickte mit SELECT SCOPE_IDENTITY() bei jedem Log-Eintrag ein Resultset an den Client, was bei ADO-Code stören kann.

Läufe statt Einzelzeilen: StartRun und EndRun

Mit Logging.StartRun und Logging.EndRun bekommt jeder Durchlauf einer Prozedur eine eigene Lauf-ID und eine gemessene Dauer. StartRun legt den Lauf auf einen Stack im SESSION_CONTEXT (Key Logging.RunStack) und schreibt _START. Ein Eintrag besteht aus RunID, Startzeit, Laufname und Prozedurname, der neueste steht vorn. EndRun liest die Startzeit vom Stack, berechnet DurationMs, schreibt _ABGESCHLOSSEN oder _FEHLER und nimmt den Eintrag wieder herunter.

Verschachtelte Läufe funktionieren, weil es ein Stack ist: Ein Kindlauf trägt die ParentRunID des Elternlaufs. Alle normalen Aufrufe von Logging.Info, Warn, Error und Debug innerhalb eines Laufs bekommen RunID und Prozedurnamen automatisch vom Stack. Bestehende Aufrufe musst du dafür nicht ändern.

CREATE OR ALTER PROCEDURE dbo.DatenImport @BatchId INT
AS
BEGIN
    SET NOCOUNT ON;
    SET XACT_ABORT ON;

    EXEC Logging.StartRun @Name = N'IMPORT', @ProcId = @@PROCID,
                          @AdditionalInfo = CONCAT(N'BatchId: ', @BatchId);
    BEGIN TRY
        EXEC Logging.Info @EventType = 'IMPORT_DETAIL', @Message = 'Validiere Batch';

        -- ... Logik ...

        EXEC Logging.EndRun;
    END TRY
    BEGIN CATCH
        IF @@TRANCOUNT > 0 ROLLBACK;
        EXEC Logging.EndRun @Success = 0;
        THROW;
    END CATCH
END;

Die Fehlerdaten kommen jetzt strukturiert in die Tabelle. Im CATCH-Block schreibt EndRun @Success = 0 die Spalten ErrorNumber, ErrorSeverity, ErrorState, ErrorLine und ErrorProcedure. Auch ein direkter Aufruf von Logging.Error füllt sie, zusätzlich zum Text in AdditionalInfo im bisherigen Format.

Zur Aufruferkennung: T-SQL bietet keine Abfrage, die den direkten Aufrufer einer Prozedur liefert. Deshalb gibt es zwei Wege: Du übergibst @ProcId = @@PROCID, oder du arbeitest mit StartRun, dann kennt der Stack den Prozedurnamen schon. Der Lauf-Name darf höchstens 30 Zeichen lang sein, damit Name + '_ABGESCHLOSSEN' in EventType NVARCHAR(50) passt.

Was sich jetzt auswerten lässt

Mit Lauf-ID, Dauer und Fehlernummer werden drei Fragen zu einfachen Abfragen, die vorher Heuristik waren.

Welche Läufe werden langsamer? Die Dauer steht auf dem Ende-Eintrag, eine Perzentil-Abfrage über die letzten sieben Tage genügt:

SELECT DISTINCT
    ProcedureName,
    COUNT(*)              OVER (PARTITION BY ProcedureName) AS Laeufe,
    AVG(DurationMs)       OVER (PARTITION BY ProcedureName) AS AvgMs,
    MAX(DurationMs)       OVER (PARTITION BY ProcedureName) AS MaxMs,
    PERCENTILE_CONT(0.95) WITHIN GROUP (ORDER BY DurationMs)
                          OVER (PARTITION BY ProcedureName) AS P95Ms
FROM Logging.EventLog
WHERE EventType LIKE '%[_]ABGESCHLOSSEN'
  AND DurationMs IS NOT NULL
  AND EventTime >= DATEADD(DAY, -7, GETDATE())
ORDER BY MaxMs DESC;

Welche Läufe haben nie geendet? Ein Start ohne Ende zur selben RunID, älter als fünf Minuten, ist ein hängender oder abgebrochener Lauf:

SELECT s.RunID, s.ProcedureName, s.EventTime AS StartZeit
FROM Logging.EventLog s
WHERE s.EventType LIKE '%[_]START'
  AND s.RunID IS NOT NULL
  AND s.EventTime < DATEADD(MINUTE, -5, GETDATE())
  AND NOT EXISTS (SELECT 1 FROM Logging.EventLog e
                  WHERE e.RunID = s.RunID
                    AND (e.EventType LIKE '%[_]ABGESCHLOSSEN' OR e.EventType LIKE '%[_]FEHLER'))
ORDER BY s.EventTime;

Welche Fehler treten wirklich auf? Gruppiert wird nach stabilen Merkmalen statt nach Message-Text:

SELECT TOP (20)
    ProcedureName, ErrorNumber, ErrorProcedure, ErrorLine,
    COUNT(*) AS Anzahl, MAX(EventTime) AS Zuletzt
FROM Logging.EventLog
WHERE Severity = 'ERROR' AND ErrorNumber IS NOT NULL
GROUP BY ProcedureName, ErrorNumber, ErrorProcedure, ErrorLine
ORDER BY Anzahl DESC;

Ein Hash der Message als Gruppierungsschlüssel bringt wenig, sobald der Text variable Teile enthält. Für Einträge ohne Fehlernummer hilft nur die Konvention, in Message einen festen Text zu schreiben und alles Variable nach AdditionalInfo zu legen.

Das Rollback-Problem

Ein Log-Eintrag, der in derselben Transaktion liegt wie die Arbeit, verschwindet beim ROLLBACK, also genau dann, wenn man ihn am dringendsten braucht. SQL Server kennt keine autonomen Transaktionen, ein normaler INSERT ins Log lässt sich daher nicht davor schützen.

Mein Weg dafür ist eine Table-Variable, denn die ist vom ROLLBACK nicht betroffen. Die Prozedur sammelt ihre Einträge in einer Variable vom Typ Logging.LogBuffer und schreibt sie nach COMMIT oder ROLLBACK mit Logging.FlushBuffer in die Tabelle, mit Originalzeit und in Originalreihenfolge:

DECLARE @Buf Logging.LogBuffer;

EXEC Logging.StartRun @Name = N'IMPORT', @ProcId = @@PROCID;

BEGIN TRY
    BEGIN TRAN;

    INSERT @Buf (EventType, Message) VALUES (N'IMPORT_DETAIL', N'Starte Massen-Update');
    -- ... Arbeit ...

    COMMIT;
    EXEC Logging.FlushBuffer @Buf;   -- erst flushen ...
    EXEC Logging.EndRun;             -- ... dann Lauf beenden
END TRY
BEGIN CATCH
    IF @@TRANCOUNT > 0 ROLLBACK;     -- 1. Rollback
    EXEC Logging.FlushBuffer @Buf;   -- 2. Puffer sichern
    EXEC Logging.EndRun @Success = 0;-- 3. Fehlerspalten und Dauer
    THROW;
END CATCH

Die Reihenfolge ist wichtig: Erst flushen, dann EndRun, sonst fehlt den gepufferten Einträgen die RunID, weil der Lauf schon vom Stack genommen ist.

Die Grenzen des Puffers

• Er gilt nur für die Prozedur, die ihn besitzt. Eine aufgerufene Prozedur kann nicht in den Puffer des Aufrufers schreiben, weil Table-Valued Parameters READONLY sind. Ihre normalen Logging.Info-Aufrufe gehen bei einem äußeren ROLLBACK weiterhin verloren.
• Er schützt gegen ROLLBACK, nicht gegen Abbruch. Bei KILL, Verbindungsabbruch oder Client-Timeout läuft der CATCH-Block nicht, und der Puffer ist weg. Dafür gibt es das Sicherheitsnetz im nächsten Abschnitt.

Das Sicherheitsnetz: Extended Events

Ein Tabellen-Logger sieht nur, was in einem TRY/CATCH landet und nicht zurückgerollt wird. Eine Extended-Events-Session auf error_reported sieht jeden Fehler der Datenbank, auch ohne TRY/CATCH und unabhängig von Transaktionen. Sie ergänzt den Logger, sie ersetzt ihn nicht.

Das Setup legt pro Datenbank eine Session Logging_Errors_ an. Der Kern ist ein Filter auf Severity und Datenbank-ID, als Ziel dient eine Datei mit Rollover:

ADD EVENT sqlserver.error_reported
(
    ACTION (sqlserver.database_name, sqlserver.client_app_name, sqlserver.client_hostname,
            sqlserver.username, sqlserver.session_id, sqlserver.sql_text)
    WHERE ([severity] >= 11 AND [sqlserver].[database_id] = )
)
ADD TARGET package0.event_file (SET filename = N'...', max_file_size = (50), max_rollover_files = (4))

Logging.ImportXeErrors liest die .xel-Dateien inkrementell in die Tabelle Logging.XeError, dedupliziert über Dateiname und Offset. Das sollte ein Agent-Job alle paar Minuten tun, weil die Dateien rollieren und ältere Fehler sonst verschwinden.

Das Interessante ist das Feld is_intercepted: Es sagt, ob ein TRY/CATCH den Fehler gefangen hat. Daraus entstehen zwei Auswertungen. Erstens Fehler, die ungefangen beim Client ankamen (IsIntercepted = 0). Zweitens gefangene Fehler ohne passenden Eintrag im Logger, verglichen über ErrorNumber in einem Fenster von ±5 Sekunden. Das sind CATCH-Blöcke, die den Fehler schlucken, statt ihn zu protokollieren. Ein per THROW erneut geworfener Fehler kann dabei zweimal auftauchen.

Zwei Dinge, die du wissen solltest

• Datenschutz: Die Action sql_text kann Literale und Parameterwerte mit personenbezogenen Daten enthalten. Im Setup lässt sie sich mit einer Variable abschalten, und Logging.Cleanup löscht importierte Fehler standardmäßig nach 30 Tagen.
• Rechte: Zum Anlegen der Session braucht der Login das Server-Recht ALTER ANY EVENT SESSION, zum Lesen der Dateien VIEW SERVER STATE (ab SQL Server 2022 VIEW SERVER PERFORMANCE STATE). Fehlt das Recht, überspringt das Setup nur diesen Schritt und warnt.

Installation und Migration in einem Script

Alles steckt in einem einzigen, idempotenten Script Logging_Setup.sql, das du in der Anwendungsdatenbank komplett ausführst. Es erkennt selbst, in welchem Zustand die Datenbank ist, und trägt das mit Version und Zeitpunkt in Logging.SetupHistory ein. Vorhandene Daten bleiben bei jedem Lauf erhalten.

Die Konfiguration steht als sechs Variablen ganz oben im Script: Migration ja oder nein, XE-Session ja oder nein, Verzeichnis, Dateigröße und Anzahl der .xel-Dateien sowie die Frage, ob sql_text mitgeschnitten wird. Eine Vorprüfung verlangt SQL Server 2016 und Kompatibilitätsgrad 130 oder höher, sonst bricht das Script ab, ohne etwas zu ändern.

Die Migration vom Schema Logger ist bewusst eine Opt-in-Option, weil sie eingreift. Sie verschiebt die Tabelle per ALTER SCHEMA TRANSFER, droppt die fünf alten Prozeduren LogEvent, Debug, Info, Warn und Error und legt an ihrer Stelle Synonyme auf Logging.* an, sodass bestehende Aufrufe weiterlaufen. Sichere vorher eigene Anpassungen mit sp_helptext. Existieren beide Tabellen, migriert das Script nicht, weil ich ein automatisches Zusammenführen für zu riskant halte.

Zusätzlich gibt es Logging.Cleanup für die Retention. Es löscht in Batches: DEBUG-Einträge nach 14 Tagen, alles andere nach 90 und importierte XE-Fehler nach 30. Die Werte sind Parameter. Geplant wird es nicht automatisch, dafür und für Logging.ImportXeErrors legst du Agent-Jobs an (Cleanup täglich, Import alle fünf Minuten).

Was das Framework nicht kann

Ein Tabellen-Logger ist für fachliche Prozess-Ereignisse gedacht, nicht für alles, was man in einer Datenbank protokollieren möchte. Die wichtigsten Grenzen:

• Der Lauf-Stack gilt pro Session. Er hat Platz für einige Dutzend verschachtelte Läufe. Ein vergessenes EndRun lässt den Eintrag für den Rest der Session auf dem Stack liegen, deshalb gehört EndRun auch in den CATCH-Block.
• Der Puffer schützt nur die besitzende Prozedur und nur gegen ROLLBACK, nicht gegen KILL oder Timeouts.
• Eine automatische Erkennung des direkten Aufrufers gibt es nicht. Entweder @ProcId = @@PROCID oder StartRun, sonst landet der Eintrag unter (unbekannt).

Für andere Aufgaben gibt es bessere Werkzeuge:

• Änderungen an Daten nachvollziehen: Temporal Tables, Change Tracking, CDC oder SQL Server Audit, je nachdem ob du Historie, Delta-Sync oder Compliance brauchst.
• Performance und Laufzeiten im Großen: Query Store und Extended Events, ohne Code-Änderung.
• Anwendung und Datenbank zusammen: Wenn eine .NET-App die Prozeduren aufruft, gehört das Logging eigentlich in die App, etwa mit Serilog und MSSQL-Sink oder OpenTelemetry. Den Bezug zur SQL-Seite stellst du über eine Correlation-ID her, die die App per sp_set_session_context setzt.

Fazit und Download

Aus einem einfachen Protokoll ist ein Werkzeug geworden, mit dem sich Läufe, Laufzeiten und Fehler wirklich auswerten lassen, und das auch dann etwas liefert, wenn ein ROLLBACK zuschlägt oder ein Fehler ungefangen durchrutscht. Die eigentliche Lehre war aber eine andere: Ein Review des eigenen Codes findet Fehler, die man beim Schreiben nicht sieht, etwa eine Aufruferkennung über eine DMV, die es gar nicht gibt.

Das Setup-Script und die Auswertungsabfragen findest du hier: https://github.com/gpiwonka/Logging