Код для анализа иерархии транзакций в журнале

Автор: Paul Randal, Code to analyze the transaction hierarchy in the log

В рассылке для MVP было обсуждение представления sys.dm_tran_database_transactions и того, как с его помощью нельзя точно определить, сколько журнала сгенерировала операция, поскольку оно не предоставляет сводных метрик для подтранзакций внутри внешней транзакции. Это делает его вывод несколько неинтуитивным.

Это обсуждение побудило меня написать код, который я давно собирался сделать, ещё когда в SQL Server 2012 появилось поле в записях журнала LOP_BEGIN_XACT, отслеживающее идентификатор родительской транзакции, что позволяет исследовать иерархию транзакций.

Он предоставляет две хранимые процедуры, sp_SQLskillsAnalyzeLog и sp_SQLskillsAnalyzeLogInner, где первая использует вторую, а вторая рекурсивно вызывает саму себя.

Процедура sp_SQLskillsAnalyzeLog выведет иерархию транзакций в журнале транзакций. По умолчанию она показывает только транзакции верхнего уровня (без родительской транзакции) и имеет следующие параметры:

• @DBName (по умолчанию master)
• @Detailed (по умолчанию 0, при значении 1 показывает время начала транзакции и учётную запись Windows, только для транзакций верхнего уровня)
• @Deep (по умолчанию 0, при значении 1 показывает иерархию подтранзакций)
• @PrintOption (по умолчанию 0 для вывода в виде результирующего набора, 1 для текстового вывода)

Я настроил процедуры на размещение в базе master и пометил их как системные объекты с помощью sp_MS_marksystemobject. Вы можете изменить их место хранения по своему усмотрению.

Псевдокод выглядит следующим образом:

1. Получить информацию из журнала во временную таблицу 1
2. Создать временную таблицу 2 с кластерным индексом по столбцу идентификаторов
3. Для каждой транзакции верхнего уровня:
• Если задан параметр @Detailed, добавить имя пользователя и время начала.
• Получить последнюю транзакцию, добавленную во временную таблицу 2.
• Если она совпадает с той, которую мы собираемся добавить, увеличить счётчик для последней добавленной, иначе добавить новую.
• Если задан параметр @Deep, то, с глубиной рекурсии = 1, RP для каждой подтранзакции текущей транзакции следующего уровня:
• Добавить префикс '…' x глубина рекурсии к имени транзакции.
• Получить последнюю транзакцию, добавленную во временную таблицу 2.
• Если она совпадает с той, которую мы собираемся добавить, увеличить счётчик для последней добавленной, иначе добавить новую.
• Рекурсивно перейти к RP, увеличивая глубину рекурсии.
• (Такой подход значительно сокращает объём данных, хранимых во временной таблице 2)
4. Вывести результирующий набор или распечатать его в зависимости от параметра @PrintOption.

Рассмотрим пример с использованием базы данных SalesDB, которую можно восстановить из zip-архива на нашей странице ресурсов:

-- Восстановление базы данных
USE [master];
GO
ALTER DATABASE [SalesDB] SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
GO
RESTORE DATABASE [SalesDB]
    FROM DISK = N'D:\SQLskills\DemoBackups\SalesDB2014.bak'
WITH STATS = 10, REPLACE;
GO
 
ALTER DATABASE [SalesDB] SET RECOVERY SIMPLE;
GO
 
-- Создание уменьшенной копии таблицы Sales
USE [SalesDB];
GO
 
SELECT *
INTO [SalesCopy]
FROM [Sales]
WHERE [SalesID] < 100000;
GO
 
CREATE CLUSTERED INDEX [SalesCopy_CL] ON [SalesCopy] ([SalesID]);
GO
 
-- Очистка журнала
CHECKPOINT;
GO
 
-- Перестроение кластерного индекса в режиме ONLINE
ALTER INDEX [SalesCopy_CL] ON [SalesCopy] REBUILD WITH (ONLINE = ON);
GO
 
-- Анализ журнала
EXEC sp_SQLskillsAnalyzeLog salesdb, @Detailed = 1, @Deep = 1, @PrintOption = 1;
GO

Вывод:

