Benjamin Nevarez

One interesting problem I am asked to troubleshoot sometimes is when a developer tells me that a stored procedure is timing out or taking too long to execute on a web application but returning immediately when executed directly in Management Studio. Even for the same parameters. Although there could be a few reasons for a problem like this to happen, including blocking, the most frequent one is related to a behavior in which the plan used by the web application was optimized using a combination of parameters which produced a “bad” plan for some other executions of the same stored procedure with different parameters. Although you may be tempted to just run sp_recompile to force a new optimization and allow the application to continue working, this does not really fix the problem and it may eventually come back. You could have also seen some similar scenarios where you have updated statistics, rebuild an index or changed something else to find out that suddenly the problem seems to be fixed. It is not. Those changes probably just forced a new optimization with the “good” parameter you were just testing. Obviously the best thing to do for this kind of problem is capturing the “bad” plan for further analysis in order to provide a permanent solution. In this post I will show you how to do that.

But first, a little bit of background. Remember that in general query optimization is an expensive operation and, in order to avoid this optimization cost, the plan cache will try to keep the generated execution plans in memory so they can be reused. So, if the stored procedure is executed thousands of times, only one optimization is needed. However, if a new connection running the same stored procedure has different SET options it may generate a new plan instead of reusing the one already on the plan cache. This new plan can be reused by later executions of the same stored procedure with the same connection settings. A new plan is needed as these SET options can impact the choice of an execution plan because they affect the results of evaluating constant expressions during the optimization process (a process known as constant folding and explained here). Another connection setting, FORCEPLAN, acts in a similar way to a hint, requesting the Query Optimizer both to preserve the join order as specified on the query syntax and to use nested loop joins only. As indicated in the Microsoft white paper Plan Caching in SQL Server 2008, the following SET options will affect the reuse of execution plans.

ANSI_NULL_DFLT_OFF
ANSI_NULL_DFLT_ON
ANSI_NULLS
ANSI_PADDING
ANSI_WARNINGS
ARITHABORT
CONCAT_NULL_YIELDS_NULL
DATEFIRST
DATEFORMAT
FORCEPLAN
LANGUAGE
NO_BROWSETABLE
NUMERIC_ROUNDABORT
QUOTED_IDENTIFIER

Unfortunately different management or development tools, like Management Studio, ADO.NET, or even sqlcmd, may have different SET options in their default configuration. You will find that mostly the problem is that one of the options, ARITHABORT, is OFF in ADO.NET and ON in Management Studio. So it may be possible that, in our example, Management Studio and the web application are using distinct cached plans and that the web application initially got a good plan for the parameters used during the optimization, but this plan is not good for some other executions of the same stored procedure with different parameters.

But now let us see how to prove that parameter sniffing is in fact the problem for your specific instance of the issue, and how to extract the plans to inspect both the parameters and the SET options used during optimization. Since AdventureWorks does not have the default SET options of a new database, let us create our own and copy some data from AdventureWorks

CREATE DATABASE Test
GO

Create a new table and a stored procedure to test

USE Test
GO
SELECT * INTO dbo.SalesOrderDetail
FROM AdventureWorks.Sales.SalesOrderDetail
GO
CREATE NONCLUSTERED INDEX IX_SalesOrderDetail_ProductID
ON dbo.SalesOrderDetail(ProductID)
GO
CREATE PROCEDURE test (@pid int)
AS
SELECT * FROM dbo.SalesOrderDetail
WHERE ProductID = @pid

