Take the 2-minute tour ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.

Thank you in advance for reading it. This question is kind of long and need a little patience to read. I will provide as much details as I can to void interference factors to solve this problem. However, it could also be interesting as it digs into the SQL Server back-end.

The problem we have is that SQL Server keeps picking different execution plans for two very similar queries, and the plans results in very different performance.

Before I ran the queries, the indexes on tables were rebuilt, the plan cache was cleaned, and no other thing was running on the db instance.

The first query I ran is like below:

DBCC DROPCLEANBUFFERS
go
checkpoint
go
USE [dbname]
GO
set statistics io on
DECLARE       @return_value int
--BAD SQL PLAN
EXEC   @return_value = [dbo].[AnStoredProcedure]
              @StartRequestIdTransform = 45796687,
              @EndRequestIdTransform = 45896687

It took 90 seconds to run and returned 462729 rows. Full statistics are as below:

DBCC execution completed. If DBCC printed error messages, contact your system administrator.
Table 'DWH_PractitionerDedupeMapping'. Scan count 0, logical reads 925458, physical reads 47, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'RequestParametersLog_Audit'. Scan count 925458, logical reads 3705389, physical reads 77, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'AccessHistoryLog_Audit'. Scan count 462726, logical reads 1390666, physical reads 78, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'StateZipcodeMapping'. Scan count 0, logical reads 925452, physical reads 16, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'CustomerLookup'. Scan count 0, logical reads 925452, physical reads 3, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ServiceList'. Scan count 1, logical reads 925453, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ManufacturerServices'. Scan count 2, logical reads 925454, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ContractServiceMapping'. Scan count 2, logical reads 925454, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DrugLabel_Lookup'. Scan count 0, logical reads 925452, physical reads 8, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'InstitutionLookup'. Scan count 2, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'InstitutionMappings'. Scan count 2, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'PM_Lookup'. Scan count 0, logical reads 268002, physical reads 4, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ContentTypes_Audit'. Scan count 0, logical reads 1851736, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ResponseProductContentInfoLog_Audit'. Scan count 188650, logical reads 961078, physical reads 1023, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'PractitionerAudit_Audit'. Scan count 0, logical reads 754600, physical reads 335, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'EcarePractitioner'. Scan count 0, logical reads 565950, physical reads 642, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'PractitionerAuditmap'. Scan count 188650, logical reads 755866, physical reads 45, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ResponseProductInfoLog_Audit'. Scan count 196310, logical reads 787414, physical reads 71, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ResponseLog_Audit'. Scan count 196310, logical reads 786852, physical reads 56, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Partner_Audit'. Scan count 0, logical reads 392620, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'RequestLog_Audit'. Scan count 2, logical reads 818, physical reads 7, read-ahead reads 390, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(I know it's a lot but I end up putting full results on purpose) As you can see, this plan did lots of scans and logical reads.

Then I ran another query:

DBCC DROPCLEANBUFFERS
go
checkpoint
go
USE [dbname]
GO
set statistics io on
DECLARE       @return_value int
--GOOD SQL PLAN
EXEC   @return_value = [dbo].[AnStoredProcedure]
              @StartRequestIdTransform = 45696687,
              @EndRequestIdTransform = 45796687

Even though the start and end parameters are different, the amount between is exactly same which is 100000. This one returned 471598 records (more than the previous one). However, this one took 56 seconds to run and the statistics look better as following:

DBCC execution completed. If DBCC printed error messages, contact your system administrator.
Table 'DWH_PractitionerDedupeMapping'. Scan count 9, logical reads 958, physical reads 9, read-ahead reads 319, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'AccessHistoryLog_Audit'. Scan count 18, logical reads 1294, physical reads 11, read-ahead reads 617, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'StateZipcodeMapping'. Scan count 18, logical reads 478, physical reads 38, read-ahead reads 128, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ServiceList'. Scan count 2, logical reads 4, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ManufacturerServices'. Scan count 2, logical reads 4, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ContractServiceMapping'. Scan count 2, logical reads 4, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'DrugLabel_Lookup'. Scan count 18, logical reads 206, physical reads 18, read-ahead reads 51, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'CustomerLookup'. Scan count 2, logical reads 8, physical reads 2, read-ahead reads 16, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'InstitutionMappings'. Scan count 2, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Partner_Audit'. Scan count 2, logical reads 6, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ContentTypes_Audit'. Scan count 2, logical reads 4, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ResponseLog_Audit'. Scan count 18, logical reads 952, physical reads 21, read-ahead reads 420, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'RequestLog_Audit'. Scan count 18, logical reads 950, physical reads 17, read-ahead reads 419, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ResponseProductInfoLog_Audit'. Scan count 18, logical reads 175594, physical reads 126, read-ahead reads 88552, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'PractitionerAuditmap'. Scan count 232688, logical reads 1013127, physical reads 276, read-ahead reads 104, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'EcarePractitioner'. Scan count 18, logical reads 11259, physical reads 46, read-ahead reads 5419, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ResponseProductContentInfoLog_Audit'. Scan count 191698, logical reads 1297326, physical reads 373, read-ahead reads 7053, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'PractitionerAudit_Audit'. Scan count 0, logical reads 972249, physical reads 181, read-ahead reads 2440, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'RequestParametersLog_Audit'. Scan count 943196, logical reads 4022270, physical reads 315, read-ahead reads 72, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'PM_Lookup'. Scan count 9, logical reads 22, physical reads 7, read-ahead reads 24, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

This result is much better overall. If you compare the scan/read stats for each table separately, you can see most of them have improvement, and a few stays similar.

At this point, it's confusing to us why two different plans SQL Server selected for such two similar queries.

I was also thinking if the good plan can be cached if I ran this queries several times, and then ran the other query to see if any change may happen. Here is what I got:

  1. I ran the query with GOOD plan 5 times, with cache cleaned only for the first time. (It's even faster after the first run)
  2. Without cache clean, I ran the other query (the one that had bad plan before)
  3. The other query GET NO LUCK. SQL Server generated SAME BUT BAD STILL plan for it, 81 seconds taken and same statistics provided.

This is something important to our database performance. We will keep investigating. At the same time, we are looking for any ideas from your sights. Again, thank you very much for reading this.

share|improve this question
    
Can you run with option recompile? Possibly parameter sniffing. Also would be useful to see queryplans - use plan explorer from SQL sentry. –  Kin Jul 10 at 22:57
    
Can you post the execution plans for both invocations somewhere and link to your post please. You're assuming the plans are different whereas its more likely the plans are identical and the data is different. I agree with @Kin that OPTION (RECOMPILE) would be sensible anyway given the complexity of the query. –  Mark Storey-Smith Jul 10 at 23:31
    
Plan Guides may help you. Also look at brentozar.com/archive/2014/07/… for some interesting reading. –  Max Vernon Jul 11 at 4:33
    
@MarkStorey-Smith and Kin: Yes we have WITH COMPILE option in the SP. I will do several more tests and post the findings and the actual plan. Will keep you updated. –  Joann.B Jul 11 at 18:18

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Browse other questions tagged or ask your own question.