ALTER INDEX by APPLECROSS\Paul @ 2016/05/01 11:26:48:113
...ONLINE_INDEX_DDL 2 times
OnlineIndexInsertTxn by APPLECROSS\Paul @ 2016/05/01 11:26:48:113
...BTree Split/Shrink
...BulkExtentAlloc
...SplitPage
...BulkExtentAlloc
...SplitPage
...BTree Split/Shrink
...BulkExtentAlloc
...SplitPage
...BulkExtentAlloc
...SplitPage 85 times
Allocate Root by APPLECROSS\Paul @ 2016/05/01 11:26:48:113
...AllocFirstPage
Allocate Root by APPLECROSS\Paul @ 2016/05/01 11:26:48:113
...AllocFirstPage
OnlineIndexInsertTxn by APPLECROSS\Paul @ 2016/05/01 11:26:48:150
...SplitPage
...BulkExtentAlloc
...SplitPage
...BulkExtentAlloc
...SplitPage 86 times
...BulkExtentAlloc
...SplitPage 89 times
...BulkExtentAlloc
...SplitPage 57 times
...BulkExtentAlloc
...SplitPage 31 times
...BulkExtentAlloc
...SplitPage 88 times
...BulkExtentAlloc
...SplitPage 52 times
SetFileSize @ 2016/05/01 11:26:48:303

Довольно здорово, правда? Вы можете видеть, что операция перестроения в режиме ONLINE использует множество транзакций верхнего уровня, что затрудняет точное определение объёма сгенерированного журнала транзакций, поскольку нет единой транзакции, которая бы управляла всем процессом. Но с помощью этого скрипта теперь вы можете видеть, что именно делает операция.

У этого инструмента есть и другие применения:

• Поиск в журнале для выяснения, кто и что делает.
• Анализ транзакций ваших хранимых процедур и того, что они вызывают в системе (например, расщепление страниц).

Надеюсь, вы найдёте это полезным! Дайте мне знать, если у вас есть пожелания по другим функциям, и я подумаю, возможны и осуществимы ли они. Я могу назвать как минимум:

• Добавление поддержки работы с резервными копиями журналов.
• Предоставление сводных данных об использованном месте в журнале для транзакций и их подтранзакций (будет довольно медленно, но выполнимо).

Наслаждайтесь!

Вот код, уверен, вероятно, есть способы сделать этот код более эффективным, я не эксперт в программировании на T-SQL :-)

/*============================================================================
  File:     sp_SQLskillsAnalyzeLog.sql
 
  Summary:  This script cracks the transaction log and prints a hierarchy of
            transactions
 
  SQL Server Versions: 2012 onwards
------------------------------------------------------------------------------
  Written by Paul S. Randal, SQLskills.com
 
  (c) 2016, SQLskills.com. All rights reserved.
 
  For more scripts and sample code, check out 
    http://www.SQLskills.com
 
  You may alter this code for your own *non-commercial* purposes. You may
  republish altered code as long as you include this copyright and give due
  credit, but you must obtain prior permission before blogging this code.
   
  THIS CODE AND INFORMATION ARE PROVIDED "AS IS" WITHOUT WARRANTY OF 
  ANY KIND, EITHER EXPRESSED OR IMPLIED, INCLUDING BUT NOT LIMITED 
  TO THE IMPLIED WARRANTIES OF MERCHANTABILITY AND/OR FITNESS FOR A
  PARTICULAR PURPOSE.
============================================================================*/
 
USE [master];
GO
 
IF OBJECT_ID (N'sp_SQLskillsAnalyzeLog') IS NOT NULL
    DROP PROCEDURE [sp_SQLskillsAnalyzeLog];
GO
 
IF OBJECT_ID (N'sp_SQLskillsAnalyzeLogInner') IS NOT NULL
    DROP PROCEDURE [sp_SQLskillsAnalyzeLogInner];
GO
 
CREATE PROCEDURE sp_SQLskillsAnalyzeLogInner (
    @XactID AS CHAR (13),
    @Depth AS INT)
