Slow query performance with Table Spool operator

This is one of the blog post in a series of posts about optimizing SQL Server queries. A list of blog posts about query tuning can be found here – https://jbswiki.com/2021/04/15/sql-server-query-optimization-introduction/

-> Table Spool operator is used to store a copy of data in a worktable that can be used at a later stage in same or another part of the execution plan without having to produce the same data by calling its child operator all over again.

-> Table spool operator in SQL Server Management Studio graphical execution plan looks as below,

-> Table spool operators helps query performance most of the time by storing data in a worktable without requiring SQL Server to recompute the required data multiple times.

-> We will discuss a scenario where this operator slows down a query execution,

Create a database called JBSWIKI,

create database JBSWIKI

Create required objects,

use JBSWIKI
GO

create table Table1(
COL1 int identity(1,1),
Col2 nvarchar(max))

create table Table2(
COL1 int identity(1,1),
Col2 nvarchar(max))

create table Table3(
COL1 int identity(1,1),
Col2 nvarchar(max))

Populate the objects,

set nocount on

insert into Table1 
SELECT '+' + convert(varchar(15),convert(bigint,RAND() * 10000000000))
GO 500000

insert into Table2
SELECT '+' + convert(varchar(15),convert(bigint,RAND() * 10000000000))
GO 50

insert into Table3
SELECT '+' + convert(varchar(15),convert(bigint,RAND() * 10000000000))
GO 120

Execute below query,

set statistics time,io on
select * into #Temp_Table from Table1 where Col2 not in (select SUBSTRING(Col2,CHARINDEX(':',Col2)+1,len(Col2)-CHARINDEX(':',Col2)) from [dbo].Table2)
and Col2 not in (select SUBSTRING(Col2,CHARINDEX(':',Col2)+1,len(Col2)-CHARINDEX(':',Col2)) from [dbo].Table3)
drop table #Temp_Table
set statistics time,io off

-> As per below details this query took 6.8 seconds duration and utilized 35439 MS CPU. Logical reads performed on Table3 and Worktable is around 500009 and 1000792 respectively.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
Table ‘Table3‘. Scan count 17, logical reads 500009, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Worktable‘. Scan count 8, logical reads 1000792, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Table2’. Scan count 8, logical reads 8, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Table1’. Scan count 9, logical reads 2514, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Workfile’. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
SQL Server Execution Times:
CPU time = 35439 ms, elapsed time = 6851 ms.

-> From the execution plan, Table spool operator stands out when compared to other operators. The logical reads performed for Worktable is comparatively very high.

-> Zooming out specifically to the Spool operator in the execution plan,

-> Object Table3 has 120 rows. Table spool operator estimates and processes 25 Million rows and this explains high logical reads for Worktable.

-> Lets try removing the table spool operator from execution plan using trace flag 8690 as advised in this article.


set statistics time,io on
select * into #Temp_Table from Table1 where Col2 not in (select SUBSTRING(Col2,CHARINDEX(':',Col2)+1,len(Col2)-CHARINDEX(':',Col2)) from [dbo].Table2)
and Col2 not in (select SUBSTRING(Col2,CHARINDEX(':',Col2)+1,len(Col2)-CHARINDEX(':',Col2)) from [dbo].Table3) OPTION (QUERYTRACEON 8690)
drop table #Temp_Table
set statistics time,io off

-> Table spool operator is no longer present. But the resource utilization is really high. This query now takes 2 Minutes 16 Seconds duration and 941780 MS CPU.

Table ‘Table3‘. Scan count 8, logical reads 500000, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Table2‘. Scan count 8, logical reads 500000, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Table1’. Scan count 9, logical reads 2514, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
SQL Server Execution Times:
CPU time = 941780 ms, elapsed time = 136280 ms.

-> Removing Table Spool operator from execution plan using trace flag 8690 did not help.

-> I rewrote the query to use a JOIN instead of NOT IN. Below are the results,

set statistics time,io on
select a.* into #Temp_Table from [dbo].Table1 a LEFT OUTER JOIN [dbo].Table2 b ON a.Col2 = SUBSTRING(b.Col2,CHARINDEX(':',b.Col2)+1,len(b.Col2)-CHARINDEX(':',b.Col2))
LEFT OUTER JOIN [dbo].Table3 c ON a.Col2 =SUBSTRING(c.Col2,CHARINDEX(':',c.Col2)+1,len(c.Col2)-CHARINDEX(':',c.Col2)) 
drop table #Temp_Table
set statistics time,io off

-> Table spool operator is not present. The resource utilization has completely come down. This query now takes just 960 MS duration and 1 logical reads on object Table3. I dont see any logical reads for worktable at all.

Table ‘Table3‘. Scan count 1, logical reads 1, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Table2’. Scan count 1, logical reads 1, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Table1’. Scan count 9, logical reads 2514, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Workfile’. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.
Table ‘Worktable’. Scan count 0, logical reads 0, physical reads 0, page server reads 0, read-ahead reads 0, page server read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob page server reads 0, lob read-ahead reads 0, lob page server read-ahead reads 0.

SQL Server Execution Times:
CPU time = 4500 ms, elapsed time = 960 ms.

Thank You,
Vivek Janakiraman

Disclaimer:
The views expressed on this blog are mine alone and do not reflect the views of my company or anyone else. All postings on this blog are provided “AS IS” with no warranties, and confers no rights.

Leave a Reply