Critical Query Plans Removed from sys.dm_exec_query_stats in SQL Server

plan-cachesql serversql-server-2019

Running SQL Server Express 2019.

Have a complicated stored procedure containing 11 sql statements (when selected from sys.dm_exec_query_stats by plan_handle).

9 of those statements are simple variable setting based on passed-in parameters, the last 2 statements (IF/ELSE) do all the work and return data (e.g. query_hash 0x111… and 0x222…).

There's quite a variability in data volume based on input parameters, so I "prime" the stored procedure with optimal values to ensure quick execution.

I've noticed that every few days (sometimes more often), my last 2 statements (query_hash 0x111… and 0x222…) get dumped from sys.dm_exec_query_stats and then re-generated based on whatever parameters come from the users on the next stored procedure call.

I know this by looking at creation_time column, and it's reflecting the time of "priming" for first 9 queries, and a later time for query_hash 0x111… and 0x222… .

From what I understand, cached plans get cleared under memory pressure, and less used plans get cleared first. My queries are being used a lot, and I have a lot of other cached plans with 1 execution that stick around for a while.

Question: why are my most used queries get dumped form cache and how do I stop it from happening?

Best Answer

There are a bunch of different reasons why a statement might be recompiled, including both performance and correctness-related reasons.

For instance, an index used by the query may have been dropped, in which case the plan must be recompiled because it genuinely can't be run in that state.

Or statistics may have been updated enough that an automatic recompilation occurs.

Depending on the load on your server, and how frequently this statement really gets recompiled, you might be able to capture the actual reason using this extended events session:

CREATE EVENT SESSION [recompiles] ON SERVER 
ADD EVENT sqlserver.sql_statement_recompile
(
    WHERE ([sqlserver].[query_hash]=(111))
)
ADD TARGET package0.event_file (SET filename=N'recompiles')
WITH (STARTUP_STATE=OFF)

This will fire for every recompile on the system, but will only store the ones with a query hash that matches what you put in the filter.

To be clear: don't start this thing up and then leave for the weekend. Try it on a test system, try it briefly on production and make sure it's not too disruptive, etc. Don't take down your server just to track this down ?

In case it's helpful, the XE defines all of these statement recompile reasons on SQL Server 2019:

SELECT map_value
FROM sys.dm_xe_map_values
WHERE [name] = N'statement_recompile_cause';

map_value
Schema changed
Statistics changed
Deferred compile
Set option change
Temp table changed
Remote rowset changed
For browse permissions changed
Query notification environment changed
PartitionView changed
Cursor options changed
Option (recompile) requested
Parameterized plan flushed
Test plan linearization
Plan affecting database version changed
Query Store plan forcing policy changed
Query Store plan forcing failed
Query Store missing the plan
Interleaved execution required recompilation
Not a recompile
Multi-plan statement required compilation of alternative query plan

Related Solutions

SQL Server – Resolving sys.dm_exec_procedure_stats DMV and BOL Contradictions

Just working from Paul's comment. The key difference between the statement in Books Online and your interpretation:

It says: ... one row per cached stored procedure plan.

You read: ... one row per cached stored procedure.

You can check which plan attributes are different and thus leading to different copies of the plan by looking at the contents of the attributes DMV, ordering by attribute name. You should see at least one attribute where two rows for the same text have different values in the value column.

SELECT t.[text], pa.attribute, pa.value
FROM sys.dm_exec_cached_plans AS p
CROSS APPLY sys.dm_exec_sql_text(p.plan_handle) AS t
CROSS APPLY sys.dm_exec_plan_attributes(p.plan_handle) AS pa
WHERE LOWER(t.[text]) LIKE N'%create%procedure%procedure_name%'
  AND LOWER(t.[text]) NOT LIKE N'%sys.dm%'
  AND pa.is_cache_key = 1
ORDER BY t.[text], pa.attribute;

