Search This Blog & Web

Sunday, April 27, 2014

Reading SQL Server Database Transaction Log

This is very exciting for me to query and look into Transaction log and see what is happening behind the scene. I will explain how to read your database transaction log file and how transactions are written for your database if you perform any database activity. 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.

The function (fn_dblog) requires a beginning LSN and ending LSN for a transaction. NULL is the default for this function and this will return all log records from the transaction log file.

Create a Database

To show how this works, we will create a database and a table to play with this function. Run the below SQL code to create a database and table.

--Create DB.
USE [master];
GO
CREATE DATABASE ReadLog;
GO
-- Create tables.
USE ReadLog;
GO
CREATE TABLE [Abc] (
    [Sr.No] INT IDENTITY,
    [Date] DATETIME DEFAULT GETDATE (),
    [Value] CHAR (25) DEFAULT 'Hoora');

We have created a database named "ReadLog" and a table 'Abc' with three columns. Now you can check all information and processes which have been used by SQL Server to create the database and table. We will run the below code to check the log file for this newly created database to check what processes and steps SQL Server took to create the database and table.

USE ReadLog;
GO
select COUNT(*) from fn_dblog(null,null)
  

We can see there are 476 rows that have been generated for just creating a dummy database and a blank table. Look at the below code to see the data in the transaction log file as shown in above attached picture


USE ReadLog;
GO
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...  It is pretty easy to understand the operation based on these key words to see what operation is being performed by SQL Server.

Looking at Insert 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 ReadLog
go
INSERT INTO Abc DEFAULT VALUES ;
GO 100
GO
UPDATE Abc
SET Value=Manama'
WHERE [Sr.No]<5
GO
DELETE Abc 
WHERE [Sr.No]>90
Go
Let's check our database log file again. As we saw from above, there is a lot of info logged in the transaction log file, so I will filter the data.
USE ReadLog
go
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')  



Your output will look something like the above screenshot after running the above script. From context it is easy to understand that table inserted as HEAP with Start and End Time. Page information, table info etc.

Similarly, it will show you this same kind of information for UPDATE and DELETE statements. You can have a lots of information from Log file like Page Split, Partition, Pages allocation etc.

Transaction Log behavior on Backup

Now I will run a backup and see the transaction log file again. Run a backup on this database and then again check the transaction log file.

Go USE ReadLog;
GO
Select COUNT(*)
FROM   fn_dblog(null,null)
 
BACKUP DATABASE [ReadLog] TO  DISK = N'c:\Program Files\Microsoft SQL Server\MSSQL10_50.SQLEXPRESS\MSSQL\Backup\ReadLog.bak' WITH NOFORMAT, NOINIT,  
NAME = N'ReadLog-Full Database Backup', SKIP, NOREWIND, NOUNLOAD,  STATS = 10
GO
 
Select COUNT(*)
FROM   fn_dblog(null,null)




As we can see, the number of rows has been drastically reduced after doing a backup and it has been reduced to 9 rows from 151. This means the inactive part of the log which tracked the transactions has been dumped to a backup file and the original entries from the log file have been flushed. Now you can shrink the log file if necessary.

How we can see Log data other than this function

DBCC Log(): command to see log information, but this command will not give you detail information. 
Trace flag 2537: look at all logs and not just the active log.


Recover data from Log file.

Using this fucntion fn_DBLog() you can restore T-Log backup upto required LSN so that you can retrive you data up to that point. 

There are some interesting options to recover your data from log and log backups. I will write blog on these after testing. I gather all this data from different blogs as follows

Trace flag 2536: You can see inactive portion of the log if not truncated or backed up.

fn_dump_dblog: allows you to dump and search log records from a log backup file, without having to restore the database


Related Blogs from different users.

No comments: