Jimmer
Jimmer

Reputation: 41

SQL Server Execution Plan Actual Row Count Far Too Large For Simple Select

(Long story short - #3 in my list of strange execution plan notes is the problem, I think).

I'm currently encountering some pretty bad performance with a stored procedure that in the past has performed well - this is in the context of performance testing in which we restore a database, and then put load on the system. I can't figure out what has changed in this portion of our system. There is no substantive blocking according to blocking reports (we set the threshold to 1 second for some time to check this).

By capturing the execution plan, we have identified that a single query within the proc is to blame. The query is a simple

INSERT INTO #table (<columnset>)
SELECT <columnset> 
FROM table
WHERE <binary type column> > @binaryArgumentPassedIntoProc

For the source table: The timestamp column in the WHERE clause is indexed. One of the columns being selected is the PK and is of type varchar. 3 other columns are being selected (for a total of 5). The temp table has no indices/keys or constraints.

The schema on this table hasn't changed with one slight exception - one of the columns on the source table now has TrimTrailingBlanks set to yes. This column is not in the column set being selected from. I can't imagine that this matters but wanted to call it out.

When I restore point-in-time I am unable to replicate the slowness. During production execution (meaning when it ran slowly in performance testing environment) the query takes 30+ seconds sometimes. In the point-in-time backup the query takes under 1 second.

By comparing the execution plan data captured from both the production execution and point-in-time execution, I'm seeing a few confusing pieces. Note that the query (in both situations) inserts 180 rows into the temp table.

  1. The EstimatedRow count in the point in time backup execution is 176.683. It is 2 in the production execution. This is true for the select and insert
  2. The TableCardinality in the production execution for the select is 2, while it is 1578 in the point in time execution. This indicates that the statistics were bad in production, which isn't surprising though I'm not sure how to deal with this in realtime when the system is under such heavy load (there are actually 1578 rows in the table during execution). That being said, this hasn't been an issue in the past when the performance was fine.
  3. The Actual Number of Rows noted in the execution plan that are inserted into the temp table is listed as 3222 in the production execution. In the point in time execution, the Actual Number of Rows is listed as 180.

Regarding (3) - My understanding of Actual Number of Rows is that it is the number of times the iterator called GetNext() when executing the query. I would think that with a simple select (primarily no joins) the Actual Number of Rows value would, at a maximum, be equal to the number of rows in the table at that point (1578).

Finally, by capturing performance counters for the physical and logical disk, it doesn't like like there is significant disk queuing nor a correlation between disk queuing and the slow executions.

Does anyone have any suggestions regarding how I can troubleshoot this further?

We are running SQL Server 2008 R2 on a Windows Server 2008 R2 SP1 machine. The machine has 16 cores and 128 GB of RAM (64 dedicated to SQL server).

UPDATE: I seeded the tables with data after restoring and before the test, and then updated statistics and recompiled the procedure. The actual and expected row counts as well as table cardinality reflected realistic values, but we were still seeing very long executions.

Here is the XML showplan profile statistics trace event output for one of the bad queries in this latest test:

<ShowPlanXML xmlns="http://schemas.microsoft.com/sqlserver/2004/07/showplan" Version="1.1" Build="10.50.2500.0"><BatchSequence><Batch><Statements><StmtSimple><QueryPlan DegreeOfParallelism="1" CachedPlanSize="24" CompileTime="4" CompileCPU="4" CompileMemory="192"><RelOp NodeId="0" PhysicalOp="Table Insert" LogicalOp="Insert" EstimateRows="170" EstimateIO="0.010254" EstimateCPU="0.00017" AvgRowSize="9" EstimatedTotalSubtreeCost="0.0154085" Parallel="0" EstimateRebinds="0" EstimateRewinds="0"><OutputList/><RunTimeInformation><RunTimeCountersPerThread Thread="0" ActualRows="69" ActualEndOfScans="1" ActualExecutions="1"/></RunTimeInformation><Update DMLRequestSort="0"><Object Database="[tempdb]" Schema="[dbo]" Table="[#sourceTable]"/><SetPredicate><ScalarOperator ScalarString="[#destinationTable].[record_Identifier] = RaiseIfNullInsert([Expr1008]),[#destinationTable].[modifiedTS] = [Expr1009],[#destinationTable].[Last_Update] = [DBName].[dbo].[sourceTable].[last_update],[#destinationTable].[LastValueUpdate] = [DBName].[dbo].[sourceTable].[LastValueUpdate],[#destinationTable].[OtherValue_lastUpdate] = [DBName].[dbo].[sourceTable].[OtherValue_lastUpdate]"><ScalarExpressionList><ScalarOperator><MultipleAssign><Assign><ColumnReference Table="[#destinationTable]" Column="record_Identifier"/><ScalarOperator><Intrinsic FunctionName="RaiseIfNullInsert"><ScalarOperator><Identifier><ColumnReference Column="Expr1008"/></Identifier></ScalarOperator></Intrinsic></ScalarOperator></Assign><Assign><ColumnReference Table="[#destinationTable]" Column="modifiedTS"/><ScalarOperator><Identifier><ColumnReference Column="Expr1009"/></Identifier></ScalarOperator></Assign><Assign><ColumnReference Table="[#destinationTable]" Column="Last_Update"/><ScalarOperator><Identifier><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="last_update"/></Identifier></ScalarOperator></Assign><Assign><ColumnReference Table="[#destinationTable]" Column="LastValueUpdate"/><ScalarOperator><Identifier><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="LastValueUpdate"/></Identifier></ScalarOperator></Assign><Assign><ColumnReference Table="[#destinationTable]" Column="OtherValue_lastUpdate"/><ScalarOperator><Identifier><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="OtherValue_lastUpdate"/></Identifier></ScalarOperator></Assign></MultipleAssign></ScalarOperator></ScalarExpressionList></ScalarOperator></SetPredicate><RelOp NodeId="1" PhysicalOp="Compute Scalar" LogicalOp="Compute Scalar" EstimateRows="170" EstimateIO="0" EstimateCPU="1.7e-005" AvgRowSize="50" EstimatedTotalSubtreeCost="0.00498448" Parallel="0" EstimateRebinds="0" EstimateRewinds="0"><OutputList><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="last_update"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="LastValueUpdate"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="OtherValue_lastUpdate"/><ColumnReference Column="Expr1008"/><ColumnReference Column="Expr1009"/></OutputList><ComputeScalar><DefinedValues><DefinedValue><ColumnReference Column="Expr1008"/><ScalarOperator ScalarString="CONVERT_IMPLICIT(varchar(15),[DBName].[dbo].[sourceTable].[record_identifier],0)"><Convert DataType="varchar" Length="15" Style="0" Implicit="1"><ScalarOperator><Identifier><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="record_identifier"/></Identifier></ScalarOperator></Convert></ScalarOperator></DefinedValue><DefinedValue><ColumnReference Column="Expr1009"/><ScalarOperator ScalarString="CONVERT_IMPLICIT(binary(8),[DBName].[dbo].[sourceTable].[ModifiedTS],0)"><Convert DataType="binary" Length="8" Style="0" Implicit="1"><ScalarOperator><Identifier><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="ModifiedTS"/></Identifier></ScalarOperator></Convert></ScalarOperator></DefinedValue></DefinedValues><RelOp NodeId="2" PhysicalOp="Top" LogicalOp="Top" EstimateRows="170" EstimateIO="0" EstimateCPU="1.7e-005" AvgRowSize="58" EstimatedTotalSubtreeCost="0.00496748" Parallel="0" EstimateRebinds="0" EstimateRewinds="0"><OutputList><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="record_identifier"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="last_update"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="LastValueUpdate"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="ModifiedTS"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="OtherValue_lastUpdate"/></OutputList><RunTimeInformation><RunTimeCountersPerThread Thread="0" ActualRows="69" ActualEndOfScans="1" ActualExecutions="1"/></RunTimeInformation><Top RowCount="1" IsPercent="0" WithTies="0"><TopExpression><ScalarOperator ScalarString="(0)"><Const ConstValue="(0)"/></ScalarOperator></TopExpression><RelOp NodeId="3" PhysicalOp="Clustered Index Seek" LogicalOp="Clustered Index Seek" EstimateRows="170" EstimateIO="0.00460648" EstimateCPU="0.000344" AvgRowSize="58" EstimatedTotalSubtreeCost="0.00495048" TableCardinality="1402" Parallel="0" EstimateRebinds="0" EstimateRewinds="0"><OutputList><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="record_identifier"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="last_update"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="LastValueUpdate"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="ModifiedTS"/><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="OtherValue_lastUpdate"/></OutputList><RunTimeInformation><RunTimeCountersPerThread Thread="0" ActualRows="69" ActualEndOfScans="1" ActualExecutions="1"/></RunTimeInformation><IndexScan Ordered="1" ScanDirection="FORWARD" ForcedIndex="0" ForceSeek="0" ForceScan="0" NoExpandHint="0"><DefinedValues><DefinedValue><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="record_identifier"/></DefinedValue><DefinedValue><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="last_update"/></DefinedValue><DefinedValue><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="LastValueUpdate"/></DefinedValue><DefinedValue><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="ModifiedTS"/></DefinedValue><DefinedValue><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="OtherValue_lastUpdate"/></DefinedValue></DefinedValues><Object Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Index="[idx_sourceTable_modifiedts]" IndexKind="Clustered"/><SeekPredicates><SeekPredicateNew><SeekKeys><StartRange ScanType="GT"><RangeColumns><ColumnReference Database="[DBName]" Schema="[dbo]" Table="[sourceTable]" Column="ModifiedTS"/></RangeColumns><RangeExpressions><ScalarOperator ScalarString="CONVERT_IMPLICIT(timestamp,[@modifiedts],0)"><Identifier><ColumnReference Column="ConstExpr1010"><ScalarOperator><Convert DataType="timestamp" Style="0" Implicit="1"><ScalarOperator><Identifier><ColumnReference Column="@modifiedts"/></Identifier></ScalarOperator></Convert></ScalarOperator></ColumnReference></Identifier></ScalarOperator></RangeExpressions></StartRange></SeekKeys></SeekPredicateNew></SeekPredicates></IndexScan></RelOp></Top></RelOp></ComputeScalar></RelOp></Update></RelOp><ParameterList><ColumnReference Column="@modifiedts" ParameterCompiledValue="0x00000000008EB813" ParameterRuntimeValue="0x0000000000914056"/></ParameterList></QueryPlan></StmtSimple></Statements></Batch></BatchSequence></ShowPlanXML>

Upvotes: 2

Views: 1176

Answers (1)

Jimmer
Jimmer

Reputation: 41

Problem solved. The wrong Actual Row Count was due to bad statistics, and the blocking was due to a large number of very small queued locking queries running against the table. They were all too small to cause blocking reports to be generated even at 1 second threshold, but enough to cause blocking on the range of 10+ seconds. I made the select READUNCOMMITTED And altered the application code to work with this.

Upvotes: 2

Related Questions