Transaction log grows due to long-running transactions when you use Change Data Capture - SQL Server & Azure SQL

  • Article

This article helps you to monitor and identify the issue of continuous transaction log growth caused by long-running transactions in a database with Change Data Capture (CDC) enabled on SQL Server, Azure SQL Database, and Azure SQL Managed Instance.

Symptoms

Consider the following scenario:

  • You enable Change Data Capture on a database.
  • The source of change data for CDC is the transaction log. As inserts, updates, and deletes are applied to tracked source tables, entries that describe those changes are added to the log.
  • The transaction log on the database grows due to long-running transactions.
  • When you query sys.databases for the given database, the log_reuse_wait_desc column shows REPLICATION.

In this scenario, the database transaction log file grows gradually, leading to excessive transaction log space consumption. Once the transaction log size reaches the max defined limit, writes to the database fail.

Cause

On a CDC-enabled database, capture job latency holds up log truncation to ensure changes can be captured from the transaction log to the CDC change tables, preventing loss of change data.

Workaround

You can use Transact-SQL (T-SQL) to specify the transaction log threshold and the time interval to monitor the transaction log. If necessary, you can terminate transactions by setting @kill_oldest_tran = 1.

To monitor the transaction log, use the following T-SQL query:

DECLARE 
    -- Log Transactions that generated Txlog over this size
    @transaction_log_bytes_used INT = 5242880,    -- 5MB (UPDATE)
    -- Log full threshold
    @log_full_threshold INT = 30,                 -- Percent (UPDATE)
    -- Kill Oldest Tran (0 = FALSE or 1 = TRUE)
    @kill_oldest_tran BIT = 0,                    --(UPDATE)
    -- Log Transactions over this duration
    @active_tran_time_minutes INT = 15,           --(UPDATE)
    -- This variable specifies the loop delay, format is Hours:minutes:seconds
    @delay VARCHAR(9) = '00:10:00',
    @runtime DATETIME,
    @starttime DATETIME,
    @msg NVARCHAR(100),
    @oldest_tran_id BIGINT,
    @oldest_tran_session_id INT,
    @oldest_tran_begin_time DATETIME,
    @killstr NVARCHAR(100)

IF OBJECT_ID('tblDiagLongTransactions') IS NULL
BEGIN
    CREATE TABLE tblDiagLongTransactions 
    (
        [datacollectiontime] [datetime] NOT NULL,
        [transaction_id] [bigint] NOT NULL,
        [name] [nvarchar](32) NOT NULL,
        [transaction_begin_time] [datetime] NOT NULL,
        [transaction_type] [int] NOT NULL,
        [transaction_state] [int] NOT NULL,
        [session_id] [int] NOT NULL,
        [is_user_transaction] [bit] NOT NULL,
        [database_transaction_log_bytes_used] [bigint] NOT NULL,
        [login_time] [datetime] NOT NULL,
        [last_request_start_time] [datetime] NOT NULL,
        [last_request_end_time] [datetime] NULL,
        [transaction_isolation_level] [smallint] NOT NULL,
        [host_name] [nvarchar](128) NULL,
        [nt_user_name] [nvarchar](128) NULL,
        [command] [nvarchar](32) NULL,
        [status] [nvarchar](30) NULL,
        [cpu_time] [int] NULL,
        [total_elapsed_time] [int] NULL,
        [Transaction_time_in_mins] [int] NULL,
        [logical_reads] [bigint] NULL,
        [wait_time] [int] NULL,
        [wait_type] [nvarchar](60) NULL,
        [wait_resource] [nvarchar](256) NULL,
        [blocking_session_id] [smallint] NULL,
        [program_name] [nvarchar](128) NULL,
        [granted_query_memory] [int] NULL,
        [writes] [bigint] NULL,
        [Request Reads] [bigint] NULL,
        [Session Reads] [bigint] NOT NULL,
        [Session Logical Reads] [bigint] NOT NULL,
        [statement_text] [nvarchar](max) NULL,
        [batch_text] [nvarchar](max) NULL,
        [objectid] [int] NULL,
        [query_hash] BINARY(8),
        [query_plan_hash] BINARY(8),
        [mostrecentsqltext] [nvarchar](max) NULL
    ) ON [PRIMARY]
END