Typically, you will see differences in one of these two attributes:

set_options

This is due to runtime differences in settings like ARITHABORT, QUOTED_IDENTIFIER, ANSI_NULLS, etc. I talk about this in the following post:

Multiple Plans for an "Identical" Query

user_id

This isn't really the user running the query, but rather it is due to two different users having different default schemas (the value is actually schema_id), and at least one of them is calling the stored procedure without the schema prefix (SQL Server caches a different plan because the search path is different - it must check the default schema first). I talk about this in the above post as well as the following:

Bad habits to kick : avoiding the schema prefix

(Also, be sure you are looking at the overarching plan for the procedure, not two plans for two completely different statements within the stored procedure, e.g. WHERE p.objtype = N'Proc'.)

Execution Plan Caching for Stored Procedures vs Non-Dynamic Queries

_{The answer is also available as a standalone blog article.}

In order to find it out, I did some tests. The goal is to have the same parametrized query executed either directly from C# or by calling a stored procedure and to compare the runtime performance.

I started to create a stored procedure which does a sample query using Adventure Works database:

create procedure Demo
    @minPrice int 
as
begin
    set nocount on;

    select top 1 [p].[Name], [p].[ProductNumber], [ph].[ListPrice]
    from [Production].[Product] p
    inner join [Production].[ProductListPriceHistory] ph
    on [p].[ProductID] = ph.[ProductID]
    and ph.[StartDate] =
    (
        select top 1 [ph2].[StartDate]
        from [Production].[ProductListPriceHistory] ph2
        where [ph2].[ProductID] = [p].[ProductID]
        order by [ph2].[StartDate] desc
    )
    where [p].[ListPrice] > @minPrice
end

Then, I use the following piece of code to compare the performances:

long RunQuery(SqlConnection connection, int minPrice)
{
    const string Query = @"
    select top 1 [p].[Name], [p].[ProductNumber], [ph].[ListPrice]
    from [Production].[Product] p
    inner join [Production].[ProductListPriceHistory] ph
    on [p].[ProductID] = ph.[ProductID]
    and ph.[StartDate] =
    (
        select top 1 [ph2].[StartDate]
        from [Production].[ProductListPriceHistory] ph2
        where [ph2].[ProductID] = [p].[ProductID]
        order by [ph2].[StartDate] desc
    )
    where [p].[ListPrice] > @minPrice
    option (recompile)";

    using (var command = new SqlCommand(Query, connection))
    {
        command.Parameters.AddWithValue("@minPrice", minPrice);
        var stopwatch = Stopwatch.StartNew();
        command.ExecuteNonQuery();
        stopwatch.Stop();
        return stopwatch.ElapsedMilliseconds;
    }
}

long RunStoredProcedure(SqlConnection connection, int minPrice)
{
    using (var command = new SqlCommand("exec Demo @minPrice with recompile", connection))
    {
        command.Parameters.AddWithValue("@minPrice", minPrice);
        var stopwatch = Stopwatch.StartNew();
        command.ExecuteNonQuery();
        stopwatch.Stop();
        return stopwatch.ElapsedMilliseconds;
    }
}

ICollection<long> Execute(Func<SqlConnection, int, long> action)
{
    using (var connection = new SqlConnection("Server=.;Database=AdventureWorks2014;Trusted_Connection=True;"))
    {
        connection.Open();
        using (var command = new SqlCommand("DBCC FreeProcCache; DBCC DropCleanbuffers;", connection))
        {
            command.ExecuteNonQuery();
        }

        return Enumerable.Range(0, 100).Select(i => action(connection, i)).ToList();
    }
}

void Main()
{
    var queries = Execute(RunQuery);
    var storedProcedures = Execute(RunStoredProcedure);

    Console.WriteLine("Stored procedures: {0} ms. Details: {1}.", storedProcedures.Sum(), string.Join(", ", storedProcedures));
    Console.WriteLine("Queries: {0} ms. Details: {1}.", queries.Sum(), string.Join(", ", queries));
}