Let us test two different applications, executing the stored procedure from a .NET application (C# code included at the end) and from Management Studio. For the purpose of this test we want to assume that a plan with a table scan is a bad plan and a plan using an index seek/RID lookup is the optimal one.

Start with a clean plan cache by running

DBCC FREEPROCCACHE

Run the .NET application from a command prompt window and provide the value 870 as a parameter (note that this application is only running the test stored procedure)

C:\TestApp\test
Enter ProductID: 870

At this moment we can start inspecting the plan cache to see the plans available in memory. Run the following script from the Test database (we will be running this script again later during this exercise)

SELECT plan_handle, usecounts, pvt.set_options
FROM (
    SELECT plan_handle, usecounts, epa.attribute, epa.value
    FROM sys.dm_exec_cached_plans
        OUTER APPLY sys.dm_exec_plan_attributes(plan_handle) AS epa
    WHERE cacheobjtype = 'Compiled Plan') AS ecpa
PIVOT (MAX(ecpa.value) FOR ecpa.attribute IN ("set_options", "objectid")) AS pvt
where pvt.objectid = object_id('dbo.test')

You should get an output similar to this

plan_handle                                           usecounts    set_options
0x05000700210F0207B8C09007000000000000000000000000    1            251

The output shows that we have one execution plan in the plan cache, it has been used once (as indicated by the usecounts value), and the set_options value, taken from the sys.dm_exec_plan_attributes DMF, is 251. Since this was the first execution of the stored procedure, it was optimized using the parameter 870 which in this case created a plan using a table scan (consider here a “bad” plan). Now run the application again using a parameter that returns only a few records and will benefit from an index seek/RID lookup plan:

C:\TestApp\test
Enter ProductID: 898

If you inspect the plan cache again you will notice that the plan has been used twice and unfortunately this time it was not good for the second parameter used

plan_handle                                           usecounts    set_options
0x05000700210F0207B8C09007000000000000000000000000    2            251

At this moment the developer may try to troubleshoot this problem by running the stored procedure in Management Studio using something like this

EXEC test @pid = 898

Now the developer is surprised to find that SQL Server is returning a good execution plan and the query is returning immediately. Inspecting the plan cache again will show something similar to this

plan_handle                                           usecounts    set_options
0x05000700210F0207B8C09007000000000000000000000000    2            251
0x05000700210F0207B860650B000000000000000000000000    1            4347

You can see that a new plan was added for the Management Studio execution, with a different value for set_options.

What to do next? It is time to inspect the plans and look at the SET options and parameters used during the optimization. Select the plan_handle of the first plan created (the one with set_options 251 in your own example) and use it to run the following query

select * from sys.dm_exec_query_plan
(0x05000700210F0207B8C09007000000000000000000000000)

You can find the SET options at the beginning of the plan

<StatementSetOptions QUOTED_IDENTIFIER="true" ARITHABORT="false"
CONCAT_NULL_YIELDS_NULL="true" ANSI_NULLS="true"
ANSI_PADDING="true" ANSI_WARNINGS="true" NUMERIC_ROUNDABORT="false" />

And the used parameters at the end

<ParameterList>
    <ColumnReference Column="@pid" ParameterCompiledValue="(870)" />
</ParameterList>

Do the same for the second plan and you will get the following information for the SET options

<StatementSetOptions QUOTED_IDENTIFIER="true" ARITHABORT="true"
CONCAT_NULL_YIELDS_NULL="true" ANSI_NULLS="true"
ANSI_PADDING="true" ANSI_WARNINGS="true" NUMERIC_ROUNDABORT="false" />

and the following parameter information

<ParameterList>
    <ColumnReference Column="@pid" ParameterCompiledValue="(898)" />
</ParameterList>

This information shows that the ARITHABORT SET option has different value on these plans and that the parameter used to optimize the query on the web application was 870. (The same information is available from the Properties window of a graphical plan). You can also verify the operators used in the plan, the first one using a table scan and the second one an index seek/RID lookup combination.

Now that you have captured the plans you can force a new optimization so the application can use a better plan immediately (keeping in mind that this is not a permanent solution). Try this

sp_recompile test

So now you know that you have a problem related to parameter sniffing. What to do next? I have a few recommendations on previous posts here and here. I have another one here but usually you should not be doing this.

Finally, you can use the following script to display SET options for a specific set_options value

declare @set_options int = 251
if ((1 & @set_options) = 1) print 'ANSI_PADDING'
if ((4 & @set_options) = 4) print 'FORCEPLAN'
if ((8 & @set_options) = 8) print 'CONCAT_NULL_YIELDS_NULL'
if ((16 & @set_options) = 16) print 'ANSI_WARNINGS'
if ((32 & @set_options) = 32) print 'ANSI_NULLS'
if ((64 & @set_options) = 64) print 'QUOTED_IDENTIFIER'
if ((128 & @set_options) = 128) print 'ANSI_NULL_DFLT_ON'
if ((256 & @set_options) = 256) print 'ANSI_NULL_DFLT_OFF'
if ((512 & @set_options) = 512) print 'NoBrowseTable'
if ((4096 & @set_options) = 4096) print 'ARITH_ABORT'
if ((8192 & @set_options) = 8192) print 'NUMERIC_ROUNDABORT'
if ((16384 & @set_options) = 16384) print 'DATEFIRST'
if ((32768 & @set_options) = 32768) print 'DATEFORMAT'
if ((65536 & @set_options) = 65536) print 'LanguageID'

C# Code

using System;
using System.Data;
using System.Data.SqlClient;

class Test
{
    static void Main()
    {
        SqlConnection cnn = null;
        SqlDataReader reader = null;

        try
        {
            Console.Write("Enter ProductID: ");
            string pid = Console.ReadLine();

            cnn = new SqlConnection("Data Source=(local);Initial Catalog=Test;
                Integrated Security=SSPI");
            SqlCommand cmd = new SqlCommand();
            cmd.Connection = cnn;
            cmd.CommandText = "dbo.test";
            cmd.CommandType = CommandType.StoredProcedure;
            cmd.Parameters.Add("@pid", SqlDbType.Int).Value = pid;
            cnn.Open();
            reader = cmd.ExecuteReader();
            while (reader.Read())
            {
                Console.WriteLine(reader[0]);
            }
            return;
        }
        catch (Exception e)
        {
            throw e;
        }
        finally
        {
            if (cnn != null)
            {
                if (cnn.State != ConnectionState.Closed)
                    cnn.Close();
            }
        }
    }
}