How can I view the Entity Framework LINQ query plan cache?

Question

I'm having issues with slow LINQ query compilation in EF6. I know EF caches the compiled query plans for LINQ queries, but that there are some gotchas (e. g. Enumerable.Contains prevents caching). I'd like to view the cache for debugging purposes to validate whether or not I'm getting proper caching for my queries. How can I do this?

Note: since this is purely for debugging, I'd be happy with an answer using reflection or other means that wouldn't be used in production.

Answer 1

You can reflect down to the cache using something like this (in EF 6.1.3):

var method = context.Database.GetType().GetMethod("CreateStoreItemCollection", BindingFlags.Instance | BindingFlags.NonPublic);
var storeItemsCollection = method.Invoke(context.Database, null);
var queryCacheManagerField = storeItemsCollection.GetType().GetField("_queryCacheManager", BindingFlags.Instance | BindingFlags.NonPublic);
var queryCacheManager = queryCacheManagerField.GetValue(storeItemsCollection);
var cacheField = queryCacheManager.GetType().GetField("_cacheData", BindingFlags.Instance | BindingFlags.NonPublic);
var cacheData = cacheField.GetValue(queryCacheManager) as ICollection;
foreach (var item in cacheData)
{
    Console.WriteLine(item.ToString());
}

Unfortunately, all the items in the cache are of internal types (in the System.Data.Entity.Core.Common.QueryCache namespace), so getting useful information out of them will require a bunch more reflection and poking around. Luckily, CompiledQueryCacheKey overrides ToString so it gives up a little (cryptic) information about itself. After running a single query (Table.Count()), the code above spits out these two entries:

[System.Data.Entity.Core.Common.QueryCache.ShaperFactoryQueryCacheKey`1[System.Int32], System.Data.Entity.Core.Common.QueryCache.QueryCacheEntry]

[FUNC<Edm.Count(In Transient.collection[Edm.Int32(Nullable=True,DefaultValue=)](Nullable=True,DefaultValue=))>:ARGS(([Project](BV'LQ1'=([Scan](DashboardAutoContext.Organizations:Transient.collection[DashboardAuto.Organization(Nullable=True,DefaultValue=)]))(1:Edm.Int32(Nullable=True,DefaultValue=)))))|||AppendOnly|True, System.Data.Entity.Core.Common.QueryCache.QueryCacheEntry]

Good luck figuring out what that means, or correlating things when you have a bunch of entries.

A different tactic I've had some success with is to create a class with a method I can assign to DbContext.Database.Log during testing. The class starts a timer when it sees an "Opened connection..." message, then stops the timer when it sees an "-- Executing at...". That time roughly corresponds to the time it takes EF to compile your LINQ query down to SQL. If your query is being cached, that time will shrink to almost nothing after the first time the query is executed; if it's not cached, the time will stay consistently high.

(It should go without saying that you'd only want to do this in a testing context.)

Answer 2

You can inject an IDbCommandTreeInterceptor implementation for logging any query tree creation. I used it successfully in a combination with a call stack keyed dictionary for spotting multiple compilations of "bad" queries.