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