AS
BEGIN
    DECLARE @String VARCHAR (8000);
    DECLARE @InsertString VARCHAR (8000);
    DECLARE @Name VARCHAR (256);
    DECLARE @ID INT;
 
    DECLARE @SubXactID CHAR (13);
    DECLARE @SubDepth INT = @Depth + 3;
 
    DECLARE [LogAnalysisX] CURSOR FAST_FORWARD LOCAL FOR
    SELECT [Transaction ID], [Transaction Name]
    FROM ##SQLskills_Log_Analysis
    WHERE [Parent Transaction ID] = @XactID;
 
    OPEN [LogAnalysisX];
 
    FETCH NEXT FROM [LogAnalysisX] INTO @SubXactID, @Name;
 
    WHILE @@FETCH_STATUS = 0
    BEGIN
        SELECT @InsertString = REPLICATE ('.', @Depth) + @Name;
 
        -- Select the last transaction name inserted into the table
        SELECT TOP 1
            @ID = [ID],
            @String = [XactName]
        FROM
            ##SQLskills_Log_Analysis2
        ORDER BY [ID] DESC;
 
        IF @String = @InsertString
            UPDATE
                ##SQLskills_Log_Analysis2
            SET
                [Times] = [Times] + 1
            WHERE
                [ID] = @ID;
        ELSE
            INSERT INTO ##SQLskills_Log_Analysis2
            VALUES (@InsertString, 1);
 
        -- Recurse...
        EXEC sp_SQLskillsAnalyzeLogInner @SubXactID, @SubDepth;
 
        FETCH NEXT FROM [LogAnalysisX] INTO @SubXactID, @Name;
    END;
 
    CLOSE [LogAnalysisX];
    DEALLOCATE [LogAnalysisX];
END
GO
 
CREATE PROCEDURE sp_SQLskillsAnalyzeLog (
    -- The name of a database, default of master
    @DBName AS sysname = N'master',
 
    -- Detailed = 0 means just the transaction name
    -- Detailed = 1 means time and user
    @Detailed AS INT = 0,
 
    -- Deep = 0 means only the top-level transactions
    -- Deep = 1 means sub-transaction hierarchy (slow!)
    @Deep AS INT = 0,
 
    -- PrintOption = 0 means SELECT as a resultset
    -- PrintOption = 1 means PRINT as text
    @PrintOption VARCHAR (25) = 0)
