Capture Execution Plan Warnings using Extended Events

We’re teaching IEPTO2 in Dublin this week (and if Ireland is not on your list of places to see in this lifetime, you must add it… it’s fantastic here) and today I finished up the Query Plan Analysis module. One thing I cover is interesting things you can find in the query plan, for example:

• NoJoinPredicate (2005 and higher)
• ColumnsWithNoStatistics (2005 and higher)
• UnmatchedIndexes (2008 and higher)
• PlanAffectingConvert (2012 and higher)

These attributes are good to look for when you’re looking at a single plan, or set of plans, as you’re tuning. But if you want to be a little more proactive, you can start to mine the plan cache and look for them there. Of course, doing so requires writing some XQuery, since the plans are XML (for details about the showplan schema, check out: http://schemas.microsoft.com/sqlserver/2004/07/showplan/). I don’t love XML, though not for lack of trying, and when one of the attendees asked if you could capture queries that had the NoJoinPredicate attribute through Extended Events, I thought, “What a great idea, I'll have to check.”

Sure enough, there’s an Event for that. There’s an Event for all four of the ones I listed above:

• missing_join_predicate
• missing_column_statistics
• unmatched_filtered_indexes
• plan_affecting_convert

Nice. Setting these up in an Extended Events session is pretty straight-forward. In this case, I would recommend using the event_file target, as you will probably start the event session and let it run for a bit before you go back and review the output. I have included a few actions, with the hope that these events aren’t fired that often, so we’re not adding too much overhead here. I included sql_text even though it’s not an action that you should truly rely upon. Jonathan has discussed this before, but sql_text is just giving you the inputbuffer, so you may not be getting the full story for the query. For that reason, I also included plan_handle. The caveat there being that, depending on when you go look for the plan, it may no longer be in the plan cache.

-- Remove event session if it exists
IF EXISTS (SELECT 1 FROM [sys].[server_event_sessions]
WHERE [name] = 'InterestingPlanEvents')
BEGIN
  DROP EVENT SESSION [InterestingPlanEvents] ON SERVER
END
GO

-- Define event session
CREATE EVENT SESSION [InterestingPlanEvents]
ON SERVER
ADD EVENT sqlserver.missing_column_statistics
(
  ACTION(sqlserver.database_id,sqlserver.plan_handle,sqlserver.sql_text)
  WHERE ([package0].[equal_boolean]([sqlserver].[is_system],(0))
    AND [sqlserver].[database_id]>(4))
),
ADD EVENT sqlserver.missing_join_predicate
(
  ACTION(sqlserver.database_id,sqlserver.plan_handle,sqlserver.sql_text)
  WHERE ([sqlserver].[is_system]=(0) AND [sqlserver].[database_id]>(4))
),
ADD EVENT sqlserver.plan_affecting_convert
(
  ACTION(sqlserver.database_id,sqlserver.plan_handle,sqlserver.sql_text)
  WHERE ([package0].[equal_boolean]([sqlserver].[is_system],(0))
    AND [sqlserver].[database_id]>(4))
),
ADD EVENT sqlserver.unmatched_filtered_indexes
(
  ACTION(sqlserver.plan_handle,sqlserver.sql_text)
  WHERE ([package0].[equal_boolean]([sqlserver].[is_system],(0))
    AND [sqlserver].[database_id]>(4))
)
ADD TARGET package0.event_file
(
  SET filename=N'C:\temp\InterestingPlanEvents' /* change location if appropriate */
)
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=ON,STARTUP_STATE=OFF)
GO

-- Start the event session
ALTER EVENT SESSION [InterestingPlanEvents] ON SERVER STATE=START;
GO

Once we have the event session up and running, we can generate these events with the sample code below. Note that this code assumes a fresh install of AdventureWorks2014. If you don’t have one, you may not see the missing_column_statistics event fire if you’re queried the [HireDate] column in [HumanResources].[Employee].

-- These queries assume a FRESH restore of AdventureWorks2014
ALTER DATABASE [AdventureWorks2014] SET AUTO_CREATE_STATISTICS OFF;
GO

USE [AdventureWorks2014];
GO

CREATE INDEX [NCI_SalesOrderHeader] ON [Sales].[SalesOrderHeader] (
[PurchaseOrderNumber], [CustomerID], [TotalDue], [DueDate]
)
WHERE [SubTotal] > 10000.00;
GO

/*
No join predicate
NOTE: We clear procedure here because the event ONLY fires for the *initial* compilation
*/
DBCC FREEPROCCACHE; /* Not for production use */

SELECT [h].[SalesOrderID], [d].[SalesOrderDetailID], [h].[CustomerID]
FROM [Sales].[SalesOrderDetail] [d],
[Sales].[SalesOrderHeader] [h]
WHERE [d].[ProductID] = 897;
GO

-- Columns with no statistics
SELECT [BusinessEntityID], [NationalIDNumber], [JobTitle], [HireDate], [ModifiedDate]
FROM [HumanResources].[Employee]
WHERE [HireDate] >= '2013-01-01';
GO

