I’ve blogged a bunch about using the undocumented fn_dblog function I helped write (and I’ve got a lot more to come :-) but here’s one I haven’t mentioned on my blog before: fn_dump_dblog (although I have talked about it at conferences last year).

Here’s a scenario: someone dropped a table and you want to find out when it happened and maybe who did it. The default trace has also wrapped so you can’t get the DDL trace from there anymore.

If the transaction log for the DROP hasn’t yet been cleared from the active portion of the log then you’d be able to use fn_dblog to search through the log for the information you need. You might even be able to look in the inactive portion of the log by using trace flag 2536, which instructs the log reader to ignore the log truncation point and dump all possible log records from the log.

But what do you do if the pertinent log records just don’t exist in the log anymore? They’re only in your log backups. You could tediously inch your way through restoring the log backups a few seconds at a time until you find the point at which the DROP took place, and then restore to just before that point so you can get the data back.

Or you could save a whole ton of time and use fn_dump_dblog which allows you to dump and search log records from a log backup file, without having to restore the database!

Edit 8/15/13: Beware – Jonathan just found out from a customer system that uses this extensively that every time fn_dump_dblog is called, it creates a new hidden SQLOS scheduler and up to three threads, which will not go away (and will not be reused) until a server restart. It’s a bug that the SQL team is going to fix now we’ve alerted them to it. Use with caution.

Finding a DROP in the log

Here’s an example – I’m going to create a table, populate it, back it up, then drop it.

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
USE [master];
GO
 
CREATE DATABASE [FNDBLogTest];
GO
USE [FNDBLogTest];
GO
SET NOCOUNT ON;
GO
 
-- Create tables to play with
CREATE TABLE [ProdTable] (
    [c1] INT IDENTITY,
    [c2] DATETIME DEFAULT GETDATE (),
    [c3] CHAR (25) DEFAULT 'a');
 
CREATE TABLE [ProdTable2] (
    [c1] INT IDENTITY,
    [c2] DATETIME DEFAULT GETDATE (),
    [c3] CHAR (25) DEFAULT 'a');
GO
 
INSERT INTO [ProdTable] DEFAULT VALUES;
GO 1000
 
-- Take initial backups
BACKUP DATABASE [FNDBLogTest] TO DISK = N'D:\SQLskills\FNDBLogTest_Full.bak' WITH INIT;
GO
BACKUP LOG [FNDBLogTest] TO DISK = N'D:\SQLskills\FNDBLogTest_Log1.bak' WITH INIT;
GO
 
INSERT INTO [ProdTable2] DEFAULT VALUES;
GO 1000

Now I’ll drop the table and add some more log records:

?
1
2
3
4
5
DROP TABLE [ProdTable];
GO
 
INSERT INTO [ProdTable2] DEFAULT VALUES;
GO 1000

Now how can I find the point at which the table was dropped?

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
SELECT
    [Current LSN],
    [Operation],
    [Context],
    [Transaction ID],
    [Description]
FROM
    fn_dblog (NULL, NULL),
    (SELECT
        [Transaction ID] AS [tid]
    FROM
        fn_dblog (NULL, NULL)
    WHERE
        [Transaction Name] LIKE '%DROPOBJ%') [fd]
WHERE
    [Transaction ID] = [fd].[tid];
GO

 

