2017-01-02

Hide & Seek With Extended Events

Dave Mason SQL Server Extended Events

Many of the SQL Server Extended Events Targets are asynchronous. If you are new to Extended Events, this may be a little confusing, if not off-putting. And that's understandable. What's one to think when certain events have occurred, but you can't "see" any evidence of them? Most often, this is addressed by changing one or more of the Event Session options, such as MAX_DISPATCH_LATENCY. But there's another potentially confusing issue I want to take a look at: an inconsistency between the event_stream target and other targets. If you use the "Watch Live Data" grid within SSMS, this will affect you.

Here's a script I'll use to demonstrate. It creates a test database and an Event Session. The session definition includes the database_attached and database_detached events, each with a small set of actions (Global Fields) included. There are two asynchronous targets: an event_file and the ring_buffer.

CREATE DATABASE [TestDB]
 ON  PRIMARY 
( NAME = N'TestDB', FILENAME = N'D:\DBA\TestDB.mdf')
 LOG ON 
( NAME = N'TestDB_log', FILENAME = N'D:\DBA\TestDB_log.ldf')
GO

CREATE EVENT SESSION [XEventTest] ON SERVER 
ADD EVENT sqlserver.database_attached(
    ACTION(
  sqlserver.client_app_name,
  sqlserver.database_name,
  sqlserver.sql_text
 )
),
ADD EVENT sqlserver.database_detached(
    ACTION(
  sqlserver.client_app_name,
  sqlserver.database_name,
  sqlserver.sql_text
 )
)
ADD TARGET package0.event_file(SET filename=N'XEventTest'),
ADD TARGET package0.ring_buffer
WITH (
 MAX_MEMORY=4096 KB,
 EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
 MAX_DISPATCH_LATENCY=1 SECONDS,
 MAX_EVENT_SIZE=0 KB,
 MEMORY_PARTITION_MODE=NONE,
 TRACK_CAUSALITY=OFF,
 STARTUP_STATE=OFF
)
GO


After creating the session, I'll open SSMS and navigate to it within the object explorer. Right-click it and select "Start Session", then right-click it a second time and select "Watch Live Data", which opens a new tab in SSMS.

Now, let's detach a database and trigger the database_detached event:

EXEC master.dbo.sp_detach_db @dbname = N'TestDB';


When I switch to the "Live Data" grid, it's empty. Hmm. What happened?

Dave Mason SQL Server Extended Events - Live Data 01


Let's proceed slowly here. As noted earlier, the XEvent session was created with two targets. We can verify them with this query:

SELECT xet.*
FROM sys.dm_xe_session_targets AS xet
JOIN sys.dm_xe_sessions AS xes
 ON (xes.address = xet.event_session_address)
WHERE xes.name = 'XEventTest';


The query results show us the ring_buffer and event_file targets. But there's also an event_stream target. Why is it there? And where did it come from?

Dave Mason SQL Server Extended Events - dm_xe_session_targets


The event_stream typically only exists when the "Live Data" grid is open. SSMS uses the event_stream target to display XEvent data in the grid. We can't "query" target data from the event_stream target or otherwise access it in T-SQL. It's only accessible from .NET Framework applications via the XEvent .NET namespaces * More on this in the next post. But we can query the target data in the other targets.

--Ring Buffer
DECLARE @XEData XML

SELECT @XEData = CAST(xet.target_data AS XML)
FROM sys.dm_xe_session_targets AS xet
JOIN sys.dm_xe_sessions AS xes
 ON (xes.address = xet.event_session_address)
WHERE xes.name = 'XEventTest'
AND xet.target_name = 'ring_buffer';

SELECT t.c.value(N'(@name)[1]', N'NVARCHAR(MAX)') AS EventName,
 t.c.query('*') AS [EventData]
FROM @XEData.nodes('//RingBufferTarget/event') AS t(c)
GO

--Event File
SELECT object_name AS EventName,
 CAST(event_data AS XML) AS [EventData]
FROM sys.fn_xe_file_target_read_file (
 'XEventTest*.xel',
 'XEventTest*.xem', null, null);
GO
Dave Mason SQL Server Extended Events - ring_buffer event_file 01


The database_detached event was clearly received by the ring_buffer and event_file targets. But if we return to the "Live Data" tab/grid in SSMS, we still have nothing. I don't have an explanation for this. I know, that's not exactly gratifying. Nonetheless, let's press on. I'll attach the database as follows:

EXEC sp_attach_db @dbname = N'TestDB',   
    @filename1 = N'D:\DBA\TestDB.mdf',   
    @filename2 = N'D:\DBA\TestDB_log.ldf'; 


If we query the ring_buffer and event_file targets again, we see the database_attached event was received by both targets.

Dave Mason SQL Server Extended Events - ring_buffer event_file 02


Back to the "Live Data" tab/grid in SSMS. Ahhh! We have something now.

Dave Mason SQL Server Extended Events - Live Data 02


The database_detached event has been received and is in the grid. But the database_attached event that just occurred isn't there. The grid is now "one event behind". This circumstance seems to persist. If I detach (and re-attach) the database any number of times, the last event is never received by the event_stream, and accordingly, not in the "Live Data" grid either.

EXEC master.dbo.sp_detach_db @dbname = N'TestDB';
GO
Dave Mason SQL Server Extended Events - Live Data 03
EXEC sp_attach_db @dbname = N'TestDB',   
    @filename1 = N'D:\DBA\TestDB.mdf',   
    @filename2 = N'D:\DBA\TestDB_log.ldf'; 
GO
Dave Mason SQL Server Extended Events - Live Data 04


Workarounds

As has been shown above, the event_file and ring_buffer targets can be queried via T-SQL. If that's how you examine an XEvent session, you should have no worries. If you depend on the "Live Data" grid, you might consider adding a "dummy" event to the XEvent session definition. It would be an event that you could invoke on demand to displace any "hidden" events. Here's the same XEvent session from above, with an added error_reported "dummy" event:

CREATE EVENT SESSION [XEventTest] ON SERVER 
ADD EVENT sqlserver.database_attached(
    ACTION(
  sqlserver.client_app_name,
  sqlserver.database_name,
  sqlserver.sql_text
 )
),
ADD EVENT sqlserver.database_detached(
    ACTION(
  sqlserver.client_app_name,
  sqlserver.database_name,
  sqlserver.sql_text
 )
),
ADD EVENT sqlserver.error_reported(
    WHERE ([severity]=(10) AND [sqlserver].[like_i_sql_unicode_string]([message],N'%Displace Last Event%'))) 
ADD TARGET package0.event_file(SET filename=N'XEventTest'),
ADD TARGET package0.ring_buffer
WITH (
 MAX_MEMORY=4096 KB,
 EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,
 MAX_DISPATCH_LATENCY=1 SECONDS,
 MAX_EVENT_SIZE=0 KB,
 MEMORY_PARTITION_MODE=NONE,
 TRACK_CAUSALITY=OFF,
 STARTUP_STATE=OFF
)
GO


At any time you could run this RAISERROR command:

RAISERROR('Displace Last Event', 10, 1);
This will create some "noise" in the grid, but it can easily be filtered out if desired.


Apathy?

After all of this, I suppose an important question is "Do you care?" The answer, of course is (wait for it...) "It depends". If your XEvent session includes events that occur on a frequent basis, the constant influx of event data probably makes this a moot point. However, if your events are happening infrequently enough, this might be an important issue. In my next two posts (one for C#, one for PowerShell), I'll show how to use the Microsoft.SqlServer.XEvent.Linq namespace to access an event stream programmatically. For that type of task, you'll definitely care.


SHARE