Code to analyze the transaction hierarchy in the log

Over the weekend there was a discussion on the MVP distribution list about the sys.dm_tran_database_transactions DMV and how one cannot use it to accurately determine how much log an operation has generated because it doesn’t provide a roll-up of the sub-transaction metrics to the outer transaction. This makes the output somewhat non-intuitive.

The discussion prompted me to write some code I’ve been meaning to do since 2012, when SQL Server 2012 introduced a field in LOP_BEGIN_XACT log records that tracks the transaction ID of the parent transaction, allowing the hierarchy of transactions to be investigated.

The actual code is at the bottom of the article, and is available in a zip file here.

It provides two stored procs, sp_SQLskillsAnalyzeLog and sp_SQLskillsAnalyzeLogInner, with the former making use of the latter, and the latter calling itself recursively.

The sp_SQLskillsAnalyzeLog proc will dump the hierarchy of transactions in the transaction log. By default it will only show the top-level transactions (with no parent transaction), and it has the following parameters:

• @DBName (with a default of master)
• @Detailed (default 0, when 1 it will shows the transaction begin time and Windows login, for top-level transactions only)
• @Deep (default 0, when 1 it will show the sub-transaction hiearchy)
• @PrintOption (default 0 for a resultset, 1 for textual output)

I’ve set the procs to be in master and system objects using sp_MS_marksystemobject. You can change them to be stored wherever you want.

The pseudo-code is as follows:

• Get the info from the log into temp table 1
• Create temp table 2 with a clustered index on an identity column
• For each top-level transaction
  • If @Detailed, add the user name and start time
  • Get the last transaction added to temp table 2
  • If it’s the same as the one we’re about to add, increment the counter for the last one added, else add the new one
  • if @Deep, then, with recursion depth = 1,
    • **RP** for each sub-transaction of current next-level up transaction
      • Prefix ‘…’ x the recursion depth to the transaction name
      • Get the last transaction added to temp table 2
      • If it’s the same as the one we’re about to add, increment the counter for the last one added, else add the new one
      • Recurse to **RP**, increasing recursion depth
  • (doing it this way vastly reduces the amount of data to be stored in temp table 2)
• select the result set or print it, depending on @PrintOption

Let’s look at an example, using the SalesDB database that you can restore from a zip file on our resources page:

-- Restore the database
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

-- Create a smaller copy of the Sales table
USE [SalesDB];
GO

SELECT *
INTO [SalesCopy]
FROM [Sales]
WHERE [SalesID] < 100000;
GO

CREATE CLUSTERED INDEX [SalesCopy_CL] ON [SalesCopy] ([SalesID]);
GO

-- Empty the log
CHECKPOINT;
GO

-- Online rebuild the clustered index
ALTER INDEX [SalesCopy_CL] ON [SalesCopy] REBUILD WITH (ONLINE = ON);
GO

-- Analyze the log
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

Pretty cool, eh? You can see that the online rebuild uses a bunch of top-level transactions, which makes it difficult to determine exactly how much transaction log it generated as there isn’t one transaction that then drives everything else. But using this script, now you can see what an operation does.

There are other uses of this too:

• Searching through the log to see who’s doing what
• Analysis of your stored proc transactions and what they cause to happen under the covers on the system (e.g. page splits)

I hope you find this useful! Let me know if there are any other features you’d like to see and I’ll figure out if they’re possible and feasible. I can think of at least:

• Making it work on log backups
• Providing a roll-up of log space used for transactions and their sub-transactions (would be pretty slow, but do-able)

Enjoy!

Here’s the code, and it’s in the zip file here. I’m sure there are probably some ways to make this code more efficient, I’m not an expert T-SQL programmer :-)

/*============================================================================
  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;