T-SQL "Tracing" (Extended Events)

Sehr oft möchte man aus diversen eigenen T-SQL-Abläufen heraus ein "Tracing" bzw. "Debug-Infos" erreichen , d.h. , z.B. in Datenbankprozeduren eine Ausgabe bestimmter Infos an bestimmten Ausführungsstellen.

Oder in SQL-Triggern etc.

Dieses "Tracing" möchte man im Idealfall auch zur Laufzeit in der ausgerollten Version der Anpassung beim Kunden aktivieren oder deaktivieren können.

Die allseits bekannte T-SQL "PRINT"-Anweisung hat per Default nur z.B. im Microsoft SQL-Management Studio eine Auswirkung , bei der gezielten Ausführung einzelner SQL-Elemente , wie z.B. einer SQL-Datenbankprozedur.

Daher ist dies in der Praxis für viele Szenarien nur bedingt eine Hilfe.

Performanter Lösungsansatz über "RAISERROR" und "Extended Events"

Ein sehr einfach umzusetzender und zudem performanter Weg ist , z.B. in der eigenen Datenbankprozedur an entsprechenden Stellen eine passende Text-Meldung mit "RAISERROR" und dem Typ "10" (Info) auszulösen.

Dies funktioniert auch später zur Laufzeit bei der Kundeninstallation und eine Überwachung lässt sich bei Bedarf ein- und ausschalten.

⚠️Wichtig ist , dass man sich eine eindeutige Nomenklatur überlegt , wie man das "Tracing" bzw. Protokollieren aufbaut.

DECLARE @sTracePrefix AS VARCHAR(12)
DECLARE @sTraceMessage AS VARCHAR(2048)

SET @sTracePrefix = 'SAG: TRACE: '

SET @sTraceMessage = @sTracePrefix + '(my log text) started ...'
RAISERROR(@sTraceMessage, 10, 1) WITH NOWAIT

-- some code...

SET @sTraceMessage = @sTracePrefix + '(my log text) finished.'
RAISERROR(@sTraceMessage, 10, 1) WITH NOWAIT

⚠️Im Beispiel wird immer der feste Präfix 'SAG: TRACE: ' benutzt.

Dies ist entscheidend.

Event-Session einrichten und starten

Basis für die Überwachung ist eine Event-Session der "Extended Events" des SQL-Servers (in UX/UI im SQL-Management Studio sinnvoll erst ab SQL Server 2012 nutzbar).

Diese Event-Session kann man sich wie folgt mit einem gezielten eigenen Namen einrichten - in dem Fall "SAGSageRuntimeTrace".

Dieser Name erscheint dann später auch im SQL Management Studio zum einfachen Filtern!

CREATE EVENT SESSION [SAGSageRuntimeTrace] ON SERVER 

ADD EVENT sqlserver.error_reported(
ACTION( sqlserver.database_name
, sqlserver.client_app_name
, sqlserver.session_id
, sqlserver.tsql_stack -- Captures exactly which proc fired it
)

WHERE ( [severity] = (10) AND [message] LIKE 'SAG: TRACE:%' ) )

-- Target: Where to store the data. A Ring Buffer keeps it purely in RAM (very fast, overwrites old data when full).
ADD TARGET package0.ring_buffer(SET max_memory=(4096))

-- Do not(!) start automatically if the SQL Server reboots
WITH (STARTUP_STATE=OFF)

GO

Event-Session starten

Per Default startet die Event-Session nicht(!) von alleine.

Dies muss man gezielt aktivieren und deaktivieren - das ist eine bewusste und sinnvolle Design-Entscheidung von Microsoft.

-- Start the session immediately
ALTER EVENT SESSION [SAGSageRuntimeTrace] ON SERVER STATE = START

Event-Session in Realtime auslesen/überwachen

Im Microsoft "SQL Server Management Studio (SSMS)" wechselt man auf der Server-Ebene in "Management" -> "Extended Events" -> "Sessions".

Ansicht SQL Management Studio - Management - Extended Events

Dort erscheint die eigene Sitzung - in dem Fall mit dem o.g. Namen "SAGSageRuntimeTrace".

Mit rechter Maustaste auf der Sitzung kann mittels "Watch Live Data" eine Überwachungsanzeige geöffnet werden (wenn die Aufzeichnung aktiv ist; diese lässt sich auch direkt über rechte Maustaste im Kontextmenü starten und beenden).

Im Text sieht man dann die Aufzeichnungsdetails , wenn man die Zeile anklickt.

Ansicht eines "Trace"- / "Debug"-Eintrags , der aus einer Datenbankprozedur ausgelöst wurde

Anmerkung: Man darf sich nicht "verwirren" lassen , dass u.U. eine Fehlerkategorie angezeigt wird. Typ "10" ist per Default wirklich nur eine Info.

