I have a batch which updates a table based on its primary key
SET NOCOUNT ON
go
IF OBJECT_ID('Tab1') IS NOT NULL
BEGIN
DROP TABLE Tab1
END
go
CREATE TABLE Tab1
(
Tab1_ID INT IDENTITY PRIMARY KEY CLUSTERED,
Some_GUID UNIQUEIDENTIFIER NULL
)
GO
INSERT Tab1(Some_GUID)
SELECT top 100000 NEWID() --Populate the test table. The more the rows in here the more acute the issue
FROM sysobjects a CROSS JOIN sysobjects b CROSS JOIN sysobjects c
GO
IF OBJECT_ID('proc1') IS NOT NULL
BEGIN
DROP PROC proc1
END
go
CREATE PROC proc1 (@Tab1_ID INT)
AS
BEGIN
CREATE TABLE #t1 (Tab1_ID INT)
INSERT #t1 VALUES (@Tab1_ID)
UPDATE Tab1 --MyTag
SET Some_GUID = Some_GUID--just some dummy
FROM Tab1 JOIN #t1 ON Tab1.Tab1_ID = #t1.Tab1_ID
DROP TABLE #t1
END
GO
IF OBJECT_ID('PrintStats') IS NOT NULL
BEGIN
DROP PROC PrintStats
END
go
--Proc which will print statistics about our update statement
CREATE PROC PrintStats
AS
BEGIN
--ACK.. Query copied from some website
DECLARE @Milliseconds INT = 1000
SELECT Command, [Execution Count], [Max Worker Time]
--ignore. This is just a tag
FROM
(
-- Get top total worker time queries for entire instance (Query 36) (Top Worker Time Queries)
SELECT DB_NAME(t.[dbid]) AS [Database Name],SUBSTRING(t.TEXT, (qs.statement_start_offset/2)+1,
((CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(t.TEXT)
ELSE qs.statement_end_offset
END - qs.statement_start_offset)/2)+1) AS Command,
qs.execution_count AS [Execution Count],
qs.total_worker_time / @Milliseconds AS [Total Worker Time], qs.min_worker_time/@Milliseconds AS [Min Worker Time],
qs.total_worker_time/qs.execution_count / @Milliseconds AS [Avg Worker Time],
qs.max_worker_time / @Milliseconds AS [Max Worker Time],
qs.min_elapsed_time / @Milliseconds AS [Min Elapsed Time],
qs.total_elapsed_time/qs.execution_count / @Milliseconds AS [Avg Elapsed Time],
qs.max_elapsed_time / @Milliseconds AS [Max Elapsed Time],
qs.min_logical_reads AS [Min Logical Reads],
qs.total_logical_reads/qs.execution_count AS [Avg Logical Reads],
qs.max_logical_reads AS [Max Logical Reads],
qs.creation_time AS [Creation Time],
qs.last_execution_time
FROM sys.dm_exec_query_stats AS qs WITH (NOLOCK)
CROSS APPLY sys.dm_exec_sql_text(plan_handle) AS t
CROSS APPLY sys.dm_exec_query_plan(plan_handle) AS qp
)
AS T
WHERE Command like '%MyTag%' and Command not like '%--ignore%'
END
GO
SELECT @@VERSION
--BEGIN TRAN
GO
DECLARE @i INT = 10000 --How many times to execute
DECLARE @Tab1_ID INT
SELECT @Tab1_ID=MAX(Tab1_ID) FROM Tab1
WHILE (@i > 0 )
BEGIN
EXEC proc1 @Tab1_ID = @Tab1_ID
IF (@i - 1) % 1000 = 0 --Print max_worker_time every 1000 iteration
BEGIN
EXEC PrintStats
END
SELECT @i = @i - 1
END
EXEC PrintStats
go
--ROLLBACK TRAN
go
The query has superb performance. The total_worker_time reported by dm_exec_query_stats is very low and Average=total_worker_time/execution_count value is very low. The execution plan too looks great with seeks on primary key. Now, when I execute the same batch in a transaction by uncommenting the begin tran and commit tran above, the performance starts to degrade. And it is a "slow" degrade. Let me explain. As the batch is executing, I watch the query stats by repeatedly executing a select * on dm_exec_query_stats. The Average=total_worker_time/execution_count keeps going up by a 1ms as I gather the statistics. The query degrades so much that by the time the batch ends, the Average has gone from 0ms to almost 8ms .
Why should the same query behave sub-optimally when in a transaction ? It is the same record being updated over and over again. I monitored the wait stats too and nothing jumps out as a cause. There are negligible waits on the LOGWRITE and/or SIGNAL_WAITS. The SQL server has more than enough memory, CPUs and fast drives. Is there a simple explanation for this phenomenon ? If this is not expected behavior, what should I be checking on the instance ? Is there a WAIT that I should be monitoring ? This is a SQL SERVER 2019 box operating at the DEFAULT ISOLATION LEVEL.
Here is the reason why I created this reproduction. We have a client application which does a series of updates on a table based on primary_keys within a transaction. The developers complained of sub-optimal performance. When I captured the statements in a profiler trace and ran them on the test box outside of a transaction, they were"extremely fast". But when I ran them in a transaction, the performance was poor. I found the same UPDATE statement starting to log an increase amount of CPU time as execution proceeded.
Please let me know if more information is needed to guide me in the right direction and I will provide it
Any help in resolving the issue appreciated