WHILE (1=1)
BEGIN
    -- Check if the database log used space is over the threshold

    SET @runtime = GETDATE()
    INSERT INTO tblDiagLongTransactions
    SELECT DISTINCT 
        @runtime AS datacollectiontime,
        atr.transaction_id,
        atr.name,
        transaction_begin_time,
        transaction_type,
        transaction_state,
        dsr.session_id,
        dsr.is_user_transaction,
        dtr.database_transaction_log_bytes_used,
        s.login_time,
        s.last_request_start_time,
        s.last_request_end_time,
        s.transaction_isolation_level,
        s.host_name,
        s.nt_user_name,
        r.command,
        r.status,
        r.cpu_time,
        r.total_elapsed_time,
        DATEDIFF(mi, transaction_begin_time, getdate()) AS 'Transaction_time_in_mins',
        r.logical_reads,
        r.wait_time,
        r.wait_type,
        r.wait_resource,
        r.blocking_session_id,
        s.program_name,
        r.granted_query_memory,
        r.writes,
        r.reads AS [Request Reads],
        s.reads AS [Session Reads],
        s.logical_reads AS [Session Logical Reads],
        (REPLACE(REPLACE(REPLACE(REPLACE(SUBSTRING(qt.text, r.statement_start_offset / 2 + 1,
            (CASE WHEN r.statement_end_offset = -1 THEN LEN(CONVERT(NVARCHAR(MAX), qt.text)) * 2
                ELSE r.statement_end_offset
            END - r.statement_start_offset) / 2), ' ', ''), CHAR(13), ''), CHAR(10), ''), CHAR(9), '')) AS statement_text,
        SUBSTRING(REPLACE(REPLACE(REPLACE(REPLACE(qt.text, ' ', ''), CHAR(13), ''), CHAR(10), ''), CHAR(9), ''), 1, 256) AS batch_text,
        qt.objectid,
        query_hash,
        query_plan_hash,
        mqt.text
    FROM sys.dm_tran_active_transactions atr
    INNER JOIN sys.dm_tran_database_transactions dtr ON atr.transaction_id = dtr.transaction_id
    INNER JOIN sys.dm_tran_session_transactions dsr ON atr.transaction_id = dsr.transaction_id
    LEFT OUTER JOIN sys.dm_exec_sessions s ON dsr.session_id = s.session_id
    LEFT OUTER JOIN sys.dm_exec_connections conn ON s.session_id = dsr.session_id
    LEFT OUTER JOIN sys.dm_exec_requests r ON r.session_id = s.session_id
    OUTER APPLY sys.dm_exec_sql_text(r.sql_handle) AS qt
    OUTER APPLY sys.dm_exec_sql_text(conn.most_recent_sql_handle) AS mqt
    WHERE s.session_id != @@spid
        AND atr.transaction_type != 2
        AND (database_transaction_log_bytes_used > @transaction_log_bytes_used
            OR datediff(minute, transaction_begin_time, getdate()) > @active_tran_time_minutes)
    
    -- Check Log full threshold
    IF @kill_oldest_tran = 1
    BEGIN
        IF EXISTS (
            SELECT 1 FROM sys.dm_db_log_space_usage
            WHERE used_log_space_in_percent >= @log_full_threshold
        )
        BEGIN
            SELECT TOP 1
                @oldest_tran_id = atr.transaction_id,
                @oldest_tran_begin_time = transaction_begin_time,
                @oldest_tran_session_id = dsr.session_id
            FROM sys.dm_tran_active_transactions atr
            LEFT OUTER JOIN sys.dm_tran_database_transactions dtr ON atr.transaction_id = dtr.transaction_id
            LEFT OUTER JOIN sys.dm_tran_session_transactions dsr ON atr.transaction_id = dsr.transaction_id
            LEFT OUTER JOIN sys.dm_exec_sessions s ON dsr.session_id = s.session_id
            WHERE dsr.session_id != @@spid
                AND is_user_transaction = 1
            ORDER BY transaction_begin_time DESC

            SELECT @oldest_tran_id AS TranID, @oldest_tran_begin_time AS TranbeginTime, @oldest_tran_session_id AS SessionID
            SET @killstr = 'KILL ' + CAST(@oldest_tran_session_id AS VARCHAR(100))
            PRINT @killstr
            
            -- Kill oldest tran
            EXEC (@killstr)
            -- Checkpoint
            CHECKPOINT
        END
    END

    -- Change the polling interval as required
    WAITFOR DELAY @delay

END