Parameter sniffing is something we should all be aware of, especially because of the fact that it could pop up…uhm…unexpectedly.
Before I get into the details, I want to point out that the goal of this post is not to explain in detail what parameter sniffing is, but rather to tell of my own unique experience (and possibly help somebody else identify it easier in future).
If you want more information on what parameter sniffing is all about, you can look at two excellent posts by respected professionals, here and here.
The scenario is the following…
I am busy with a price modelling tool for a well-known retailer. This custom tool is built on Microsoft technologies (SQL Server 2008 back-end and ASP.NET front-end).
A key part of the tool is a stored procedure that processes each model, based on a collection of rules and parameters created by the end-user. As you can imagine, the work performed by this 5k-line proc (yes, 5 thousand!!!) is vitally important and it needs to perform optimally all the time.
A user complained that the process seemed to take a lot longer than before. Checking the metadata confirmed that the execution time of the proc had jumped from about 10mins to 5hrs!!!
The initial investigation revealed the following:
- Not every execution of the proc performed badly.
- Index fragmentation was not an issue.
- There were no blocking processes, or contention for resources.
- Hardware counters (memory usage, disk counters, etc.) seemed acceptable.
- Executing the proc manually (one query at a time) peformed well.
- Using Adam Machanic’s “Who Is Active” proc (you have to get it!!!), I managed to pin-point the last merge statement in the process as the culprit.
After checking my indexes again, sitting back in my chair for a second and wiping the puzzled look from my face…the small voice of reason (paraphrase good fortune/luck/experience) came to me. Maybe it had something to do with parameter sniffing, or some hybrid form of it at least. I knew that the proc used the “with recompile” option, so it was definitely possible that different plans were generated at certain times.
Without doing much further investigation, I decided to forsake the proper scientific methods for a classic “divide-and-conquer” approach (it was a time-sensitive matter of course)…creating a local variable for each input parameter and assigning the values of the input parameters to those local variables. Sometimes you just have to act on a hunch, and look at the details at a later stage.
The results were exactly what I had hoped for, and the IO Stats and Execution Plans of the two procedures seem to confirm my suspicion. Note the difference in logical reads (IO Stats), as well as the difference in the actual number of rows and Hash Match vs. Nested Loops (Execution Plans).
Bad Plan - IO Stats
Good Plan - IO Stats
Bad Execution Plan
Good Execution Plan
Keep parameter sniffing in the back of your mind when troubleshooting poor performance, especially when everything else seems to be in order…