HOW TO READ THE SQL SERVER DATABASE TRANSACTION LOG

Query

Have you ever wondered how SQL Server logs track transactions and what information SQL Server captures in the transaction log file?  We have a SQL Server function that can be used to read the transaction log to see what entries are made for database transactions.

Answer

There is an undocumented function called "fn_dblog" which enables you to read data from your transaction log which contains very informative data about things that are happening in your database.

Let us see this in practical

USE [master];

GO

CREATE DATABASE DataRead;

GO

-- Create tables.

USE DataRead;

GO

CREATE TABLE [Locality] (

    [Sr.No] INT IDENTITY,

    [Date] DATETIME DEFAULT GETDATE (),

    [City] CHAR (25) DEFAULT 'Bangalore');

We have created a database “DataRead” and a table “Locality” with three columns in it. We can check all the information and the processes which were used by SQL server while creating the database and the table. We need to run the below query 

USE DataRead;

GO

select ROWS = COUNT(*) from fn_dblog(null,null)

Rows

100

We can see there are 100 rows that have been generated for just creating a dummy database and a blank table. You can go and check the logs by using this function to get details for all processes used to create the database and table. Look at the below code to see the data in the transaction log file

select [Current LSN],

       [Operation],

       [Transaction Name],

       [Transaction ID],

       [Transaction SID],

       [SPID],

       [Begin Time]

FROM   fn_dblog(null,null)

You can see in the above screenshot that the transaction name column shows the database name, similarly it will show the create table for the table creation code. Transaction ID is the same for all parts of a transaction. The value for transaction name will be filled only when the particular transaction starts with "LOP_BEGIN_XACT" in the Operation column. "LOP_BEGIN_XACT" means begin transaction. The operation column will let us know which operation is performing like an insert, update, delete, shrink, lock, page allocation etc... 

Run some DML commands to see what is captured in a transaction log 

Now we will run a few DML scripts to check how data insertion, updating or deletion is logged in the database log file. During this operation you can also track how a page is allocated or de-allocated.

USE DataRead

go

INSERT INTO [Locality] DEFAULT VALUES ;

GO 100

GO

UPDATE Locality

SET City='Mumbai'

WHERE [Sr.No]<5

GO

DELETE Locality

WHERE [Sr.No]>90

Go

Let's check our database log file again. As we saw from above example, there is a lot of info logged in the transaction log file, so we will filter the data

SELECT

 [Current LSN],

 [Transaction ID],

 [Operation],

  [Transaction Name],

 [CONTEXT],

 [AllocUnitName],

 [Page ID],

 [Slot ID],

 [Begin Time],

 [End Time],

 [Number of Locks],

 [Lock Information]

FROM sys.fn_dblog(NULL,NULL)

WHERE Operation IN

   ('LOP_INSERT_ROWS','LOP_MODIFY_ROW',    'LOP_DELETE_ROWS','LOP_BEGIN_XACT','LOP_COMMIT_XACT')

Let's see how we can read the output. You can see the highlighted area which we will read as:

• INSERT statement with transaction ID 0000:00000562
• started at 2013/12/03 22:33:44:317
• Inserted a row in a HEAP table 'dbo.Locality' in page ID 0001:0000004d
• finished at 2013/12/03 22:33:44:317

 Similarly, it will show you this same kind of information for UPDATE and DELETE statements.

Finding internal SQL Server operations in transaction log

We can also check internal functions of SQL Server through this function. Let's take for example page splitting. We can track all info about page splits like how many times page splits occur, on which page and during which operation. Let's take a look at this below to see page splits for the above INSERT operation. Run the below SQL code to get all operations related to page splits

--Get how many times page split occurs.

SELECT

 [Current LSN],

 [Transaction ID],

 [Operation],

  [Transaction Name],

 [CONTEXT],

 [AllocUnitName],

 [Page ID],

 [Slot ID],

 [Begin Time],

 [End Time],

 [Number of Locks],

 [Lock Information]

FROM sys.fn_dblog(NULL,NULL)

WHERE [Transaction Name]='SplitPage'

As you can see above Page Split occur one time for the above DML activity? The first script will let us know how many times page splits occurred.

We can see the internal process that SQL server ran during this single page split operation by executing the below query. 

SELECT

 [Current LSN],

 [Transaction ID],

 [Operation],

  [Transaction Name],

 [CONTEXT],

 [AllocUnitName],

 [Page ID],

 [Slot ID],

 [Begin Time],

 [End Time],

 [Number of Locks],

 [Lock Information]

FROM sys.fn_dblog(NULL,NULL)

WHERE [Transaction ID]='0000:0000055d'

The above image takes the first page split, transaction ID ‘0000:0000055d’ and shows all internal processes.

Similarly if you drop any object or you perform other database operations they will get logged in the transaction log file which will then be visible using this function