Sql-server – Missing execution plans for stored procedures

plan-cachesql server

What are the reasons for a plan to be missing from cache for stored procedures?

WITH RECOMPILE
Dynamic SQL
Encrypted code
Significant data changes
Update statistics
What else?

I've worked on 2 servers (SQL Server 2008 R2 and SQL Server 2012) recently that didn't have plans in cache for very resource-intensive stored procedures. Many, maybe all, of the statements inside the stored procedures also didn't have plans in cache. Some of the stored procedures execute pretty frequently like a few times per second.

No memory pressure whatsoever. One of the servers has far more hardware than is needed.

I thought the missing plans were due to temporary table creations in the middle of the stored procedures, but that appears to be old information from SQL Server 2000 or earlier. Starting with SQL Server 2005, the recompiles happen at the statement level for the statements after the DDL. Is that true in all cases or can it still happen on newer versions?

What else could be the culprit for the missing plans? I've skimmed a few articles on this topic, but nothing seems to fit.

Optimize for adhoc workloads is enabled on the server I am looking at this week. One of the stored procedures is only executed once a day. I do have the code for that one. I don't have the code for the one that's executing over 100 times per minute, but I can get it. I won't be able to post the code, but I can describe it in relation to my question.

I don't believe anyone is freeing the procedure cache or dropping clean buffers. This client is using Solarwinds DPA as one of their monitoring tools. DPA did capture one of the execution plans for the statement in the stored proc that gets called once a day. That statement has a massive amount of reads due to non-sargable WHERE clause. If DPA captured the statement, then it's an estimated plan and was in the plan cache at one time. Just isn't there when we are troubleshooting. I'll have them start logging sp_WhoIsActive to a table.

I'm using sp_BlitzCache. (I work for Brent Ozar Unlimited) This will show the plan for the entire stored procedure as well as the plans for the individual statements, if they exist. If they don't exist, it has this for a warning "We couldn't find a plan for this query. Possible reasons for this include dynamic SQL, RECOMPILE hints, and encrypted code." And that warning is on the statements too.

TF 2371 isn't in place. I'm looking at the wait stats. The server is pretty bored. PLE is over 130,000.

I now have the code for 2 more stored procedures. One of them is using dynamic SQL with exec (@sql) so that one we know why there isn't a plan for it. But the other one, and this is the one that's running over 100 times per minute, doesn't have anything out of the ordinary. The only thing that stands out in that one is that the temporary tables are being created in the middle of over 1000 lines of code. It does call a bunch of child stored procedures too.

Regarding Plan Caching in SQL Server 2008, I'm not seeing any literals >= 8k, but one of the stored procedures has a comment about a bulk insert right before it calls another stored procedure. But the bulk insert doesn't appear in the outer stored procedure that I am looking at. The "Recompilation Threshold" section of the article is interesting. What I'm seeing for the temporary tables is tons of INSERTs (that could result in millions of rows), some updates and deletes. So lots of data changes to the temporary tables. Millions.

Best Answer

There are two plan cache DMFs:

sys.dm_exec_query_plan - returns cached plans in XML format, but only up to a certain size (and only as long as they can be formatted as XML in SQL Server, which means up to 128 nested levels.)

sys.dm_exec_text_query_plan - returns cached plans in text format, of any size. But the drawback is that when plans are large, you can't convert them to XML inside SQL Server, and even TRY_CONVERT as XML returns a null.

sp_BlitzCache only hits the former DMV (because it needs to analyze query plans as XML to do all kinds of slicing and dicing.) I made Github issue #838 to improve this so we could at least alert users to go check sys.dm_exec_text_query_plan for their bigger queries. We still won't be able to do XML analysis on it, though.

Related Solutions

Sql-server – Would it be better for query plans to be split by statement for re-usability

If a user executes a statement that is one of the statements in the multi-statement query can it use that relevant part of the query plan already in the cache for the multi-statement query?

No. The basic unit of plan reuse in SQL Server is the batch.

Would it be better to hash each statement in a multi-statement query so they could be used by users running individual statements from the query?

A system tuned for high levels of plan reuse will place common code (at a suitable granularity) in reusable objects (e.g. procedures, functions, triggers) on the SQL Server. It will also explicitly parameterize any application-generated or client-side code. For maximum plan reuse, these generated batches should differ only in parameter values.

I expect there are complications that I'm not taking into account

It sounds like you are asking why SQL Server was designed to cache and reuse at the batch level, rather than at the statement level. I doubt anyone aside from the original designers could answer this question authoritatively. Anyway, it seems to me that a batch is a natural granularity to use because it is relatively self-contained natural unit of work, and represents a reasonable trade-off between implementation complexity and plan reuse probability.

There are a few things that make batches not entirely self-contained (for example local temporary tables created and referenced across stored procedure boundaries). These exceptions reduce orthogonality and have been associated with unexpected 'by design' behaviours and bugs over the years.

Sql-server – Is execution plan cached “better” for stored procedures than for a non-dynamic query

_{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.