1

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

0
2

I was able to reproduce the issue with your updated example code (thanks for that!).

You're running into a form of this problem: Why is using a table variable more than twice as fast as a #temp table in this specific case?

If you have a procedure that's called with high frequency (many times per second), using table variables instead of temporary tables will significantly reduce the maintenance occurring in tempdb.

I tested replacing the temp table in dbo.Proc1 with a table variable, and average duration stabilized, even inside a transaction.

You can read more about this "internal maintenance" overhead in two articles from Paul White:

Side note: I'm actually not sure why the problem only shows up inside a transaction in this case

3
  • I read/read Paul's articles that you provided as links in here. And I do not think those are the reason for the degradation. Let me explain. I observed the temporary cache and the contents of the log using the SQL statements provided in the article while the BEGIN TRAN is in effect. The temporary cache kept growing with objects starting with #t1_. This is expected as the SQL Server just cannot rename the temporary object & reuse it while it is in the scope of a TRANSACTION. By the time the batch finishes, there are 10000 #t1___ objects in the cache which I guess is expected/understandable... – QFirstLast Apr 7 '20 at 19:40
  • ..Except for the intial flurry of entries, the log did not keep growing. To me, this makes sense. The UPDATE statement in the sample updates the column to the same value. The SQL Server may be smart enough to realize that nothing has changed and not log it. So.... if nothing goes into the log and the same temp object is being created during each execution with the exact same plan, cardinality and statistics, why does the Max Worker Time creep up as the execution proceeds ? I would expect it to remain more or less constant and not show a swing upwards. Any thoughts on this appreciated. – QFirstLast Apr 7 '20 at 19:50
  • @QFirstLast that's an interesting observation! I will take another look when I have some time. – Josh Darnell Apr 8 '20 at 13:09

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.