Interpret SQL Transaction Log using sys.fn_dblog

Ever wondered how to read the transaction log for a database? There is an undocumented SQL function sys.fn_dblog which may help you to read T-Log except for the truncated transaction details. We can use this function effectively for point in time recovery at a LSN level.

First lets see how the typical output of the function, I have run the function on the AdventureWorks2012 DB,

select * from sys.fn_dblog(NULL,NULL)

Note:-The 2 parameters for are sys.fn_dblog StartLSN and EndLSN if you want to see the operation between specific LSN range. Default NULL, NULL will read the entire T-Log.

There you go you can see a CurrentLSN Column, Operations Column, TransactionID, PreviousLSN column etc, I am not going to discuss all columns in detail but we will see the use of some of them in our exercise today.

As you can see in the Operations column you can see operation like INSERT(LOP_INSERT_ROWS), Begin transaction(LOP_BEGIN_XACT), CheckpointEnd(LOP_END_CKPT)etc. Lets carry out an example and see how can we interpret these details.

Lets Create a Table and see what happens in the Log,

CREATE TABLE Test (a int)

GO

select [Current LSN],Operation,Context,[Transaction ID],[Previous LSN],[Transaction Name],AllocUnitName,[Begin Time] from sys.fn_dblog(NULL,NULL) ORDER BY [Transaction ID] 

As you can see there is a BEGIN TRAN event(LOP_BEGIN_XACT) with the corresponding Transaction name column as "CREATE TABLE", this is followed by set of INSERT and UPDATE operation(LOP_INSERT_ROWS and LOP_MODIFY_ROW) on various system tables(Refer AllocUnitName Column on the pic) for the new table creation.

Next I insert values to the table,

INSERT INTO Test Values(1)

GO

INSERT INTO Test Values(2)

GO

INSERT INTO Test Values(3)

GO

select [Current LSN],Operation,Context,[Transaction ID],[Previous LSN],[Transaction Name],AllocUnitName,[Begin Time],[End Time] from sys.fn_dblog(NULL,NULL) ORDER BY [Transaction ID]

As you can see we have 3 LOP_BEGIN_XACT,LOP_INSERT_ROWS,LOP_COMMIT_XACT set of operation for the 3 row insert and some page allocation tasks. You can also see we have start time for Begin TRAN and a End Time for the Commit Tran. If you see the Context column for the INSERT operation you can see LCK_HEAP indicating inserting rows to a heap table.

Next I ran UPDATE,

UPDATE Test SET a = 5 where a = 1

As expected you can see LOP_MODIFY_ROW on a LCX_HEAP for the UPDATE statement. Next I ran DELETE,

DELETE from Test where a = 5

 There you go LOP_DELETE_ROWS operation on LCX_HEAP. 

Next I ran,

DROP TABLE Test

As in CREATE Table statement DROP Table has LOP_BEGIN_XACT,LOP_LOCK_XACT operation followed by updating system tables operations and finally Commit operation LOP_COMMIT_XACT.

Finally Lets see how a rollback looks like in the T-Log,

BEGIN TRAN

INSERT INTO Test Values(1)

ROLLBACK

There was a INSERT operation then on Rollback there was a DELETE operation of the inserted row and finally Abort Transaction operation(LOP_ABORT_XACT).

Now that we have seen how we can interpret the sys.fn_dblog output now we can see how we can put it to use, 

For example if an user DELETED multiple row by mistake and does not know what rows he deleted and comes to you for help and want to restore the database to a state exactly before the data deletion. We usually go back to restoring the backups but if you have multiple users using the DB how will you go to the exact state before the DELETE was issues that's where sys.fn_dblog can be very useful. You can just read the out of the Log around the time the delete was issued then note the CurrentLSN on the LOP_BEGIN_XACT operation for the Delete then Restore backup and Transaction log backup with STOPBEFOREMARK as the CurrentLSN on the LOP_BEGIN_XACT operation.

For assumption lets say my LOP_BEGIN_XACT is '0000002c:000000a9:001e' just prefix lsn:0x to the current LSN Value on LOP_BEGIN_XACT  operation in our case it will be lsn:0x0000002c:000000a9:001e.

Now Run RESTORE LOG with STOPBEFOREMARK,

RESTORE LOG [AdventureWorks2012]

FROM DISK = 'H:\DBBkp\Log\AdventureWorks2012_bkp25.trn'

WITH STOPBEFOREMARK = 'lsn:0x0000002c:000000a9:001e',

RECOVERY;

This should exactly get us back to a state exactly before the DELETE statement issued.