Queries not logging when using Extended Events in MS-SQL Server to track queries

Question

I'm using MS-SQL Server 2012 Standard, running on Windows Server 2012 RTM. I used SSMS to create a Extended Event Session, where I used the built-in "Batch Query Tracking" template and save the result to a file.

I have a database named "mydb" with a "dbo.mytable" table in it. At one point I tested this on a different box, and following the above steps, the queries would get logged to the extended event tracking, but on this new box (using the same AWS AMI, a day later), any query on "dbo.mytable" are not being recorded.

By default, the Batch Query Tracking template has a filter on batch_sql_completed (is_system=0 and dbid>4). I removed these, and other system queries log. I verified the Extended Event Session is running. I also tried the "Detailed Query Tracking" template, to make sure it wasn't that template that I used before.

My goal is to simply audit all queries run on the database. The test queries I ran were simple inserts into "mytable" and select-all's. I'm running the queries through SSMS.

Any ideas on why these queries would not be logged? Let me know what other information I can provide. Thanks!

More details on my testing

Creating the Extended Event Session:

• Go to "New Session.." right-click menu option in SSMS (under Management -> Extended Events)
• Enter following information:
  • Session name: log-queries
  • Template: Query Batch Tracking
  • Schedule: Start the event session at server startup; Start immediately after creation
  • Causality tracking: Track how events related to one another.
  • Data Storage: event_file, C:\logs\log-queries.xel
• Verify it is running:
  • select * from sys.dm_xe_sessions;
  • Verified: I see it in the list

About my test database:

• Database: mydb
• Table: dbo.mytable (cid nchar(10), cname nchar(10), city nchar(10))
  • ("dbo" is the schema; one of the default options when I created)
• Query: SELECT TOP 1000 [cid], [cname], [city] FROM [mydb].[dbo].[mytable]

Verifying if logging working:

• Following this tutorial, extract the statements from log file, and I look for my query in the result:

IF OBJECT_ID('tempdb..#ExEvent') IS NOT NULL DROP TABLE #ExEvent

SELECT IDENTITY(INT,1,1) AS RowId, object_name AS event_name, CONVERT(XML,event_data) AS event_data
    INTO #ExEvent
FROM sys.fn_xe_file_target_read_file(N'C:\logs\*.xel', null, null, null);


