The following simple query ran into timeouts several times during the last days:
SELECT Object1.*,
Object2.Column1,
Object2.Column2 AS Column3
FROM Object2 INNER JOIN Object1 ON Object2.Column2 = Object1.Column3
WHERE Object2.Column4=Variable1 AND
Object2.Column5=Variable2 AND
Object1.Column6=Variable3
I could catch it in SentryOne and saw it getting executed frequently, running into the 60 sec query timeout set by the application and constantly causing 12 Mio reads.
I could not see anything related like blockings or deadlocks causing it to timeout.
I copied the query and ran it in SSMS. It returned within few ms and returned zero rows.
This is the execution plan I got: https://www.brentozar.com/pastetheplan/?id=SJ-LK8jug
Lateron, I did this step again with the same query and same parameter values. Suddenly it ran for around 90 seconds returning zero rows and I got a different plan as follows: https://www.brentozar.com/pastetheplan/?id=HyVu58i_l
As you can see, the number of estimated rows is 1 and the number of actual rows is huge. This made me guess that a lot of changes were made to the table.
So I looked at the [sys].[dm_db_stats_properties] values for the involved tables, especially for OBJECT1 and the used indexes.
[Please note to avoid confusion, the anonymized plans use the same names for different indexes (Object1.Index1)]
At this point I saw the following statistic values…
Object1.Index1 (referencing the 2nd, inefficient exec. plan):
RowsInTable=3826101
RowsSampled=103245
UnfilteredRows=3826101
RowMods=2140
Histogram Steps 200
PercentChanged=0.0
For Object1.Index2 (Clustered Index):
RowsInTable=3826101
RowsSampled=103734
UnfilteredRows=3826101
RowMods=2140
HistoSteps=199
PercentChanged=0.0
Then I realized that I had accidentaly added a line break in the first execution and I think that made me have a different, new execution plan.
I decided to Update all statistics for the OBJECT1 table. After that I ran the initial query again as I catched it from SentryOne without ANY CHANGES, no line breaks…
This time it was quick as expected and the execution plan was identical to the first, efficient plan. This makes me suspect that the statistics were kind of stale.
I queried the statistics meta information again with the following results (referencing the first, efficient plan):
Object1.Index1 (Clustered Index)
RowsinTable=3828157
RowsSampled=104017
UnfilteredRows=3828157
RowModifications=14
HistoSteps=199
PercentCahnge=0.0
For Object1.Index2 (Nonclustered Index)
RowsInTable=3828157
RowsSampled=103275
UnfilteredRows=3828157
RowMods=14
HistogrSteps=127
PercentChanged=0.0
The application afterwards ran es expected, quickly without timeouts. So I guess that STATISTICS UPDATE helped here.
Let me point out additionally that as part of my automated overnight Index and Statistics maintenance all indexes of the table have been succesfully maintained / updated during the last night.
Now my questions:
-
I know that execution plans are problematic if they expect few rows and actually return a lot of rows more than expected. I do not understand how an execution plan can reveal 3,141,000 Rows if it actually returns ZERO rows. How is this possible?
-
The investigation on the table OBJECT 1 and it's statistics did not show any hints for larger changes or added rows. I queried for added or changed rows since last automated index & statistics maintenance and it looks like 2370 rows were changed while ~ 3,800,000 Rows are in the table. This is a slight amount changed as the values of [sys].[dm_db_stats_properties] showed as well. Could statistics really be an issue here? do the figures I quoted above show any good reasons for a statistics update?
UPDATE:
The Values for ParameterCompiledValue and ParameterRuntimeValue are identical in the GOOD PLAN but different in the BAD PLAN.
The Table OBJECT1 has one value in the Column6 that delivers > 3 Mio Rows while all other values deliver a max of around 60k rows.
The BAD Plan used exectly thi >3 Mio Rows value for ParameterRuntimeValue while it was compiled with a value that would deliver just 160 Rows.
So it looks like I need either a plan that addresses both of the scenarios or a more flexible solution that creates a proper plan either way…?
Best Answer
Regarding your first question in general:
I do not understand how an execution plan can reveal 3,141,000 Rows if it actually returns ZERO rows. How is this possible?
The final output rows count isn't known to the optimiser when it generates a plan. So all it can consider are the estimates it can calculate from statistics. (In the case of your "bad" plan, the estimated output rows was actually 4.4 which was based on the first estimate in the plan.)
If those estimates are outdated, or insufficiently accurate (sample vs fullscan of unevenly distributed data for example) then a poor plan can be generated even with a simple query.
In addition, if a plan is reused with different variables, the estimates the plan was generated from may be wildly inaccurate. (And I think that's what sp_BlitzErik is leaning towards as the cause in your particular case.)
UPDATE:
Your latest update shows that the problems you're seeing are caused by classic inappropriate parameter sniffing.
The simplest solution (if you control the code) is to add OPTION (RECOPILE) to the end of the problematic query. This will ensure the statement plan is recreated on every run, and will also allow certain shortcuts to be taken in creating the plan.
The downside is additional CPU and time spent creating the plan on each run, so this solution may not be suitable.
Considering the skew of your data (3 mill for one value vs 160k max for others), and assuming that skew will not change much, branching like this may do the trick:
Note that "3MillValue" in two places would need to be hard-coded with the value that returns that amount, and that OPTIMIZE FOR is the key to this technique.