I was recently asked if we could tell why a plan was removed from cache. If you read this blog, you know what I’m going to say next. I checked the extended events and there are actually two different events that will tell us information about a plan removed from cache; sp_cache_remove and query_cache_removal_statistics. Let’s talk about how these work.
Removed From Cache
Just so we can see ALL the activity, I’m creating an Extended Events session that captures a little more than just the two events:
CREATE EVENT SESSION PlanCacheRemoval ON SERVER ADD EVENT sqlserver.query_cache_removal_statistics (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.rpc_completed (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.rpc_starting (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.sp_cache_hit (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.sp_cache_insert (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.sp_cache_miss (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.sp_cache_remove (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.sp_statement_completed (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.sp_statement_starting (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.sql_batch_completed (WHERE (sqlserver.database_name = N'AdventureWorks2017')), ADD EVENT sqlserver.sql_batch_starting (WHERE (sqlserver.database_name = N'AdventureWorks2017')) ADD TARGET package0.event_file (SET filename = N'C:\PerfData\PlanCacheRemoval.xel') WITH (TRACK_CAUSALITY = ON);
I’m capturing batch start and complete, rpc start and complete, and finally all the cache statements, hit, miss, insert and remove. The first time I run a procedure, the results could look like this:
Since this is the first time running the procedure, we get a sp_cache_miss event since the query isn’t there. We then see the sql_batch_starting (I’m running the procedure from SSMS). Following is the sp_cache_insert event as the plan gets added to the cache. We then see all the statements run, plus recompiles because I tossed in a temporary table for fun (so you can see what happens).
At the end of this, the plan is in cache. Now, let’s do something to cause the plan to be removed from cache. I’ll modify the procedure. This results in the following events:
You’ll note that the second statement in the sequence is “CREATE OR AL…” in the batch_text. That’s me modifying the procedure. The very next event is sp_cache_remove. It shows the remove_method as “Compplan Remove”. This the plan being removed in an automated way from cache. The next three events are all for query_cache_removal_statistics.
What are they?
These are the statement level statistical information being removed from the DMVs. That’s right, we can observe that information getting removed from the system along with the plan from cache.
Manually Removed From Cache
We can easily see the automated processes removing plans from cache. What happens if we were to use the database scoped configuration to clear out the procedure cache for this database (NOTE: you’ll want to run your procedure at least once so that it’s in there to be removed):
You can again see the “Compplan Remove” method being used. What happens when we nuke the cache using DBCC FREEPROCCACHE:
There are hundreds of query_cache_removal_statistics events and then multiple different “… Flush” events to remove everything.
Conclusion
While I’m not getting into all the details of how objects are removed from cache, you can see that it is possible to get some understanding of how and why objects were moved out of cache using extended events. Combining all the events through causality tracking makes it much easier to see the order in which these events occurred.
If information of this type in a simple blog post is useful, imagine how much more you could get from an in-person event. This is your last possible chance to sign up for my all day seminar in Munich on October 26, 2018. Please click here now to register.
Finally, I am scheduling events for 2019. If you are an event organizer, please get in touch. I’d love to bring this all day seminar to your event.
[…] Grant Fritchey shows us that there is some limited information to tell us why an execution plan was …: […]
Grant Fritchey, good article. Do you know if it is possible read out the stats from dm_exec_query_stats on a extended event just before a statement is flushed from the PlanCache – and then the stats from that DMV are also flushed. Because if sp_cache_remove is after stats is removed from dm_exec_query_stats, then its too late to capture that info.
To my immediate knowledge, I’m going with no. You can’t. However, I’ll get some research done later this week to get a more definite answer.
I have actually dug a little deeper today. And I figured out that the extended event sqlserver.query_cache_removal_statistics read out the statistics into XML. Now I just need to figure out how to add this statistics to the statistics from the DMV’s. The difficult thing here is to match the XEL (XML) output, with the dm_exec_query_stats. Because the plan_handle is not unique, I need the creation_time as well. I will also investigate this a little bit further the next days and get back to you.
Interesting. Have you tried using correlation to connect the events together? That may do the trick. Still haven’t made time to do some testing. Sorry.
No need to be sorry, we are both busy :-). I haven’t either got the time to investigate further. I hope to get there soon. Maybe if you are going to SQL PASS in Seattle in November we could meet and chat. Otherwise I will just keep you posted here 🙂