?
Current LSN            Operation       Context           Transaction ID Description
---------------------- --------------- ----------------- -------------  --------------------------------
0000009d:0000021e:0001 LOP_BEGIN_XACT  LCX_NULL          0000:00001ff7  DROPOBJ; <snip>
0000009d:0000021e:0002 LOP_LOCK_XACT   LCX_NULL          0000:00001ff7
0000009d:0000021e:0003 LOP_LOCK_XACT   LCX_NULL          0000:00001ff7
0000009d:0000021e:0008 LOP_MODIFY_ROW  LCX_IAM           0000:00001ff7
0000009d:0000021e:0009 LOP_MODIFY_ROW  LCX_PFS           0000:00001ff7  Deallocated 0001:0000009b
0000009d:0000021e:000a LOP_MODIFY_ROW  LCX_IAM           0000:00001ff7
0000009d:0000021e:000b LOP_MODIFY_ROW  LCX_PFS           0000:00001ff7  Deallocated 0001:0000009c
0000009d:0000021e:000c LOP_MODIFY_ROW  LCX_IAM           0000:00001ff7
0000009d:0000021e:000d LOP_MODIFY_ROW  LCX_PFS           0000:00001ff7  Deallocated 0001:0000009d
0000009d:0000021e:000e LOP_MODIFY_ROW  LCX_IAM           0000:00001ff7
0000009d:0000021e:000f LOP_MODIFY_ROW  LCX_PFS           0000:00001ff7  Deallocated 0001:0000009e
0000009d:0000021e:0010 LOP_MODIFY_ROW  LCX_IAM           0000:00001ff7
0000009d:0000021e:0011 LOP_MODIFY_ROW  LCX_PFS           0000:00001ff7  Deallocated 0001:0000009f
0000009d:0000021e:0012 LOP_MODIFY_ROW  LCX_PFS           0000:00001ff7  Deallocated 0001:0000009a
0000009d:0000021e:0013 LOP_HOBT_DDL    LCX_NULL          0000:00001ff7  Action 3 on HoBt 0xd:100 <snip>
0000009d:0000021e:0014 LOP_DELETE_ROWS LCX_MARK_AS_GHOST 0000:00001ff7
0000009d:0000021e:0032 LOP_LOCK_XACT   LCX_NULL          0000:00001ff7
...snip...

Cool eh?

Now I’ll take another log backup, which clears the log, and contains the log I just looked at.

?
1
2
BACKUP LOG [FNDBLogTest] TO DISK = N'D:\SQLskills\FNDBLogTest_Log2.bak' WITH INIT;
GO

Who Did the DROP?

If you want to figure out who ran the DROP command, look at the Transaction SID field for the DROP transaction’s LOP_BEGIN_XACT log record and then pass that value into the SUSER_SNAME () function. Simple!

Restoring using STOPBEFOREMARK

The LSN for the LOP_BEGIN_XACT log record is where I need to restore to just before.

To do that I need to convert the LSN to the format necessary when using the STOPBEFOREMARK option for RESTORE. The option is documented but the format is not – how helpful!!

The LSN we have from the log dump above is 0000009d:0000021e:0001. To convert it:

  • Take the rightmost 4 characters (2-byte log record number) and convert to a 5-character decimal number, including leading zeroes, to get stringA
  • Take the middle number (4-byte log block number) and convert to a 10-character decimal number, including leading zeroes, to get stringB
  • Take the leftmost number (4-byte VLF sequence number) and convert to a decimal number, with no leading zeroes, to get stringC
  • The LSN string we need is stringC + stringB + stringA

So 0000009d:0000021e:0001 becomes ’157′ + ’0000000542′ + ’00001′ = ’157000000054200001′.

The restore sequence to restore to just before the DROP is therefore:

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
RESTORE DATABASE [FNDBLogTest2]
    FROM DISK = N'D:\SQLskills\FNDBLogTest_Full.bak'
WITH
    MOVE N'FNDBLogTest' TO N'C:\SQLskills\FNDBLogTest2.mdf',
    MOVE N'FNDBLogTest_log' TO N'C:\SQLskills\FNDBLogTest2_log.ldf',
    REPLACE, NORECOVERY;
GO
 
RESTORE LOG [FNDBLogTest2]
    FROM DISK = N'D:\SQLskills\FNDBLogTest_Log1.bak'
WITH
    NORECOVERY;
GO
 
RESTORE LOG [FNDBLogTest2]
FROM
    DISK = N'D:\SQLskills\FNDBLogTest_Log2.bak'
WITH
    STOPBEFOREMARK = 'lsn:157000000054200001',
    NORECOVERY;
GO
 
RESTORE DATABASE [FNDBLogTest2] WITH RECOVERY;
GO

And the table is there again, right before the point it was dropped. You can see where I used the constructed LSN string in the final log restore.

[Edit] Mike Matthews from Dell, who’s attended several of our Immersion Events, sent me the following code that you can use to programmatically convert the LSN:

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
DECLARE @LogFile varchar(max);
 
SET @LogFile = 'H:\MSSQL11.MSSQLSERVER\MSSQL\Backup\BigDemoDB\';
SET @LogFile = @LogFile + 'BigDemoDB_Log_20120614_1345.trn';
 
