Author: mikevanzap

Since logging is fundamental functionality for many SQL applications, I still ask myself what the best approach is to make SQL log for your application. In lots of my solutions I got with SQL log table approach. But there could be other ways how to implement SQL logging mechanisms. I decided to use Extended Events functionality to implement such a solution. This is powerful feature of SQL server. There are many examples on internet web sites where you can find this functionality was implemented mainly for maintenance purposes or SQL server counters monitoring. But let’s try to find another usage for this feature.

Problem

Let’s develop error log solution for simple insert query. For our solution we will use extended events.

You can create extended events in SQL Management Studio -> Management->Extended Events section as you can see on picture bellow, in this post I will use T-SQL scripts.

In short:

• Create testing database
• Create log table
• Create extended event session
• Start extended event session
• Simulate event which trigger log message
• Get data from extended event
• Put data into log table

At first, we prepare database with log table.

CREATE DATABASE LogTest
GO
USE LogTest
GO

IF OBJECT_ID('dbo.LogData') IS  NULL
CREATE TABLE dbo.LogData 
(sql_text NVARCHAR(1000),[log_datetime] DATETIME,[message] NVARCHAR(100))

The next step is to create extended event session. I named it LogTestSession. Since I would like to monitor error messages I will add object sqlserver.error_reported. It handles events connected to error messages triggered on the server. In Action section there are listed attributes we want to get from extended events. Where clause contains filters to our database (we get ID of our database) and then put it to this predicate (Because we would like to test it only on our database) Error number = 50000 means that we would like to check only user messages. As you can see there are many ways how to configure behaviour of extended events. There is not necessary to use filter and you can monitor all databases on the server and error messages. As target we use Ring buffer, it means that data will be written to memory. There is possibility to redirect extended event output to other destinations. I will not describe all possibilities in this post, more info can be found here:  https://bit.ly/2JEVDcV.

The last attribute, I used in this solution is MAX_DISPATCH_LATENCY = { seconds SECONDS | INFINITE } and here is definition directly from Microsoft sites https://bit.ly/2HCIHSD. Specifies the amount of time that events will be buffered in memory before being dispatched to event session targets. By default, this value is set to 30 seconds.

Bellow is T-SQL batch for creating extended event session.

CREATE EVENT SESSION LogTestSession ON SERVER 
    ADD EVENT sqlserver.error_reported  -- ,
      (
      ACTION (sqlserver.sql_text, sqlserver.tsql_stack, sqlserver.database_id,sqlserver.username)
       WHERE sqlserver.database_id = 33  AND [error_number]=50000 /*Filter error no or db number*/
     )   
    ADD TARGET package0.ring_buffer    
        (SET max_memory = 4096 
    ) 
WITH (max_dispatch_latency = 1 seconds)

In next step we start extended events. Since that time, we can test our mechanism.

ALTER EVENT SESSION LogTestSession ON SERVER
STATE = START

Let’s raise user message.

DECLARE @Message VARCHAR(100) = 'Hello word message '+ CONVERT(VARCHAR(20),GETDATE(),20)
RAISERROR(  @Message,1,1);
SELECT CONVERT(VARCHAR(20),GETDATE(),20)

DECLARE @Message VARCHAR(100) = 'Log message '+ CONVERT(VARCHAR(20),GETDATE(),20)
RAISERROR(  @Message,1,1);
SELECT CONVERT(VARCHAR(20),GETDATE(),20)

Now we get data from extended events. There are few useful catalos in SQL server. In the script bellow we get data from tables containing user messages and stage them into temporary table like XML.

IF OBJECT_ID('tempdb.dbo.#LogData') IS NOT NULL
 DROP TABLE #LogData;

SELECT
       CAST(LocksAcquired.TargetXml AS XML)  AS XMLData
   INTO
       #LogData
   FROM
       (
       SELECT
               CAST(t.target_data AS XML)  AS TargetXml 
           FROM
                    sys.dm_xe_session_targets  AS t
               JOIN sys.dm_xe_sessions         AS s

                   ON s.address = t.event_session_address
           WHERE
            
               s.name        = 'LogTestSession'
       )
           AS LocksAcquired;

Now let’s parse our data to our LOG table. In next step we can create one procedure from these two queries. IT would fit better in scenarios of next posts.

 
INSERT INTO  dbo.LogData  	(sql_text ,[log_datetime] ,[message]  )
SELECT
     T.XMLData.value('(action[@name="sql_text"])[1]',
            'varchar(1000)'     )  AS [SqlText],
         T.XMLData.value('(@timestamp)[1]',
            'datetime'     )  AS [OccurredDtTm],
         T.XMLData.value('(data[@name="message"])[1]',
            'varchar(60)'     )  AS [Message]
    FROM
        #LogData
    CROSS APPLY XMLData.nodes('/RingBufferTarget/event[@name="error_reported"]')  AS T(XMLData);

Look to our log table and voila. Log messages are there.

SELECT * FROM dbo.LogData

Clean up our solution.

IF EXISTS (SELECT *
      FROM sys.server_event_sessions  
     WHERE name = 'LogTestSession')
BEGIN
    DROP EVENT SESSION LogTestSession
          ON SERVER;    
END

In this post I demonstrate how Extended Events could be used for logging purposes. Be aware that this approach does not come with real-time solution but with the asynchronous one. So, it cannot fit to every solution. On the other hand Extended Events are not in scope of transaction. Furthermore, here raise other questions which could be answered in other posts.

• Handling error messages within transactions
• What about extended events and their performance?
• Ring buffer is still increasing, do we have solution to clean it up?
• It could be interesting to compare this solution with classic approach within transaction scope
• Whatever idea you get….

Stay tuned, stay strong

PS: if you would like to play, you can download the whole script here ext_events_log.