Code to show rolled back transactions after a crash

In Monday’s Insider newsletter I discussed an email question I’d been sent about how to identify the transactions that had rolled back because of a crash, and I said I’d blog some code to do it.

First of all you need to know the time of the crash. We can’t get this exactly (from SQL Server) unless SQL Server decides to shut itself down for some reason (like tempdb corruption) but we can easily get the time that SQL Server restarted, which is good enough, as we just need to know a time that’s after the transactions started before the crash, and before those transactions finished rolling back after a crash. We can get the startup time from the sqlserver_start_time column in the output from sys.dm_os_sys_info.

Then we can search in the transaction log, using the fn_dblog function, for LOP_BEGIN_XACT log records from before the crash point that have a matching LOP_ABORT_XACT log record after the crash point, and with the same transaction ID. This is easy because for LOP_BEGIN_XACT log records, there’s a Begin Time column, and for LOP_ABORT_XACT log records (and, incidentally, for LOP_COMMIT_XACT log records), there’s an End Time column in the TVF output.

And there’s a trick you need to use: to get the fn_dblog function to read log records from before the log clears (by the checkpoints that crash recovery does, in the simple recovery model, or by log backups, in other recovery models), you need to enable trace flag 2537. Now, if do all this too long after crash recovery runs, the log may have overwritten itself and so you won’t be able to get the info you need, but if you’re taking log backups, you could restore a copy of the database to the point just after crash recovery has finished, and then do the investigation.

After that, the tricky part is matching what those transactions were doing back to business operations that your applications were performing. If you don’t name your transactions, that’s going to be pretty hard, as all you’ve got are the generic names that SQL Server gives transactions (like INSERT, DELETE, DROPOBJ). Whatever the reason you might want this information, your applications should be written so they gracefully handle transaction failures and leave the database in a consistent state (as far as your business rules are concerned – of course SQL Server leaves the database in a transactionally-consistent state after a crash).

I’ve written some code and encapsulated it in a proc, sp_SQLskillsAbortedTransactions, which is shown in full at the end of the post. To use it, you go into the context of the database you’re interested in, and just run the proc. It takes care of enabling and disabling the trace flag.

Here’s an example of a crash situation and using the proc.

First I’ll create a table and start a transaction:

USE [master];
GO

IF DATABASEPROPERTYEX (N'Company', N'Version') > 0
BEGIN
    ALTER DATABASE [Company] SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
    DROP DATABASE [Company];
END
GO

CREATE DATABASE [Company];
GO
USE [Company];
GO

CREATE TABLE [test] ([c1] INT, [c2] INT, [c3] INT);
GO
INSERT INTO [test] VALUES (0, 0, 0);
GO

BEGIN TRAN FirstTransaction;
INSERT INTO [Test] VALUES (1, 1, 1);
GO

Now in a second window, I’ll start another transaction, and force the log to flush to disk (as I haven’t generated enough log to have the current log block automatically flush to disk):

USE [Company];
GO

BEGIN TRAN SecondTransaction;
INSERT INTO [Test] VALUES (2, 2, 2);
GO

EXEC sp_flush_log;
GO

And in a third window, I’ll force a crash:

SHUTDOWN WITH NOWAIT;
GO

After restarting the instance, I can use this code to run my proc:

USE [Company];
GO

EXEC sp_SQLskillsAbortedTransactions;
GO
Begin Time               Transaction Name   Started By       Transaction ID
------------------------ ------------------ ---------------- --------------
2017/01/18 17:09:36:190  FirstTransaction   APPLECROSS\Paul  0000:00000374
2017/01/18 17:09:40:600  SecondTransaction  APPLECROSS\Paul  0000:00000375

Cool eh?

Here’s the code – enjoy!

