Lessons Learned #561: It is Fast on the Other Server —What Should We Compare First?
While working on a support case, our customer told us that a stored procedure was taking longer than expected. “It’s fast on the other server,” they explained. Our customer was executing the same stored procedure with the same parameter value in both environments. They had already compared the data and indexes and had not found an obvious explanation for the difference. At that point, we had a symptom, but we still needed evidence to explain it. My first question was simple: was the slower execution doing more work, or taking longer to do comparable work? To answer that question, we needed to look beyond the query text. We would compare the actual execution plans, logical reads, CPU time, and elapsed time, using each observation to guide the next step. In this article, I would like to share how I investigated the problem, step by step. For the demonstration, I will use two tables with identical data and equivalent indexes in the same Azure SQL Database. You can also run this example on two different servers, using one copy of the table on each server. Step 1: Collect evidence from both executions The customer had already compared the data and indexes. Before making any changes, I asked them to collect the same information from both environments: The actual execution plan. The output from SET STATISTICS IO ON. The output from SET STATISTICS TIME ON. We also needed to confirm that both tests used the same parameter value and returned the same results. The execution time told us that there was a difference. These additional details would help us understand why. Logical reads show how many page accesses an execution performs. CPU time shows how much processor time it uses, while elapsed time shows how long it takes. The actual execution plans help us connect those measurements to the operations performed. I wanted to compare this evidence before updating statistics, changing indexes, or recompiling the procedure. Those changes could alter the behavior we were trying to understand. Step 2: The slower execution was doing more work Once we had collected the execution plans and measurements, I started by comparing logical reads, CPU time, and elapsed time. The measurements showed a clear difference: Metric Execution A Execution B Logical reads 30,418 1,532,129 CPU time 219 ms 954 ms Elapsed time 216 ms 1,284 ms Physical reads 0 0 In this sample, execution B took almost six times as long and performed approximately 50 times as many logical reads. We now had an important clue: the slower execution was doing considerably more work. Both executions reported zero physical reads. However, that did not mean that accessing the data was free. Logical reads still represent page accesses through the buffer pool, and repeatedly accessing those pages consumes resources. The higher CPU time in B supported the same observation. Waiting could also contribute to its elapsed time, but waiting alone would not explain the additional logical reads. My next step was to inspect the actual execution plans: which operations were responsible for that extra work? Step 3: An Index Seek does not always mean less work The difference in logical reads gave us a direction. I opened both actual execution plans to see how each execution accessed the data. Execution A used a Clustered Index Scan. It read one million rows, selected the 500,000 that matched the customer, and calculated the total. Execution B used an Index Seek, followed by Nested Loops and a Key Lookup. At first glance, the seek might look like the better choice. It located the customer's orders through the nonclustered index. However, that index did not contain Amount, which the query needed to calculate the total. For each matching order, the plan retrieved the missing value from the clustered index. The Key Lookup executed 500,000 times. That helped explain the additional logical reads: execution B repeatedly accessed the clustered index to retrieve individual rows. Observation Execution A Execution B Access pattern Clustered Index Scan Index Seek followed by Key Lookups Estimated matching rows 500,000 100 Actual matching rows 500,000 500,000 Key Lookup executions None 500,000 The estimates provided our next clue. Execution A expected 500,000 matching rows and received 500,000. Execution B expected only 100, but received 500,000—5,000 times its estimate. A seek followed by a small number of lookups can be efficient. However, repeating those lookups half a million times can become expensive. The plans also used different execution modes: A used batch mode, while B used row mode. This was another difference to keep in mind when comparing CPU and duration. The question was no longer simply why B was slower. Why did its cached plan expect only 100 rows? Step 4: Same runtime parameter, different compiled values To understand the estimate of 100 rows, I checked the parameter information in both actual execution plans. We had executed both procedures with @CustomerId = 2. However, the plans showed an important difference: Parameter property Execution A Execution B ParameterCompiledValue 2 1 ParameterRuntimeValue 2 2 The XML made this easy to see. Execution A: <ColumnReference Column="@CustomerId" ParameterDataType="int" ParameterCompiledValue="(2)" ParameterRuntimeValue="(2)" /> Execution B: <ColumnReference Column="@CustomerId" ParameterDataType="int" ParameterCompiledValue="(1)" ParameterRuntimeValue="(2)" /> ParameterCompiledValue shows the value used when the plan was compiled. ParameterRuntimeValue shows the value used for the execution we captured. Both executions used customer 2, but their plans had been compiled for different customers. Both plans also reported that they were retrieved from cache. In our example, customer 1 has 100 orders, while customer 2 has 500,000. The estimate in B now made sense: its plan had been compiled for the customer with only 100 orders. Using a parameter value during compilation is normal behavior, commonly called parameter sniffing. It helps the optimizer use the available statistics to estimate how many rows the query will process. The difficulty appears when a plan suitable for one parameter value is reused for another value with very different needs. Here, the plan compiled for 100 orders was reused to process 500,000. Different compiled and runtime values alone do not prove a performance problem. In this investigation, however, they connected several observations: the estimate of 100 rows, the 500,000 actual rows, the repeated Key Lookups, and the additional logical reads. We had a strong explanation. Our next step was to test it by compiling for the current parameter and comparing the work again. Step 5: Test the explanation The parameter information gave us a strong clue, but I wanted to test whether a new plan compiled for the current customer would reduce the work. We executed procedure B with the same parameter, this time requesting recompilation: EXEC dbo.GetCustomerOrdersB @CustomerId = 2 WITH RECOMPILE; The new actual execution plan showed both the compiled and runtime parameter values as 2. Instead of the Index Seek followed by 500,000 Key Lookups, the optimizer selected a Clustered Index Scan. It estimated 500,000 matching rows and received 500,000. The measurements also changed: Metric B: original cached plan B: recompiled execution Logical reads 1,532,129 30,418 CPU time 954 ms 344 ms Statement elapsed time 1,284 ms 346 ms Estimated matching rows 100 500,000 Actual matching rows 500,000 500,000 These timings are individual observations, rather than benchmark averages. However, the reduction in logical reads clearly showed that the new execution performed less work. We had not changed the data, added an index, or updated statistics between these executions. The plan XML referenced the same statistics object with the same last-update timestamp and zero modifications. The important change was the plan compiled for the current parameter. It also used batch mode instead of the original plan's row mode. This supported our explanation: the original cached plan was suitable for a customer with few orders, but its repeated lookups became expensive when reused for a customer with 500,000 orders. Recompilation was useful here as a diagnostic test. However, recompiling every execution is not always the best long-term solution. We also need to consider how often the query runs, the cost of compilation, and the parameter values used by the application. What if the query is slower on another server? In this example, the execution history helped explain why equivalent queries performed different amounts of work. In a comparison between two servers, this is one possible cause, but it is not the only one. I would start with the same evidence: actual execution plans, logical reads, CPU time, and elapsed time. From there, we can decide whether to investigate different plans, waits, configuration, or other differences between the environments. For a broader troubleshooting approach, see Microsoft's guide: Troubleshoot a query that shows a significant performance difference between two servers. Can Azure SQL Database handle different parameter needs? Recompilation helped us test our explanation. But could the database use different plans for customers with different numbers of orders, without compiling the query on every execution? This is where Parameter Sensitive Plan optimization, or PSP, can help. For eligible queries, PSP can maintain multiple plan variants and select a variant according to the runtime parameter value. A customer with few orders and a customer with many orders can therefore use different plans for the same parameterized query. PSP is available in Azure SQL Database with compatibility level 160 or later, provided the feature is enabled. Eligibility still matters: enabling it does not guarantee that every query will receive multiple variants. See Parameter Sensitive Plan optimization for details. Our first test deliberately used compatibility level 150. Next, we will repeat the experiment with PSP enabled, keeping the data, indexes, and stored procedures unchanged. We will check both the measurements and the plans to see whether PSP actually intervenes. Step 6: Verify that the feature actually intervenes Next, I repeated the test at compatibility level 160, after enabling PSP in the laboratory database. We executed the procedure for the customer with 100 orders first, followed by the customer with 500,000 orders. The captured plans showed that both executions still used the same plan, compiled for customer 1. The second execution performed 500,000 Key Lookups and reported 1,532,129 logical reads. I also checked the XML for evidence of PSP variants. The captured plans did not contain a dispatcher or a query variant identifier. PSP was enabled, but the captured plans showed no evidence that it was being used. I needed to find out why it had not generated plan variants for this query. Step 7: Check PSP configuration SELECT DB_NAME() AS DatabaseName, compatibility_level FROM sys.databases WHERE database_id = DB_ID(); SELECT name, value FROM sys.database_scoped_configurations WHERE name IN ( 'PARAMETER_SENSITIVE_PLAN_OPTIMIZATION', 'PARAMETER_SNIFFING' ); The results confirmed the configuration/settings: Compatibility level: 160. PARAMETER_SNIFFING: 1. PARAMETER_SENSITIVE_PLAN_OPTIMIZATION: 1. The configuration was correct, so I used Extended Events to find out why PSP had been skipped. I captured the reason during a new compilation using an in-memory ring buffer. -- 1. Create the session DECLARE @sql nvarchar(max); SET @sql = N' CREATE EVENT SESSION Lab_PSP_Reason ON DATABASE ADD EVENT sqlserver.parameter_sensitive_plan_optimization_skipped_reason ( ACTION(sqlserver.sql_text, sqlserver.session_id) WHERE ([sqlserver].[session_id] = (' + CONVERT(nvarchar(12), @@SPID) + N')) ), ADD EVENT sqlserver.query_with_parameter_sensitivity ( ACTION(sqlserver.sql_text, sqlserver.session_id) WHERE ([sqlserver].[session_id] = (' + CONVERT(nvarchar(12), @@SPID) + N')) ) ADD TARGET package0.ring_buffer ( SET max_memory = 1024 ) WITH (MAX_DISPATCH_LATENCY = 1 SECONDS);'; EXEC sys.sp_executesql @sql; ALTER EVENT SESSION Lab_PSP_Reason ON DATABASE STATE = START; -- 2. Trigger a new compilation EXEC sys.sp_recompile N'dbo.GetCustomerOrdersB'; EXEC dbo.GetCustomerOrdersB @CustomerId = 1; EXEC dbo.GetCustomerOrdersB @CustomerId = 2; WAITFOR DELAY '00:00:02'; -- 3. Read the XML before stopping the session SELECT CAST(t.target_data AS xml) AS CapturedEvents FROM sys.dm_xe_database_session_targets AS t JOIN sys.dm_xe_database_sessions AS s ON s.address = t.event_session_address WHERE s.name = N'Lab_PSP_Reason' AND t.target_name = N'ring_buffer'; -- 4. Stop and delete the session ALTER EVENT SESSION Lab_PSP_Reason ON DATABASE STATE = STOP; DROP EVENT SESSION Lab_PSP_Reason ON DATABASE; Why did PSP not generate variants? The database was using compatibility level 160, and both PSP and parameter sniffing were enabled. However, the captured plans still showed the same plan being reused. To understand why, I captured the Extended Event parameter_sensitive_plan_optimization_skipped_reason during a new compilation. It reported: <data name="reason"> <value>30</value> <text>SkewnessThresholdNotMet</text> </data> For this compilation, the optimizer's skewness threshold for PSP was not met, so it did not generate plan variants. This did not mean that the original plan was efficient for both customers. Our earlier measurements had already shown the additional work caused by reusing it for the larger customer. That was another useful lesson from the investigation: check whether an optimization actually intervened, rather than assuming that enabling it resolved the problem. PSP can help eligible queries, but we still need to inspect their plans and measure their behavior. Step 8: Reduce the work behind the slow execution Recompilation had helped us validate the explanation. Next, I wanted to test a change that would reduce the work even when the plan was compiled for the smaller customer. The nonclustered index contained CustomerId, but the query also needed Amount. The original plan retrieved that missing value through a Key Lookup for every matching order. We extended the existing index to include Amount: CREATE NONCLUSTERED INDEX IX_Orders_CustomerId ON dbo.OrdersB (CustomerId) INCLUDE (Amount) WITH (DROP_EXISTING = ON); Then we repeated the sequence that had exposed the problem: compile for the customer with 100 orders, followed by executions for the customer with 500,000 orders. This time, we did not use WITH RECOMPILE for those executions. Metric for the larger customer Before the index change After: first execution After: second execution Logical reads 1,532,129 1,426 1,426 CPU time 984 ms 141 ms 156 ms Elapsed time 1,501 ms 144 ms 154 ms Key Lookup executions 500,000 0 0 These measurements were collected at compatibility level 160 before and after the index change. The new plan obtained the required values directly from the nonclustered index. It no longer needed to retrieve Amount separately from the clustered index for each order. An important detail remained: the plan was still compiled for customer 1 and reused for customer 2. It still estimated 100 matching rows and processed 500,000. We had not eliminated the estimation difference. We had removed the repeated lookups that made that difference expensive in this example. The improvement also did not depend on PSP generating variants: the captured executions reused the same ordinary cached plan. For this query and the tested parameter values, extending the index provided a more efficient access path. Before applying the same approach in production, we would also evaluate the additional index storage and the maintenance cost for data changes. The goal was to reduce the work that made the reused plan expensive. The actual plan and measurements showed that the change achieved that in our test. What I learned from this investigation “It’s fast on the other server” was the starting point. To investigate it, we needed to compare what happened during each execution. In our demonstration, equivalent data and indexes did not lead to equivalent execution plans. Both measured executions used the same parameter, but their cached plans had been compiled for different customers. The slower execution expected 100 matching rows and processed 500,000. Its repeated Key Lookups helped explain the additional logical reads and CPU consumption. Recompilation helped us test that explanation. We then extended the existing index to include Amount, allowing the query to retrieve the required values without those lookups. Even after the index change, the execution for the larger customer reused a plan compiled for the smaller customer. The estimate remained inaccurate for the larger customer, but the expensive lookups were gone. Logical reads dropped from 1,532,129 to 1,426 in our compatibility-level-160 test. We also verified PSP rather than assuming it would intervene. Although it was enabled, Extended Events reported SkewnessThresholdNotMet for the compilation we captured. For me, the practical lessons were: Compare logical reads and CPU alongside elapsed time. Inspect the actual work behind an Index Seek or Scan. Compare estimated and actual rows at the relevant operators. Check compiled and runtime parameter values. Validate a proposed improvement using the execution sequence that exposed the problem. Confirm whether an optimization feature actually participated. The index change addressed the additional work in this example. Other queries may need a different approach, and index changes should be evaluated against the wider workload. When a customer says, “It’s fast on the other server,” my next question is: “What do the two executions show us?” Further reading For a broader investigation of performance differences between servers, see Troubleshoot a query that shows a significant performance difference between two servers. For details about plan variants, eligibility, and diagnostic events, see Parameter Sensitive Plan optimization.