Die o.g. Meldung wurde z.B. mit T-SQL in der SQL-Datenbankprozedur wie folgt aus den Kontext-Variablen im Code der Prozedur zusammengestellt.

SET @sTraceMessage = 'SAG: TRACE: Document is checked: '  + 'Mandant=' + ISNULL(CAST(@nMan AS VARCHAR(10)), 'NULL') + ' | '  + 'Type=' + ISNULL(@sDocumentType, 'NULL') + ' | '  + 'Recipient=' + ISNULL(@sDocumentRecipient, 'NULL') + ' | '  + 'Group=' + ISNULL(@sDocumentRecipientGroup, 'NULL') + ' | '  + 'StatusSperre=' + ISNULL(CAST(@nStatusSperre AS VARCHAR(10)), 'NULL')

RAISERROR(@sTraceMessage, 10, 1) WITH NOWAIT

Event-Session beenden

Am Ende darf man nicht vergessen , die Aufzeichnung wieder zu beenden!

ALTER EVENT SESSION [SAGSageRuntimeTrace] ON SERVER STATE = STOP

Damit wird die Aufzeichnung angehalten. Die Anweisungen für die "RAISERROR" laufen für die Extended Events Leere und haben dort keinen Endpunkt , der diese auswertet.

Allerdings verarbeitet der SQL-Server natürlich intern die "RAISERROR" , was weitere Vorteile bietet (siehe nächster Punkt).

Anmerkung: Das Starten und Stoppen der Event-Sessions ist natürlich auch über die UX/UI des SQL-Management Studios möglich.

Weitere Nutzungsmöglichkeiten

Die SQL Server-Engine überträgt "RAISERROR"-Nachrichten mit Typ "10" - also mit Informationscharakter - weiterhin über das Netzwerk an diejenige Client-Anwendung , welche die Datenbankverbindung initiiert hat.

Da es sich um eine Nachricht mit dem Schweregrad 10 (Severity 10) - Information - handelt , behandelt der SQL Server sie wie eine "PRINT"- oder reine Informationsnachricht und nicht(!) als kritischen Fehler , der z.B. eine Transaktion abbricht.

Der Server leitet diese Zeichenfolge über das Tabular Data Stream (TDS)-Protokoll an den Aufrufer zurück.

So interagieren verschiedene Endpunkte damit:

SQL Server Management Studio (SSMS):
SSMS lauscht aktiv auf diese Nachrichten. Das ist der Grund, warum Ihr Trace-Text in der Registerkarte „Meldungen“ (Messages) erscheint, wenn Sie die gespeicherte Prozedur in einem SSMS-Abfragefenster ausführen.

.net-Anwendungen (ADO .net)
Jede .net-Anwendung kann auf diese Nachrichten lauschen, indem sie sich in das System.Data.SqlClient.SqlConnection.InfoMessage-Ereignis einklinkt. Wenn ein Entwickler explizit Code wie ...

myConnection.InfoMessage += new System.Data.SqlClient.SqlInfoMessageEventHandler(MyHandler);

... schreibt, empfängt seine Software die o.g. Zeichenfolgen und kann diese nach Bedarf verarbeiten.

Andere Treiber (ODBC, JDBC, PHP, usw.): Fast alle Datenbanktreiber verfügen über einen ähnlichen Mechanismus , um nicht-fatale Warnungen und Informationsnachrichten vom Server zu empfangen und bei Bedarf weiterzuverwenden.

English

Background

Very often, you want to achieve "tracing" or output "debug info" from various custom T-SQL processes - i.e., outputting specific information at particular execution points within stored procedures, for example.

Or in SQL triggers, etc.

Ideally, you also want to be able to enable or disable this tracing at runtime in the rolled-out version of the customisation at the client's site.

The widely known T-SQL 'PRINT' statement defaults to having an effect only in places like Microsoft SQL Server Management Studio (SSMS) during the targeted execution of individual SQL elements, such as a SQL stored procedure.

Therefore , in practice , this is only of limited help for many scenarios.

High-performance solution using "RAISERROR" and "Extended Events"

A very easy-to-implement and high-performance approach is to trigger a suitable text message with 'RAISERROR' and a severity level of "10" (Info) at appropriate points within your own stored procedure.

This also works later at runtime within the client's installation, and monitoring can be switched on and off as needed.

⚠️ It is important to decide on a clear nomenclature for how you structure your tracing or logging.

DECLARE @sTracePrefix AS VARCHAR(12)
DECLARE @sTraceMessage AS VARCHAR(2048)

SET @sTracePrefix = 'SAG: TRACE: '

SET @sTraceMessage = @sTracePrefix + '(my log text) started ...'
RAISERROR(@sTraceMessage, 10, 1) WITH NOWAIT

