Category: It’s always parameter sniffing

Combining a few themes of recent posts today. I’ll mix in some sp_executesql, it’s always parameter sniffing, and the plan cache.

Consider this situation

We converted an ad-hoc query into a prepared query using sp_executesql. Then, a user called in reporting slowness. When we run the query in Management Studio, the query runs quickly. We checked our SET options with the application and they’re matching.

What could be causing the difference?

Well, it could be the line endings in our version of the query. If the query we’re running in Management Studio has different text or line endings, we might not be retrieving the right query from cache to correctly reproduce the parameter sniffing issues.

First, the query in cache

Let’s take a look at the query that’s causing issues in the plan cache.

USE StackOverflow2010
GO

EXEC sp_executesql N'
SELECT p.Body,p.Tags
FROM Posts as p
WHERE p.PostTypeId = @PostType',
N'@PostType INT', '1'

Here’s the execution plan for that query:

And the compiled parameters:

Second, the query we’re running locally

When we run our query locally, we get a different plan. We are using a different parameter, but that’s not the critical difference. The difference in this query is the spacing.

USE StackOverflow2010
GO

EXEC sp_executesql N'
SELECT p.Body,p.Tags
FROM Posts as p WHERE p.PostTypeId = @PostType',
N'@PostType INT', '3'

I specifically changed the spacing on line 6-7 to show that now I’m getting a different plan. Here’s the new plan I get:

And the new compiled parameters:

So how do we find the correct formatting, so we can retrieve the compiled plan from the first query?

Well, our first step is to go check the plan cache to see if we have the right query hash, and sql handle. Use the second execution plan’s properties to find those values.

They’re right below the parameter list:

Now, we query the plan cache for that query hash and use the DMV, sys.dm_exec_sql_text.

SELECT execution_count,max_worker_time,sText.text
FROM sys.dm_exec_query_stats as s
CROSS APPLY sys.dm_exec_sql_text(s.sql_handle) as sText
WHERE s.query_hash = 0xF21CD06978A7FB4C

One of these is the problematic query, that’s for sure!

Side note: Turning on CR/LF

Now, for this next step, you’ll need to setup your Management Studio to retain CR/LF (Carriage Return and Line Feed). Find that option under Tools->Options

Then under Results to Grid, check this box for Retain CR/LF. Once you do this, you’ll need to open a new tab or restart your Management Studio for it to take effect.

Back to the plan cache

Let’s copy the text out from this query result. I copied both results into new windows, here’s a side-by-side.

Now, I mentioned earlier changing this specifically. But if I saw this while troubleshooting parameter sniffing, this would be a big sign that the two queries had different formatting.

If we have access to the application codebase, we can ask for the full query with formatting included. Otherwise, this crude but effective comparison showed us that we need to change formatting.

Applying the change and demonstrating the query slow in Management Studio

Here’s our PostType 3 query with the correct formatting.

USE StackOverflow2010
GO

EXEC sp_executesql N'
SELECT p.Body,p.Tags
FROM Posts as p
WHERE p.PostTypeId = @PostType',
N'@PostType INT', '3'

And this time, the compiled value is 1 but the actual runtime parameter is 3. We retrieved the bad plan from cache!

After thoughts

This example is extremely straightforward. I didn’t add any special formatting or white space beyond an extra line. Issues like this can get much more complicated, quickly.

When troubleshooting parameter sniffing issues, having the query version from the application is going to be better than trying to reverse engineer it from the plan cache like this example.

However, the plan cache can be used to determine if there’s a difference, when combined with comparison tools like Notepad++‘s Compare functionality. There’s definitely room for another blog post on that.

I wanted to write this post to show that small differences in text can make the difference when it comes to reproducing a parameter sniffing issue.

Stay tuned!

This is the sequel to “It’s always parameter sniffing (part 1).” In that post, we identified the stored procedure, and found a plan in cache that had some weird execution times.

This time, we’ll try to reproduce the issue in SQL Server Management Studio, and I’ll show why you need the SET options from the plan cache.

The setup

