SQL Server Query Optimization – Introduction

-> This is an Introduction blog post in a series of posts about optimizing SQL Server queries :-

-> SQL Server Parameter Sniffing
-> @@FETCH_STATUS -9
-> What DBCC SHOW_STATISTICS tells me
-> Trace Flag 7471
-> Tempdb contention
-> SQL Server Triggers and Insert performance
-> Optimize for ad hoc workloads
-> Why Bookmark Lookup is BAD?
-> Optimizing Queries using XML in SQL Server
-> Slow query performance with Table Spool operator

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.

SQL Server Triggers and Insert performance

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/

-> Customer advised that insert performance on a database server is very bad. When checked further, I was able to understand that inserting 100 rows onto a table JB_Table1 took 252 Seconds,

INSERT INTO [dbo].[JB_Table1]([SNO],[firstname],[lastname],[age],[salary],[Lastsalary]) VALUES (1,'abc','def',34,54367.3,getdate())
go 100

-> I initially thought that there may be several indexes on the table that might be slowing down the inserts. Hence I checked the available indexes on the table and saw just 1 index,

-> You can download the Database backup file from here and try it in your lab.

-> I then executed a single insert statement with an execution plan,

-> From the execution plan it is clear that “Query cost” for Insert statement is 0%, but the update statement is 100%. But where is the update coming from, as we have not executed any updates.

-> That is when I realized that there is an underlying trigger that performs this update.

-> I captured a profiler trace using below events,

-> From the above screenshot we are clearly able to understand that Trigger “trg_jb_Table1_create_date” is utilizing all the resources. It executes for 2.3 seconds, performs close to 1.5 GB Reads and utilizes 2.3 Seconds of CPU. The time taken by the insert statement is high because we are executing the trigger for every insert.

-> Above execution plan shows a missing Index. Lets try creating it and check the performance,


USE [JBDB]
GO
CREATE NONCLUSTERED INDEX [IX_Test1] ON [dbo].[JB_Table1] ([CreateDate])
GO

-> Lets execute the insert statement and then capture a trace,

-> Single Insert statement is now just taking 30 MS duration, 440 KB reads and 0 CPU. This is much better.

-> Lets check the trigger definition,

-> Every time a row is inserted into Table JB_Table1, this trigger is used to update the “CreateDate” column with getdate(). I think this trigger can be replaced with a default constraint as below,

ALTER TABLE dbo.JB_Table1
  ADD CONSTRAINT DF_CreateDate_JB_Table1
  DEFAULT getdate() FOR CreateDate;
GO

-> Once the constraint is created. Backup the trigger and drop it,

USE [JBDB]
GO

DROP TRIGGER [dbo].[trg_jb_table1_create_date]
GO

-> Lets execute the insert statement and then capture a trace,

-> Now the insert statement takes just 1 MS Duration, 56 KB reads and 0 CPU. The best solution in this scenario will be to use default constraint and remove the trigger.

-> Dont forgot to remove Index IX_Test1 which was created to speed up trigger “trg_jb_Table1_create_date”.

USE [JBDB]
GO
DROP INDEX [IX_Test1] ON [dbo].[JB_Table1]
GO

-> Inserting 100 rows now completes in Milliseconds.

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.

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.