WITH LSN_CTE
AS
(
SELECT TOP 1
       LogRecords.[Current LSN],
       LEFT( LogRecords.[Current LSN], 8 )          AS Part1,
       SUBSTRING( LogRecords.[Current LSN], 10, 8 ) AS Part2,
       RIGHT( LogRecords.[Current LSN], 4 )         AS Part3
FROM   fn_dump_dblog( DEFAULT, DEFAULT,DEFAULT, DEFAULT, @LogFile, DEFAULT,DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
                      DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT ) AS LogRecords
WHERE  [Transaction Name] LIKE '%DROPOBJ%'
)
SELECT [Current LSN],
       CAST( CAST( CONVERT( varbinary, Part1, 2 ) AS int ) AS varchar ) +
       RIGHT( '0000000000' + CAST( CAST( CONVERT( varbinary, Part2, 2 ) AS int ) AS varchar ), 10 ) +
       RIGHT( '00000'      + CAST( CAST( CONVERT( varbinary, Part3, 2 ) AS int ) AS varchar ), 5 ) AS [Converted LSN]
FROM   LSN_CTE;

Using fn_dump_dblog

So what if the log records are no longer in the log? I can use the fn_dump_dblog function.

Edit 8/15/13: Beware – Jonathan just found out from a customer system that uses this extensively that every time fn_dump_dblog is called, it creates a new hidden SQLOS scheduler and up to three threads, which will not go away (and will not be reused) until a server restart. It’s a bug that the SQL team is going to fix now we’ve alerted them to it. Use with caution.

For instance, here is how I can use it to look in the FNDBLogTest_Log2.bak backup:

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
SELECT
    COUNT (*)
FROM
    fn_dump_dblog (
        NULL, NULL, N'DISK', 1, N'D:\SQLskills\FNDBLogTest_Log2.bak',
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT);
GO

I have to specify all the DEFAULT parameters (63 of them!) or it won’t work. The other parameters are:

  • Starting LSN (usually just NULL)
  • Ending LSN (again, usually just NULL)
  • Type of file (DISK or TAPE)
  • Backup number within the backup file (for multi-backup media sets)
  • File name

So I could do the same query as I did above:

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
SELECT
    [Current LSN],
    [Operation],
    [Context],
    [Transaction ID],
    [Description]
FROM
    fn_dump_dblog (
        NULL, NULL, N'DISK', 1, N'D:\SQLskills\FNDBLogTest_Log2.bak',
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT),
    (SELECT
        [Transaction ID] AS [tid]
    FROM
        fn_dump_dblog (
            NULL, NULL, N'DISK', 1, N'D:\SQLskills\FNDBLogTest_Log2.bak',
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
            DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT)
    WHERE
        [Transaction Name] LIKE '%DROPOBJ%') [fd]
WHERE [Transaction ID] = [fd].[tid];
GO

Which works perfectly, but takes much longer to run.

So maybe you’re wondering what all the other parameters to fn_dump_dblog are for? They are for specifying the media families of a media set that has more than one media family.

Here’s an example using a log backup striped across two files:

?
1
2
3
4
5
BACKUP LOG [FNDBLogTest] TO
    DISK = N'D:\SQLskills\FNDBLogTest_Log3_1.bak',
    DISK = N'D:\SQLskills\FNDBLogTest_Log3_2.bak'
WITH INIT;
GO

If I try to use fn_dump_dblog and only specify a single file, I get an error:

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
SELECT
    COUNT (*)
FROM
    fn_dump_dblog (
        NULL, NULL, N'DISK', 1, N'D:\SQLskills\FNDBLogTest_Log3_1.bak',
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT);
GO

 

?
Msg 3132, Level 16, State 1, Line 1
The media set has 2 media families but only 1 are provided. All members must be provided.

So I have to specify both media families:

?
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
SELECT
    COUNT (*)
FROM
    fn_dump_dblog (
        NULL, NULL, N'DISK', 1, N'D:\SQLskills\FNDBLogTest_Log3_1.bak',
        N'D:\SQLskills\FNDBLogTest_Log3_2.bak', DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT,
        DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT);
GO

Summary

So there you go – some more powerful tools to add to your disaster recovery arsenal.

Enjoy!