AS
BEGIN
    SET NOCOUNT ON;
 
    IF EXISTS (SELECT * FROM [tempdb].[sys].[objects]
        WHERE [name] = N'##SQLskills_Log_Analysis')
        DROP TABLE [##SQLskills_Log_Analysis];
 
    IF EXISTS (SELECT * FROM [tempdb].[sys].[objects]
        WHERE [name] = N'##SQLskills_Log_Analysis2')
        DROP TABLE [##SQLskills_Log_Analysis2];
 
    -- Only get the detailed info if we need it
    IF @Detailed = 1
        EXEC ('USE ' + @DBName + ';' +
            'SELECT [Transaction ID], [Transaction Name], [Parent Transaction ID],' +
            '[Begin Time], SUSER_SNAME ([Transaction SID]) AS [Who] ' +
            'INTO ##SQLskills_Log_Analysis FROM fn_dblog (null,null) ' +
            'WHERE [Operation] = ''LOP_BEGIN_XACT'';');
    ELSE
        EXEC ('USE ' + @DBName + ';' +
            'SELECT [Transaction ID], [Transaction Name], [Parent Transaction ID],' +
            'NULL AS [Begin Time], NULL AS [Who]' +
            'INTO ##SQLskills_Log_Analysis FROM fn_dblog (null,null) ' +
            'WHERE [Operation] = ''LOP_BEGIN_XACT'';');
     
 
    CREATE TABLE ##SQLskills_Log_Analysis2 (
        [ID]        INT IDENTITY,
        [XactName]  VARCHAR (8000),
        [Times]     INT);
 
    CREATE CLUSTERED INDEX [ID_CL]
    ON ##SQLskills_Log_Analysis2 ([ID]);
 
    -- Insert a dummy row to make the loop logic simpler
    INSERT INTO ##SQLskills_Log_Analysis2
    VALUES ('PSRDummy', 1);
 
    -- Calculate the transaction hierarchy
    DECLARE @XactID     CHAR (13);
    DECLARE @Name       VARCHAR (256);
    DECLARE @Begin      VARCHAR (100);
    DECLARE @Who        VARCHAR (100);
    DECLARE @String     VARCHAR (8000);
    DECLARE @ID         INT;
    DECLARE @Counter    INT;
 
    DECLARE [LogAnalysis] CURSOR FAST_FORWARD FOR
    SELECT
        [Transaction ID], [Transaction Name], [Begin Time], [Who]
    FROM
        ##SQLskills_Log_Analysis
    WHERE
        [Parent Transaction ID] IS NULL;
 
    OPEN [LogAnalysis];
 
    FETCH NEXT FROM [LogAnalysis] INTO @XactID, @Name, @Begin, @Who;
 
    WHILE @@FETCH_STATUS = 0
    BEGIN
        -- Select the last transaction name inserted into the table
        SELECT TOP 1
            @ID = [ID],
            @String = [XactName]
        FROM
            ##SQLskills_Log_Analysis2
        ORDER BY ID DESC;
 
        -- If it's the same as we're about to insert, update the counter,
        -- otherwise insert the new transaction name
        IF @String = @Name
            UPDATE
                ##SQLskills_Log_Analysis2
            SET
                [Times] = [Times] + 1
            WHERE
                [ID] = @ID;
        ELSE
        BEGIN
            SELECT @String = @Name;
 
            -- Add detail if necessary
            IF @Detailed = 1
            BEGIN
                -- Do this separately in case CONCAT_NULL_YIELDS_NULL is set
                IF @WHO IS NOT NULL
                     SELECT @String = @String + ' by ' + @Who;
 
                SELECT @String = @String + ' @ ' + @Begin;
            END
 
            INSERT INTO ##SQLskills_Log_Analysis2 VALUES (@String, 1);
        END
 
        -- Look for subtransactions of this one
        IF @Deep = 1
            EXEC sp_SQLskillsAnalyzeLogInner @XactID, 3;
 
        FETCH NEXT FROM [LogAnalysis] INTO @XactID, @Name, @Begin, @Who;
    END;
 
    CLOSE [LogAnalysis];
    DEALLOCATE [LogAnalysis];
 
    -- Discard the dummy row
    DELETE
    FROM
        ##SQLskills_Log_Analysis2
    WHERE
        [ID] = 1;
 
    -- Print the hierachy
    DECLARE [LogAnalysis2] CURSOR FOR
    SELECT
        [ID],
        [XactName],
        [Times]
    FROM
        ##SQLskills_Log_Analysis2;
 
    OPEN [LogAnalysis2];
 
    -- Fetch the first transaction name, if any
    FETCH NEXT FROM [LogAnalysis2] INTO @ID, @String, @Counter;
 
    WHILE @@FETCH_STATUS = 0
    BEGIN
        IF @Counter > 1
        BEGIN
            SELECT @String = @String + ' ' +
                CONVERT (VARCHAR, @Counter) + ' times';
        END
         
        -- If we're going to SELECT the output, update the row
        IF @PrintOption = 0
            UPDATE
                ##SQLskills_Log_Analysis2
            SET
                [XactName] = @String
            WHERE
                [ID] = @ID;
        ELSE
            PRINT @String;
 
        FETCH NEXT FROM [LogAnalysis2] INTO @ID, @String, @Counter;
    END;
 
    CLOSE [LogAnalysis2];
    DEALLOCATE [LogAnalysis2];
 
    IF @PrintOption = 0
    BEGIN
        SELECT
            [XactName]
        FROM
            ##SQLskills_Log_Analysis2;
    END
 
    DROP TABLE ##SQLskills_Log_Analysis;
    DROP TABLE ##SQLskills_Log_Analysis2;
END
GO
 
EXEC sys.sp_MS_marksystemobject [sp_SQLskillsAnalyzeLog];
EXEC sys.sp_MS_marksystemobject [sp_SQLskillsAnalyzeLogInner];
GO
 
-- EXEC sp_SQLskillsAnalyzeLog salesdb, 1, 1, 1;