Recently, I wanted to play around with the auto_stats event against a test system running SQL Server 2014. I ran through the session setup GUI and added the auto_stats event. I configured it with a filter (predicate) to only show me auto_stats event in a database named AutoStatsTest. There’s a cost to events that may fire frequently and a cost to filters, but this is my test box and I was just using this to learn– so no biggie, right?
The wizard worked just fine. It created a session which scripted out as this:
|
1 2 3 4 5 6 7 8 |
CREATE EVENT SESSION [AutoStatsTest] ON SERVER ADD EVENT sqlserver.auto_stats( WHERE ([database_name]=N'AutoStatsTest')) ADD TARGET package0.event_file(SET filename=N'S:\XEvents\Traces\AutoStatsTest') WITH (MAX_MEMORY=4096 KB, EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS, MAX_DISPATCH_LATENCY=5 SECONDS, MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE, TRACK_CAUSALITY=OFF, STARTUP_STATE=OFF) GO |
I started up the session and started running some code to create the AutoStatsTest database, populate data in a table, and then run some SELECT queries. I left the auto_create_statistics property enabled on the database so that the SELECT queries should trigger automatic creation of stats. I then deleted data and ran the selects again.
After running my code, I opened up my trace file and saw…. nothing.
Hmm. I thought maybe it was a latency issue. I waited and re-checked the file. I reran the code. No change. I set it up from the beginning, same thing happened. I drank more coffee.
Then I realized I had probably screwed up my filter.
I had set up a filter on my “Filter (predicate)” tab, but I hadn’t actually told it to collect database_name. I went back in and checked that off.
Now the session scripts out a bit differently — we’ve got SET collect_database_name=(1) in there:
|
1 2 3 4 5 6 |
CREATE EVENT SESSION [AutoStatsTest] ON SERVER ADD EVENT sqlserver.auto_stats(SET collect_database_name=(1) WHERE ([database_name]=N'AutoStatsTest')) ADD TARGET package0.event_file(SET filename=N'S:\XEvents\Traces\AutoStatsTest') WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF) GO |
After recreating the trace with the new definition and saving it off, I re-ran my test script and this time it worked as expected: I got trace data to explore!
The Extended Events wizard can be a little rough around the edges. It didn’t warn me that I was doing something problematic. But it also made it pretty easy to set up my trace, and also test my theory about what was wrong with it.
Summing up: when you set up an Extended Events trace, just because you set a filter or predicate on a field doesn’t necessarily mean that it can use the filter. You may have to additionally specify that the field needs to be collected.
8 Comments. Leave new
Hi Kendra,
Thank you for this clarification. It’s so true.
I remember that there was a similar problem in Profiler many years ago. I think it was SQL Server 2000. If you set a filter on the “DatabaseName” field, it just didn’t work. Only the “DatabaseId” field worked. Of course, this wasn’t a matter of not collecting the field. It was simply a bug. But I don’t trust the “DatabaseName” field ever since, and I always use the “DatabaseId” field instead.
It’s funny that when I started to use Extended Events, I automatically applied my habits and used the “DatabaseId” field for filtering, so I have never tried using the “DatabaseName” field as a filter in Extended Events.
Maybe now that I know it’s working (after specifying that I would like to collect it), I’ll start using it.
Thanks!
Another “gotcha” with Extended Events is that “Watch Live Data” has a minimum 200K buffer (you can tweak it via Advanced/Memory Max Size), which means that a small SQL statement may not trigger output to the viewer – i.e it stays stubbornly blank, as though it’s not actually working.
Running the same statement (or any statement that satisfies the Extended Event criteria) a few times (depending on the statement size) then kicks it into life.
Nice thread on it here: http://dba.stackexchange.com/questions/86388/visualizing-sql-server-extended-events-data
Oh, interesting!
I’ll admit, I don’t use “watch live data” much at all anymore. I’ve seen it crash SSMS on people while they were doing demos, and also found a lot of weird quirks like what you’re describing here, so what I do now is usually just open the target directly. Having the data refresh in front of me turns out to not really be so needed.
Kendra
And yet … there have been several troubleshooting occasions where a user/colleague initiated a process, with me watching the Profiler output to see if a particular event pops-up. Not fancy, but useful. So, a trustworthy Watch Live Data output would be a winner. Else, it’s XML gymnastics to get at the data in a file, after – way after – the event.
Not really seeing the Fab Factor going up to 11, here.
Today I experienced how it messes up the filters. All single quotes magically become triple quotes when editing an EE through the GUI. Took me a while to figure out why my filter all of a sudden does not work. So I script the EE out and make manual changes and then run the sql code.
Why do I filter, to reduce the load I need to process later.
Check here: http://www.sqldoubleg.com for some nice code to import EE data into a table.
I have a crazy one where I setup a session to track password changes. DEV and TST no one mentions anything, I think it’s great, ready for prime time! So I roll it into production on all of our servers and WHAM! Timeouts start happening on large inserts, people are getting mad, and we can’t figure it out!
The funny thing is if you Google “Extended Event Latency”, it will serve up articles on how to track latency with Extended Events rather than help solve a rather large problem seemingly caused by the freshly promoted ee session.
Am I filtering too much, or is it the LIKE that is causing me problems? I have only been troubleshooting for a day, but so far, no luck.
CREATE EVENT SESSION [WhoDunnit] ON SERVER
ADD EVENT sqlserver.sql_statement_starting(SET collect_statement=(1)
ACTION(sqlserver.client_app_name,sqlserver.database_name,sqlserver.nt_username,sqlserver.sql_text,sqlserver.username)
WHERE ([sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’ALTER%ROLE %’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’CREATE USER %’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’DROP USER%’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’GRANT % TO %’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’DENY % TO %’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’REVOKE %’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’DROP LOGIN %’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’ALTER LOGIN %’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’CREATE%ROLE %’)
OR [sqlserver].[like_i_sql_unicode_string]([sqlserver].[sql_text],N’ALTER AUTHORIZATION ON DATABASE::%’)
)
)
ADD TARGET package0.event_file(SET filename=N’D:\WhoDunnit.xel’)
WITH (MAX_MEMORY=8192 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=5 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=PER_CPU,TRACK_CAUSALITY=ON,STARTUP_STATE=ON)
GO
UUGH, Permission not Password changes
Got it figured out. Think of it as a line to get into a jobsite, your work will be delayed if you check everyone before they do their job, so it will be better to check them on their way out and not interrupt the flow of work getting done.
I had to change
ADD EVENT sqlserver.sql_statement_starting
to
ADD EVENT sqlserver.sql_statement_completed