Notice option (recompile) and with recompile. This will force SQL Server to discard previously cached execution plans.

Each query is run une hundred times with a different parameter every time. The time spent by the server is measured at client side.

By running DBCC FreeProcCache; DBCC DropCleanbuffers; before gathering metrics, I make sure that all previously cached execution plans are removed.

Running this code gives the following output:

Stored procedures: 786 ms. Details: 12, 7, 7, 9, 7, 7, 9, 8, 8, 6, 8, 9, 8, 8, 14, 8, 7, 8, 7, 10, 10, 7, 9, 6, 9, 8, 8, 7, 7, 10, 8, 7, 7, 6, 7, 8, 8, 7, 7, 7, 14, 8, 8, 8, 7, 9, 8, 8, 7, 6, 6, 12, 7, 7, 8, 7, 8, 7, 8, 6, 7, 7, 7, 12, 8, 6, 6, 7, 8, 7, 8, 8, 7, 11, 8, 7, 8, 8, 7, 9, 8, 9, 10, 8, 7, 7, 8, 8, 7, 9, 7, 6, 9, 7, 6, 9, 8, 6, 6, 6.
Queries: 799 ms. Details: 21, 8, 8, 7, 6, 6, 11, 7, 6, 6, 9, 8, 8, 7, 9, 8, 7, 7, 7, 7, 7, 7, 10, 8, 8, 7, 8, 7, 6, 11, 19, 10, 8, 7, 8, 7, 7, 7, 6, 9, 7, 9, 7, 7, 8, 7, 12, 9, 7, 7, 7, 8, 7, 7, 8, 7, 7, 7, 9, 8, 7, 7, 7, 6, 7, 7, 16, 7, 7, 7, 8, 8, 9, 8, 7, 9, 8, 7, 8, 7, 7, 6, 7, 7, 7, 7, 12, 7, 9, 9, 7, 7, 7, 7, 9, 8, 7, 8, 11, 8.

Let's run it again:

Stored procedures: 763 ms. Details: 11, 8, 10, 8, 8, 14, 10, 6, 7, 7, 6, 7, 7, 9, 6, 6, 6, 8, 6, 6, 7, 6, 8, 7, 16, 8, 7, 8, 9, 7, 7, 8, 7, 7, 11, 10, 7, 6, 7, 8, 7, 7, 7, 7, 7, 7, 10, 9, 9, 7, 6, 7, 6, 7, 7, 6, 6, 6, 6, 6, 10, 9, 10, 7, 6, 6, 6, 6, 6, 8, 7, 6, 6, 7, 8, 9, 7, 8, 7, 10, 7, 7, 7, 6, 7, 6, 7, 11, 13, 8, 7, 10, 9, 8, 8, 7, 8, 7, 7, 7.
Queries: 752 ms. Details: 25, 10, 8, 8, 12, 8, 7, 9, 9, 8, 6, 7, 7, 6, 8, 6, 7, 7, 8, 9, 7, 7, 7, 7, 6, 10, 8, 7, 7, 7, 7, 7, 7, 7, 8, 9, 7, 6, 6, 6, 7, 13, 7, 7, 7, 7, 7, 7, 7, 7, 7, 7, 6, 10, 7, 7, 8, 9, 8, 7, 6, 6, 7, 7, 9, 7, 8, 6, 9, 7, 7, 8, 7, 6, 6, 7, 7, 7, 7, 6, 7, 7, 8, 7, 7, 6, 7, 9, 8, 7, 7, 7, 7, 6, 7, 6, 6, 9, 7, 7.

It seems that the performance is very close between stored procedures and direct queries. Running the code a dozen times, I notice that stored procedures seem to be slightly fast, but the gap is very narrow. Possibly passing around the whole query creates this additional cost, which may increase if SQL Server is hosted on a dedicated machine with a slow LAN between it and the application server.