We’re using the stored procedure, QueryPostType, which takes a parameter of PostTypeId. In StackOverflow2010, the Post Type 1 has 1.1 million rows in the Posts table, and Post Type 3 has 28 rows.

The user calls in and tells us that they’re trying to find all the Post Types of 3, so it should be easy to reproduce, right? I’ll return statistics time to show you how long it took to execute on my machine.

set statistics time on;
exec QueryPostType @PostType = 3;

-- SQL Server Execution Times:
-- CPU time = 0 ms,  elapsed time = 88 ms.

Based on those results, the query runs fast in SSMS. If you’ve been doing performance tuning for a while, you’re ready for this next statement.

The query runs fast in SSMS but slow in the app!

To me, that means that we didn’t get the right plan from cache. For some reason, our query didn’t retrieve a cached plan. It would be really nice if we could use the “RetrievedFromCache” value inside execution plans…but it’s just not reliable.

So what do we do now? In my opinion, our next step is to check the “SET” options. These are settings that users can change on their applications/connections, and they will give a separate execution plan when used.

Checking settings on the cached plan

Let’s check on our query’s settings in the execution plan, and then we can check on the plan in cache.

These are the settings and actual execution plan from the query above.

Now let’s query the plan cache and check out the plan in there. I’m returning the execution count too, see why in a second.

SELECT dm_plan.query_plan, 
       stat.execution_count
FROM sys.dm_exec_procedure_stats as stat
CROSS APPLY sys.dm_exec_query_plan(stat.plan_handle) as dm_plan
WHERE object_name(stat.object_id) = 'QueryPostType'

In this example, the plan with 126 executions is from the application. In the real world, that number could be much, much higher. Let’s open that plan and see what settings were used there.

Here’s the plan it created, just in case you’re curious about the shape of the plan in cache.

Arithabort was off in the application

This post isn’t about the “right” settings, it’s about retrieving the right plan from cache! Let’s go back to our previous example and turn it off, then hopefully we’ll retrieve the plan from cache.

SET STATISTICS TIME ON;
SET ARITHABORT OFF;
EXEC QueryPostType @PostType = 3;
-- SQL Server Execution Times:
-- CPU time = 1468 ms,  elapsed time = 1493 ms.

I’ve never been so happy to see parameter sniffing. And we even got the index scan plan.

I hope this was useful! This happened to me today and I had to find the SET options from the plan cache. Stay tuned.

This is a blog post about a perennial issue. Have you ever had a call in the middle of the night about a slow webpage and you know nothing in the webpage changed?

Yeah, it’s probably parameter sniffing.

First, some clarification

All parameter sniffing is not bad. It’s usually a good thing, keeping our server’s CPU cores from wasting cycles on creating a new execution plan for each query. When SQL Server sees a query, it has to create a plan for the query it was given. It’s not the fault of your database that the old execution plan went away.

Is Parameter Sniffing causing my poor performance right now?

Oof, this is a tough question. Let’s talk about determining if parameter sniffing is occurring.

User A sends us the webpage that’s running slow and they send us the exact form that’s running slowly. We know from experience in our system that it’s the stored procedure, QueryPostType. Here’s the definition.

CREATE PROCEDURE [dbo].[QueryPostType] (@PostType INT) as
BEGIN

SELECT PostTypeId, Tags, Body 
FROM Posts 
WHERE PostTypeId = @PostType

END
GO

For the sake of setting expectations, we’re in the StackOverflow2010 database, and the Posts table is very skewed by PostTypeId.

Back to the example: The user has only given us the name of the procedure, and we’re playing detective. Let’s start by looking at the plan cache information on the procedure.

SELECT
    min_worker_time,
    max_worker_time,
    total_worker_time
FROM sys.dm_exec_procedure_stats
WHERE object_name(object_id) = 'QueryPostType'

This is the first warning sign

So the procedure stats for this query have incredibly different worker time values. That’s a good sign that something is wrong. The next step is to determine what parameters created this cached plan, then we’ll see if the other warning signs line up.

Parameter sniffing is complex enough that it might take a few more posts. Stay tuned!