SELECT ISNULL(t_action.RowId, t_data.RowId) AS RowId
        , ISNULL(t_action.event_name, t_data.event_name) AS event_name
        , t_action.[client_hostname], t_action.[collect_system_time], t_action.[database_name], t_action.[query_plan_hash], t_action.[server_principal_name], t_action.[session_id]
        , t_data.[collect_statement], t_data.[connection_reset_option], t_data.[cpu_time], t_data.[data_stream], t_data.[duration], t_data.[last_row_count], t_data.[line_number], t_data.[logical_reads], t_data.[object_name], t_data.[offset], t_data.[offset_end], t_data.[output_parameters], t_data.[parameterized_plan_handle], t_data.[physical_reads], t_data.[result], t_data.[row_count], t_data.[statement], t_data.[writes]
    FROM (
            SELECT RowId, event_name, [client_hostname], [collect_system_time], [database_name], [query_plan_hash], [server_principal_name], [session_id]                  
                FROM (
                        SELECT RowId
                                , event_name
                                , T2.Loc.query('.').value('(/action/@name)[1]', 'varchar(max)')AS att_name
                                , T2.Loc.query('.').value('(/action/value)[1]', 'varchar(max)')AS att_value
                        FROM   #ExEvent
                        CROSS APPLY event_data.nodes('/event/action') as T2(Loc)
                        WHERE T2.Loc.query('.').value('(/action/@name)[1]', 'varchar(max)')
                            IN ('client_hostname', 'collect_system_time', 'database_name', 'query_plan_hash', 'server_principal_name', 'session_id')
                    ) AS SourceTable
                        PIVOT(
                            MAX(att_value)
                            FOR att_name IN ([client_hostname], [collect_system_time], [database_name], [query_plan_hash], [server_principal_name], [session_id])
                    ) AS PivotTable
            ) AS t_action

        -- Full outer because it might be no events selected only the payload
        FULL OUTER JOIN (
            SELECT RowId, event_name, [collect_statement], [connection_reset_option], [cpu_time], [data_stream], [duration], [last_row_count], [line_number], [logical_reads], [object_name], [offset], [offset_end], [output_parameters], [parameterized_plan_handle], [physical_reads], [result], [row_count], [statement], [writes]
                FROM (
                        SELECT RowId
                                , event_name
                                , T3.Loc.query('.').value('(/data/@name)[1]', 'varchar(max)') AS att_name
                                , T3.Loc.query('.').value('(/data/value)[1]', 'varchar(max)') AS att_value

                            FROM   #ExEvent
                            CROSS APPLY event_data.nodes('/event/data') as T3(Loc)
                            WHERE T3.Loc.query('.').value('(/data/@name)[1]', 'varchar(max)')
                                IN ('collect_statement', 'connection_reset_option', 'cpu_time', 'data_stream', 'duration', 'last_row_count', 'line_number', 'logical_reads', 'object_name', 'offset', 'offset_end', 'output_parameters', 'parameterized_plan_handle', 'physical_reads', 'result', 'row_count', 'statement', 'writes')
                        ) AS SourceTable
                            PIVOT (
                            MAX(att_value)
                                FOR att_name IN ([collect_statement], [connection_reset_option], [cpu_time], [data_stream], [duration], [last_row_count], [line_number], [logical_reads], [object_name], [offset], [offset_end], [output_parameters], [parameterized_plan_handle], [physical_reads], [result], [row_count], [statement], [writes])
                        ) AS PivotTable

            ) AS t_data
            ON t_data.RowId = t_action.RowId

Answer 1

If you used that template, it should definitely be logging the queries you ran from SSMS.

Extended Event sessions don't start by default when you create them - you need to tell them to start. Perhaps you did that on the other server, but not in this second case?

You can check to see if the session is running by look at the results of:

select * from sys.dm_xe_sessions

If your session is not in that result set, it's not running.

You can start the session up by running:

ALTER EVENT SESSION your_session_name
ON SERVER  
STATE = start;

If you confirm it's running, and you're still not seeing results in your file, please script out the event session in SSMS and update your question with the results. Perhaps it's configured differently by mistake, or it is writing the file to a place you don't expect.

---

Fantastic job adding those details to your question, that was really helpful.

It sounds like what you were running into is what Shawn Melton mentions in his answer here.

In short, events (queries, in this case) are only written to that file when the MAX_DISPATCH_LATENCY (defaults to 30 seconds) or MAX_MEMORY (defaults to 4 MB) is reached.

For what it's worth, I have experienced that MAX_DISPATCH_LATENCY is not always enforced (i.e., if the MAX_MEMORY buffer limit is not reached, the file is not updated - even if it's been longer than 30 seconds). However, as Shawn mentioned, stopping the event session flushes the entire buffer of events into the file.

Answer 2

Problem was with me trying to use the Batch Query Tracking template for my Extended Events Session creation.

When I follow this tutorial, and create a session as follows, the logging works as expected:

CREATE EVENT SESSION [What I do] ON SERVER

ADD EVENT sqlserver.rpc_completed(SET collect_statement=(1)
    ACTION(package0.collect_system_time,sqlserver.client_hostname,sqlserver.database_name,sqlserver.query_plan_hash
            ,sqlserver.server_principal_name,sqlserver.session_id)),

ADD EVENT sqlserver.sql_statement_completed(SET collect_parameterized_plan_handle=(0),collect_statement=(1)
    ACTION(package0.collect_system_time,sqlserver.client_hostname,sqlserver.database_name,sqlserver.query_plan_hash
            ,sqlserver.server_principal_name,sqlserver.session_id))

ADD TARGET package0.event_file(SET filename=N'C:\logs\WhatIdo.xel')

WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB
        ,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF)
GO