Let's now turn execution plan caching on and see what happens. To do this, I remove option (recompile) and with recompile from the code. Here's the new output:

Stored procedures: 26 ms. Details: 23, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0.
Queries: 15 ms. Details: 14, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0.

It becomes clear that caching has exactly the same effect for both direct queries and stored procedures. In both cases, it reduces the time to nearly zero milliseconds, and the most expensive query is the first one—the one which runs after the removal of cached execution plans.

Running the same code again shows a similar pattern. Sometimes, queries are faster, and sometimes stored procedures are. But every time, the first query is the most expensive one, and all others are close to zero milliseconds.

Reopening SQL connection

If the SQL connection is opened for every query, such as in this slightly modified code:

long RunQuery(string connectionString, int minPrice)
{
    const string Query = @"
    select top 1 [p].[Name], [p].[ProductNumber], [ph].[ListPrice]
    from [Production].[Product] p
    inner join [Production].[ProductListPriceHistory] ph
    on [p].[ProductID] = ph.[ProductID]
    and ph.[StartDate] =
    (
        select top 1 [ph2].[StartDate]
        from [Production].[ProductListPriceHistory] ph2
        where [ph2].[ProductID] = [p].[ProductID]
        order by [ph2].[StartDate] desc
    )
    where [p].[ListPrice] > @minPrice
    option (recompile)";

    using (var connection = new SqlConnection(connectionString))
    {
        connection.Open();
        using (var command = new SqlCommand(Query, connection))
        {
            command.Parameters.AddWithValue("@minPrice", minPrice);
            var stopwatch = Stopwatch.StartNew();
            command.ExecuteNonQuery();
            stopwatch.Stop();
            return stopwatch.ElapsedMilliseconds;
        }
    }
}

long RunStoredProcedure(string connectionString, int minPrice)
{
    using (var connection = new SqlConnection(connectionString))
    {
        connection.Open();
        using (var command = new SqlCommand("exec Demo @minPrice with recompile", connection))
        {
            command.Parameters.AddWithValue("@minPrice", minPrice);
            var stopwatch = Stopwatch.StartNew();
            command.ExecuteNonQuery();
            stopwatch.Stop();
            return stopwatch.ElapsedMilliseconds;
        }
    }
}

ICollection<long> Execute(Func<string, int, long> action)
{
    var connectionString = "Server=.;Database=AdventureWorks2014;Trusted_Connection=True;";
    using (var connection = new SqlConnection(connectionString))
    {
        connection.Open();
        using (var command = new SqlCommand("DBCC FreeProcCache; DBCC DropCleanbuffers;", connection))
        {
            command.ExecuteNonQuery();
        }
    }

    return Enumerable.Range(0, 100).Select(i => action(connectionString, i)).ToList();
}

void Main()
{
    var queries = Execute(RunQuery);
    var storedProcedures = Execute(RunStoredProcedure);

    Console.WriteLine("Stored procedures: {0} ms. Details: {1}.", storedProcedures.Sum(), string.Join(", ", storedProcedures));
    Console.WriteLine("Queries: {0} ms. Details: {1}.", queries.Sum(), string.Join(", ", queries));
}

the observed metrics are very similar:

Stored procedures: 748 ms. Details: 11, 8, 6, 6, 8, 9, 9, 8, 8, 7, 6, 8, 7, 9, 6, 6, 6, 6, 6, 6, 7, 7, 6, 9, 6, 6, 7, 6, 6, 7, 8, 6, 7, 7, 7, 13, 7, 7, 8, 7, 8, 8, 7, 7, 7, 7, 6, 7, 8, 8, 8, 9, 7, 6, 8, 7, 6, 7, 6, 6, 6, 6, 8, 12, 7, 9, 9, 6, 7, 7, 7, 8, 10, 12, 8, 7, 6, 9, 8, 7, 6, 6, 7, 8, 6, 6, 12, 7, 8, 10, 10, 7, 8, 7, 8, 10, 8, 7, 8, 7.
Queries: 761 ms. Details: 31, 9, 7, 6, 6, 8, 7, 7, 7, 7, 7, 6, 8, 7, 6, 6, 7, 10, 8, 10, 9, 7, 7, 7, 7, 10, 13, 7, 10, 7, 6, 6, 6, 8, 7, 7, 7, 7, 7, 7, 7, 9, 7, 7, 7, 6, 6, 6, 9, 7, 7, 7, 7, 7, 6, 8, 10, 7, 7, 7, 7, 7, 7, 7, 8, 6, 10, 10, 7, 8, 8, 7, 7, 7, 7, 7, 6, 6, 7, 6, 8, 7, 7, 7, 7, 7, 7, 7, 8, 7, 8, 7, 9, 7, 6, 6, 12, 10, 7, 6.

with option (recompile) and with recompile and:

Stored procedures: 15 ms. Details: 14, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0.
Queries: 32 ms. Details: 26, 1, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1, 0, 0, 0, 0, 0, 0, 1, 0, 1, 0, 0, 0, 0, 0, 0, 0, 0, 0.

without.

Under the hood

Let's see what happens under the hood. The following query shows cached execution plans:

select usecounts, size_in_bytes, cacheobjtype, objtype, text 
from sys.dm_exec_cached_plans 
cross apply sys.dm_exec_sql_text(plan_handle)
where cacheobjtype = 'Compiled Plan'
order by usecounts desc

When running this query after executing the stored procedures one hundred times, the result of the query looks like this:

usecounts   size_in_bytes cacheobjtype                                       objtype              text
----------- ------------- -------------------------------------------------- -------------------- ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
100         90112         Compiled Plan                                      Proc                 create procedure Demo
    @minPrice int 
as
begin
    set nocount on;

    select top 1 [p].[Name], [p].[ProductNumber], [ph].[ListPrice]
    from [Production].[Product] p
    inner join [Production].[ProductListPriceHistory] ph
    on [p].[ProductID] = ph.[Product
100         16384         Compiled Plan                                      Prepared             (@minPrice int)exec Demo @minPrice --with recompile
1           49152         Compiled Plan                                      Adhoc                --DBCC FreeProcCache
--DBCC DropCleanbuffers

select usecounts, size_in_bytes, cacheobjtype, objtype, text 
from sys.dm_exec_cached_plans 
cross apply sys.dm_exec_sql_text(plan_handle)
where cacheobjtype = 'Compiled Plan'
order by usecounts desc

(3 row(s) affected)

When running the query directly one hundred times, the result is:

usecounts   size_in_bytes cacheobjtype                                       objtype              text
----------- ------------- -------------------------------------------------- -------------------- ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
100         73728         Compiled Plan                                      Prepared             (@minPrice int)
    select top 1 [p].[Name], [p].[ProductNumber], [ph].[ListPrice]
    from [Production].[Product] p
    inner join [Production].[ProductListPriceHistory] ph
    on [p].[ProductID] = ph.[ProductID]
    and ph.[StartDate] =
    (
        select top 1 [ph2].[
1           49152         Compiled Plan                                      Adhoc                --DBCC FreeProcCache
--DBCC DropCleanbuffers

select usecounts, size_in_bytes, cacheobjtype, objtype, text 
from sys.dm_exec_cached_plans 
cross apply sys.dm_exec_sql_text(plan_handle)
where cacheobjtype = 'Compiled Plan'
order by usecounts desc

(2 row(s) affected)

Conclusion

The execution plan is cached for stored procedures and direct queries.
The performance between stored procedures and direct queries is very similar when the SQL Server and the application are hosted on the same machine. When SQL Server is hosted on a dedicated server accessed through LAN, using stored procedures may result in better performance.