-- some code...

SET @sTraceMessage = @sTracePrefix + '(my log text) finished.'
RAISERROR(@sTraceMessage, 10, 1) WITH NOWAIT

⚠️ In the example, the fixed prefix 'SAG: TRACE: ' is consistently used. This is crucial.

Setting up and starting the event session

The basis for the monitoring is an "Extended Events" event session in SQL Server (which realistically only became usable via the UX/UI in SQL Server Management Studio from SQL Server 2012 onwards).

You can set up this event session with a specific custom name as follows - in this case, 'SAGSageRuntimeTrace'.

This name will later appear in SQL Server Management Studio for easy filtering!

CREATE EVENT SESSION [SAGSageRuntimeTrace] ON SERVER 

ADD EVENT sqlserver.error_reported(
ACTION( sqlserver.database_name
, sqlserver.client_app_name
, sqlserver.session_id
, sqlserver.tsql_stack -- Captures exactly which proc fired it
)

WHERE ( [severity] = (10) AND [message] LIKE 'SAG: TRACE:%' ) )

-- Target: Where to store the data. A Ring Buffer keeps it purely in RAM (very fast, overwrites old data when full).
ADD TARGET package0.ring_buffer(SET max_memory=(4096))

-- Do not(!) start automatically if the SQL Server reboots
WITH (STARTUP_STATE=OFF)

GO

Starting the event session

By default, the event session does not(!) start on its own.

You have to explicitly enable and disable it - this is a deliberate and sensible design decision by Microsoft.

-- Start the session immediately
ALTER EVENT SESSION [SAGSageRuntimeTrace] ON SERVER STATE = START

Reading/monitoring the event session in real time

In Microsoft "SQL Server Management Studio (SSMS)", navigate at the server level to Management -> Extended Events -> Sessions.

View of SQL Management Studio - Management - Extended Events

Your custom session will appear there - in this case, with the aforementioned name 'SAGSageRuntimeTrace'.

By right-clicking the session, you can open a monitoring view via "Watch Live Data" (provided the recording is active; it can also be started and stopped directly from the right-click context menu).

You will then see the recording details in the text area when you click on the row.

View of a "Trace" / "Debug" entry , created within a stored procedure

Note: Do not be confused if an error category is displayed. Severity "10" is, by default, genuinely just an informational message.

The above message was compiled from context variables in the procedure's code using T-SQL, for example, like this:

SET @sTraceMessage = 'SAG: TRACE: Document is checked: '  + 'Mandant=' + ISNULL(CAST(@nMan AS VARCHAR(10)), 'NULL') + ' | '  + 'Type=' + ISNULL(@sDocumentType, 'NULL') + ' | '  + 'Recipient=' + ISNULL(@sDocumentRecipient, 'NULL') + ' | '  + 'Group=' + ISNULL(@sDocumentRecipientGroup, 'NULL') + ' | '  + 'StatusSperre=' + ISNULL(CAST(@nStatusSperre AS VARCHAR(10)), 'NULL')

RAISERROR(@sTraceMessage, 10, 1) WITH NOWAIT

Stopping the event session

Don't forget to stop the recording at the end!

ALTER EVENT SESSION [SAGSageRuntimeTrace] ON SERVER STATE = STOP

This pauses the recording. The 'RAISERROR' statements run into the void as far as Extended Events are concerned, as there is no endpoint evaluating them there.

However, SQL Server naturally still processes the 'RAISERROR' internally, which offers further advantages (see the next point).

Note: Starting and stopping event sessions is , of course , also possible via the UX/UI of SQL Server Management Studio.

Additional use cases

The SQL Server engine continues to transmit 'RAISERROR' messages with severity "10" - i.e. , of an informational nature - over the network to the client application that initiated the database connection.

Because it is a message with severity 10 (Information) , SQL Server treats it as a 'PRINT' or purely informational message, and not(!) as a critical error that would abort a transaction , for example.

The server passes this string back to the caller via the Tabular Data Stream (TDS) protocol.

Here is how various endpoints interact with it:

SQL Server Management Studio (SSMS): SSMS actively listens for these messages. That is why your trace text appears in the "Messages" tab when you execute the stored procedure in an SSMS query window.

.net Applications (ADO .net):
Any .net application can listen to these messages by hooking into the
'System.Data.SqlClient.SqlConnection.InfoMessage' event. If a developer explicitly writes code such as...

myConnection.InfoMessage += new System.Data.SqlClient.SqlInfoMessageEventHandler(MyHandler);

...their software will receive the aforementioned strings and can process them as needed.

Other Drivers (ODBC, JDBC, PHP, etc.): Almost all database drivers feature a similar mechanism for receiving non-fatal warnings and informational messages from the server and utilising them if required.

OFFICIUM INSERVIO IT