-- Unmatched Index
DECLARE @Total MONEY = 10000.00;

SELECT [PurchaseOrderNumber], [CustomerID], [TotalDue], [DueDate]
FROM [Sales].[SalesOrderHeader]
WHERE [SubTotal] > @Total;
GO

-- Plan Affecting Convert
SELECT [BusinessEntityID], [NationalIDNumber], [JobTitle], [HireDate], [ModifiedDate]
FROM [HumanResources].[Employee]
WHERE [NationalIDNumber] = 345106466;
GO

ALTER EVENT SESSION [InterestingPlanEvents]
ON SERVER
STATE=STOP;
GO

DROP EVENT SESSION [InterestingPlanEvents]
ON SERVER;
GO

NOTE: AFTER you have finished pulling plans from cache, you can run the ALTER statement to enable the auto create statistics option. Doing so at this point will clear the plan cache and you'll have to start all over with your testing.  (And also wait until you're done to drop the index.)

ALTER DATABASE [AdventureWorks2014] SET AUTO_CREATE_STATISTICS ON;
GO

DROP INDEX [NCI_SalesOrderHeader] ON [Sales].[SalesOrderHeader];
GO

Since I’ve stopped the event session, I’ll open the output file in SSMS to see what we captured:

Output from Extended Events

For our first query with a missing join predicate, we have one event that shows up, and I can see the text for the query in the sql_text field. However, what I really want is to look at the plan too, so I can take the plan_handle and check sys.dm_exec_query_plan:

SELECT query_plan FROM sys.dm_exec_query_plan
(0x06000700E2200333405DD12C0000000001000000000000000000000000000000000000000000000000000000);

And opening that in SQL Sentry Plan Explorer:

Missing Join Predicate

The plan has a visual indicator of the missing join predicate in the nested loop (the red X), and if I hover over it I see the warning (and it’s in the XML for the plan). Excellent…I can now go talk to my developers about rewriting this query.

The next event is for a missing column statistic. I completely forced this situation by turning AUTO_CREATE_STATISTICS off for the AdventureWorks2014 database. I do not recommend this in any way, shape, or form. This option is enabled by default and I recommend always leaving it enabled. Turning it off is the easiest way to generate this event, however. I again have the query in the sql_text field, but I’ll use the plan_handle again to pull the plan:

SELECT query_plan FROM sys.dm_exec_query_plan
(0x060007004448323810921C360000000001000000000000000000000000000000000000000000000000000000);

Missing Statistic

And we again have a visual cue (the yellow triangle with the exclamation mark) to indicate that there’s an issue with the plan, and again it’s in the XML. From here, I’d first check to see if AUTO_CREATE_STATISTICS is disabled, and if not, I’d start running the query in Management Studio to see if I can recreate the warning (and coerce the statistics to create).

Now, the remaining events are a bit more interesting.

You’ll notice that we have three unmatched_filtered_indexes events. I have yet to determine why, but I’m working on it and will post in the comments if/when I get it sorted. For now, it’s enough that I have the event, and within the event we can also see object information so I know the index in question:

NCI_SalesOrderHeader index referenced by missing index event

And I can again take the plan_handle to find the query plan:

Unmatched index

This time I see the warning in the SELECT operator, so I know there’s something I need to investigate further. In this case, you do have options to get the optimizer to use the filtered index when you’re using parameters, and I recommend going through Aaron’s post for more information on using filtered indexes.

Lastly, we have nine events for plan_affecting_convert. What the heck? I’m still figuring out this one, but I did use the Track Causality option for my event session (when testing) to confirm that all events are part of the same task (they are). If you look at the expression element in the output, you see that it changes slightly (as does compile_time), and this is surfaced when you look at the details of the warning in SQL Sentry’s Plan Explorer (see second screen shot below). Within the event output, the expression element does tell us what column is involved, which is a start but not nearly enough information, so again we need to go get the plan:

SELECT query_plan FROM sys.dm_exec_query_plan
(0x0600070023747010E09E1C360000000001000000000000000000000000000000000000000000000000000000);

Plan Affecting Convert

Conversion detail from the plan

We again see our friend, the yellow triangle, in the SELECT operator, and within the XML we can find the PlanAffectingConvert attribute. This attribute was added in the SQL Server 2012 showplan schema, so if you’re running an earlier version, you won’t see this in the plan. Resolving this warning may require a bit more work – you need to understand where you’re having a data type mismatch and why, and then either start modifying code or the schema… both can be met with resistance. Jonathan has a post that discusses implicit conversion in more detail, which is a good place to start if you haven't worked with conversion issues previously.

Summary

The Extended Events library of events continues to grow, and one thing to consider when troubleshooting in SQL Server is whether you can get the information you’re seeking in another way. Perhaps because it’s easier (I sure prefer XE to XML!), or because it’s more efficient, or gives you more detail. Whether you are proactively looking for query issues in your environment, or reacting to a problem someone has reported but you’re having trouble finding it, extended events is a viable option to consider, particularly as more new features are added to SQL Server.