/*============================================================================
  File:     sp_SQLskillsAbortedTransactions.sql
 
  Summary:  This script cracks the transaction log and shows which
            transactions were rolled back after a crash
 
  SQL Server Versions: 2012 onwards
------------------------------------------------------------------------------
  Written by Paul S. Randal, SQLskills.com
 
  (c) 2017, 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_SQLskillsAbortedTransactions') IS NOT NULL
    DROP PROCEDURE [sp_SQLskillsAbortedTransactions];
GO
 
CREATE PROCEDURE sp_SQLskillsAbortedTransactions
AS
BEGIN
    SET NOCOUNT ON;

    DBCC TRACEON (2537);
 
    DECLARE @BootTime	DATETIME;
    DECLARE @XactID     CHAR (13);

    SELECT @BootTime = [sqlserver_start_time] FROM sys.dm_os_sys_info;

    IF EXISTS (SELECT * FROM [tempdb].[sys].[objects]
        WHERE [name] = N'##SQLskills_Log_Analysis')
        DROP TABLE [##SQLskills_Log_Analysis];

    -- Get the list of started and rolled back transactions from the log
    SELECT
        [Begin Time],
        [Transaction Name],
        SUSER_SNAME ([Transaction SID]) AS [Started By],
        [Transaction ID],
        [End Time],
        0 AS [RolledBackAfterCrash],
        [Operation]
    INTO ##SQLskills_Log_Analysis
    FROM fn_dblog (NULL, NULL)
    WHERE ([Operation] = 'LOP_BEGIN_XACT' AND [Begin Time] < @BootTime) OR ([Operation] = 'LOP_ABORT_XACT' AND [End Time] > @BootTime);

    DECLARE [LogAnalysis] CURSOR FAST_FORWARD FOR
    SELECT
        [Transaction ID]
    FROM
        ##SQLskills_Log_Analysis;
 
    OPEN [LogAnalysis];
 
    FETCH NEXT FROM [LogAnalysis] INTO @XactID;
 
    WHILE @@FETCH_STATUS = 0
    BEGIN
        IF EXISTS (
            SELECT [End Time] FROM ##SQLskills_Log_Analysis
            WHERE [Operation] = 'LOP_ABORT_XACT' AND [Transaction ID] = @XactID)
        UPDATE ##SQLskills_Log_Analysis SET [RolledBackAfterCrash] = 1
            WHERE [Transaction ID] = @XactID
            AND [Operation] = 'LOP_BEGIN_XACT';

        FETCH NEXT FROM [LogAnalysis] INTO @XactID;
    END;
 
    CLOSE [LogAnalysis];
    DEALLOCATE [LogAnalysis];
 
    SELECT
        [Begin Time],
        [Transaction Name],
        [Started By],
        [Transaction ID]
    FROM ##SQLskills_Log_Analysis
    WHERE [RolledBackAfterCrash] = 1;
 
    DBCC TRACEOFF (2537);

    DROP TABLE ##SQLskills_Log_Analysis;
END
GO
 
EXEC sys.sp_MS_marksystemobject [sp_SQLskillsAbortedTransactions];
GO
 
-- USE [Company]; EXEC sp_SQLskillsAbortedTransactions;

SQLskills holiday gift to you: all 2015 Insider videos

As we all wind down for the 2016 holiday season, we want to give the SQL Server community a holiday gift to say ‘thank you’ for all your support during 2016, and what better gift than more free content?!

As many of you know, I publish a bi-weekly newsletter to more than 13,500 subscribers that contains an editorial on a SQL Server topic, a demo video, and a book review of my most recently completed book. We’re making all the 2015 demo videos available so everyone can watch them – 25 videos in all, mostly in WMV format. I did the same thing the last few years for the 2014 videos2013 videos2012 videos, and 2011 videos.

Here are the details:

  • January 2015: Measuring sequential I/O performance (video | demo code)
  • January 2015: Incremental statistics (video | demo code)
  • February 2015: Delayed durability (video | demo code)
  • February 2015: Availability Groups using named instances (video | no demo code)
  • March 2015: Using sp_rev_login (video | demo code)
  • March 2015: Adding tempdb data files (video | demo code)
  • March 2015: Using DML triggers with CDC (from Pluralsight) (video | no demo code)
  • April 2015: Compensation log records (from Pluralsight) (video | demo code)
  • April 2015: The effects of AUTO_CLOSE (video | demo code)
  • May 2015: 2014 backup encryption (video | demo code)
  • May 2015: Using CrystalDiskMark for I/O benchmarking (video | no demo code)
  • June 2015: Backing up to a URL (video | no demo code)
  • June 2015: Using data compression (video | demo code)
  • July 2015: More on incremental statistics (video | demo code)
  • August 2015: Tracking page splits (from Pluralsight) (video | demo code)
  • August 2015: 2016 stretch database (video | demo code)
  • August 2015: Using CPU-Z for benchmarking (video | no demo code)
  • September 2015: Using Extended Events histogram targets (video | demo code)
  • September 2015: Converting scalar UDFs to inline TVFs (video | demo code)
  • October 2015: Low-priority lock waits (from Pluralsight) (video | demo code)
  • October 2015: Impact of the cluster key on index structure size (from Pluralsight) (video | demo code)
  • October 2015: Changes to @@VERSION (video | demo code)
  • November 2015: Introducing Query Store (video | demo code)
  • November 2015: Execution plan patterns (from PASS) (video | demo code)
  • December 2015: Predicate pushdown diagnostics (video | demo code)

If you want to see the 2016 videos before next December, get all the newsletter back-issues, and follow along as the newsletters come out, just sign-up at https://www.SQLskills.com/Insider. No strings attached, no marketing or advertising, just free content.

Happy Holidays and enjoy the videos!

Updated sys.dm_os_waiting_tasks script to add query DOP

[Edit 2016: Check out my new resource – a comprehensive library of all wait types and latch classes – see here.]

A question came up in class today about easily seeing the degree of parallelism for parallel query plans, so I’ve updated my waiting tasks script to pull in the dop field from sys.dm_exec_query_memory_grants. I’ve also added in a URL field that points into the new waits library, and shortened some of the column names.

Here it is for your use.

Enjoy!

(Note that ‘text’ on one line does not have delimiters because that messes up the code formatting plugin):

/*============================================================================
  File:     WaitingTasks.sql

  Summary:  Snapshot of waiting tasks

  SQL Server Versions: 2005 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.
============================================================================*/
SELECT
    [owt].[session_id] AS [SPID],
    [owt].[exec_context_id] AS [Thread],
    [ot].[scheduler_id] AS [Scheduler],
    [owt].[wait_duration_ms] AS [wait_ms],
    [owt].[wait_type],
    [owt].[blocking_session_id] AS [Blocking SPID],
    [owt].[resource_description],
    CASE [owt].[wait_type]
        WHEN N'CXPACKET' THEN
            RIGHT ([owt].[resource_description],
                CHARINDEX (N'=', REVERSE ([owt].[resource_description])) - 1)
        ELSE NULL
    END AS [Node ID],
    [eqmg].[dop] AS [DOP],
    [er].[database_id] AS [DBID],
    CAST ('https://www.sqlskills.com/help/waits/' + [owt].[wait_type] as XML) AS [Help/Info URL],
    [eqp].[query_plan],
    [est].text
FROM sys.dm_os_waiting_tasks [owt]
INNER JOIN sys.dm_os_tasks [ot] ON
    [owt].[waiting_task_address] = [ot].[task_address]
INNER JOIN sys.dm_exec_sessions [es] ON
    [owt].[session_id] = [es].[session_id]
INNER JOIN sys.dm_exec_requests [er] ON
    [es].[session_id] = [er].[session_id]
FULL JOIN sys.dm_exec_query_memory_grants [eqmg] ON
    [owt].[session_id] = [eqmg].[session_id]
OUTER APPLY sys.dm_exec_sql_text ([er].[sql_handle]) [est]
OUTER APPLY sys.dm_exec_query_plan ([er].[plan_handle]) [eqp]
WHERE
    [es].[is_user_process] = 1
ORDER BY
    [owt].[session_id],
    [owt].[exec_context_id];
GO