SQL Server :Part 1 : Architecture of Transaction Log

In our earlier post, we have discussed in detail about the architecture of the data file and different types of pages. In this post, we will be discussing about the architecture of log file.

Logging is a mechanism used in RDBMS to support various ACID (Atomicity,Consistency,Isolation and Durability) properties of transactions. A transaction log is a physical file in which SQL server stores the details of all transactions and data modifications performed on the database.In the event of of disaster, that causes SQL server to shutdown unexpectedly (Power failure/hardware failure), the transaction log is used to bring the database in a consistent state while restarting the server.On restarting the server, database goes through the recovery process.During this recovery process , the transaction log is used to make sure that all committed transactions are written to respective data pages (rolled forward) and revert the uncommitted transaction that were written to data pages.

Logically transaction log is a set of log records.Each records is identified by a log sequence number (LSN). The new log records is always written at the logical end of log file with a LSN which is greater than the previous one.Each LSN will be associated with a transaction id , which can be used to group the log records of a transaction. As log file store the log records in the sequential order as it happens, It is not necessary that, log records of a transaction are always available in sequence in the log file.Each log records will have the LSN of previous log as a backward pointer and that will help in rollback of transaction.

Transaction log will store separate log entries for each operation.For example, while inserting a record into a table, transaction log will store separate log entry for inserting into clustered index and other non clustered index. In the same way, if a single update statement is updating 10 records, transaction log will capture 10 separate log entries.For data modification, transaction log store either the logical operation performed or the before and after image of the record.

To understand it better, let us look into the transaction log using the sys.fn_dblog. It is an undocumented function which will help us to read the active portion of the log. we are using the below query to create two tables and insert some records into that.We will delete the records from these table to keep the table clean. This insert and delete operation is to make sure that the pages are allocated to the table and we will not get unnecessary entries in the transaction log while examining it.We have issued a manual checkpoint to force the SQL server to write the log information to data file and clear the log. Note that, one table is heap table and other one is clustered index table.

USE Mydb

GO

CREATE TABLE LoginfoHeap

(
   id INT)


GO

CREATE TABLE LoginfoCI

(
   id INT PRIMARY KEY)


INSERT INTO LoginfoHeap VALUES(1),(2)

INSERT INTO LoginfoCI VALUES(2),(4)

GO

DELETE FROM LoginfoHeap 

DELETE FROM LoginfoCI

GO

CHECKPOINT

GO

SELECT 
[Current LSN], 
Operation  ,Context    ,
[Transaction ID],
[Previous LSN],AllocUnitName,[
Previous Page LSN],
[Page ID],[XACT ID],SUSER_SNAME(CONVERT(VARBINARY,[Transaction SID])) AS 'Login',
[Begin Time],[End Time]
FROM sys.fn_dblog (NULL, NULL)







From the output it is very clear that , we have only two active log entries.First one is written ,when the checkpoint started. The second one is written,  when the checkpoint completed the process.

Now we will insert,update and delete records to these tables through two session

---SESSION I
   BEGIN TRAN
   INSERT INTO LoginfoCI VALUES(2)

--SESSION 2
   BEGIN TRAN
   INSERT INTO LoginfoHeap VALUES(1),(2)

---SESSION I
   INSERT INTO LoginfoCI VALUES(4)

--SESSION 2
   UPDATE LoginfoHeap   SET id =8 WHERE id=1

---SESSION I
   UPDATE LoginfoCI  SET id =6 WHERE id=2

--SESSION 2
   DELETE FROM LoginfoHeap    WHERE id=2

---SESSION I
   DELETE FROM LoginfoCI   WHERE id=4
   SELECT * FROM sys.dm_tran_current_transaction
   COMMIT

--SESSION 2
   SELECT * FROM sys.dm_tran_current_transaction
   COMMIT

The DMV sys.dm_tran_current_transcation returns a single row that displays the state information of the current transaction in the current session.We are interested only in the transaction_id, which will help us to filter the output of sys.fn_dblog. Let us see the output of sys.fn_dblog.

SELECT 
[Current LSN], 
Operation  ,
Context    ,
[Transaction ID],
[Previous LSN],
AllocUnitName,
[Previous Page LSN],
[Page ID],[XACT ID],
SUSER_SNAME(CONVERT(VARBINARY,[Transaction SID])) AS 'Login',
[Begin Time],
[End Time]
FROM sys.fn_dblog (NULL, NULL) 
WHERE [Transaction ID] IN 
(
   SELECT [Transaction ID] FROM sys.fn_dblog (NULL, NULL) 
   WHERE [XACT ID] IN (856960,856981)
)

The values 856960 and 856981 are the transaction_id returned from sys.dm_tran_current_transaction.We have filter the output to get only the relevant rows in which we are interested.

In our script, we have opened two transaction and all our transaction log entries are grouped to
one of these transaction_id marked in red and green.Let us analyse what we did and how it is captured in the transaction log.

In the session 1, we have started the transaction and inserted a single record.The first records in the output map to the BEGIN TRAN command. This is the starting point of the transaction and created a new transaction_id.The previous LSNcolumn value is 0 as this is the first log entry in this transaction.In the same log records,it stores the XACT_ID,login and transaction start time.The second record represent the insert into the clustered table.The transaction_id is used to group the entries associated with a transaction. The previouse LSN column, is a pointer to the previous log entry in the same transaction which help SQL server to move backwards in case of rollback.Page id column refer the the page number where this LSN made the change.Previous Page LSN column refer the last log sequence number(LSN) which modify this page.When LSN modify a page, it will also update the corresponding LSN number in the page header (m_lsn field in the header. For more detail refer this post)

In the session 2, we have opened another transaction and inserted two records through single insert statement to the heap table. You can map these operations to row number 3,4, and 5 in the transaction log output. Third row represent the Begin tran command. Even if we inserted two records in single insert statement , SQL server recorded two separate entry in the transaction log.

As a next step, in session 1 we have added 1 record to the clustered index table.We can map this operation to the 6th record in the transaction log output.

In the next statement , we have modified a record in heap table through Session 2. You can map this to the 7th record in the transaction log output.If you look into the previous LSN column , it will be current LSN column value of the last record associated with this transaction.

In the same way, as a next statement we have modified a record in the clustered table through session 1. We can map the 8th and 9th records in the transaction log output to the update operation on the clustered table. You might have noticed that, when we modified a record in the heap table, transaction log recorded operation in a single row. Where as the same operation in a clustered table has two record in the transaction log. One for delete and other one for insert. When you modify the clustered index key, SQL server internally delete the existing record and insert a new record. This is because, the record need to be stored in the new location based on the modified value(based on the order of clustered index column). The easiest way for SQL server to achieve this is , delete the existing record and insert it as new records with modified clustered column value.

In the next two statement, we are deleting one record from heap table and clustered table.This can be mapped to the 10th and 11th records in the output.Finally we have issued the commit statement in both sessions.12th and 13th record in the transaction log output can be mapped to the commit operation.The Previous LSN column refer the Current LSN column of corresponding  begin tran statement. It will also capture the transaction end time in the End time column.

Understanding the VLF(Virtual Log File)

A database can have one or more log file. In general there will be only one log file as there is no performance improvement by having multiple log file. SQL server uses the transaction log in sequential manner.As the data file divided into pages,log files are divided into virtual log file(VLF).The size of the VLFs  in a log file may not be in equal size. SQL server decide the size and number of VLF in a log file based on the size of the log file growth as given below.

Growth upto 64 MB          = 4  VLF

From 64 MB to 1 GB       = 8   VLF

Larger than 1 GB             = 16 VLF

Let us create a database with 64 MB initial log size and later increase it to 1 GB. As per above calculation the log file should have 12 VLFs.  4 VLF based on initial size and 8 VLF due to changing the log size to 1 GB.

USE MASTER;
GO
CREATE DATABASE Mydb
ON 
(      NAME = MyDb_dat,  FILENAME = 'D:\MyDb\Mydb.mdf',
       SIZE = 10MB, MAXSIZE = 3072MB,   FILEGROWTH = 5MB )

LOG ON ( NAME = MyDb_log,FILENAME = 'D:\MyDb\MyDB.ldf',
    SIZE = 64MB, MAXSIZE = 2048MB, FILEGROWTH = 5MB ) ;
GO

ALTER DATABASE Mydb 
MODIFY FILE ( NAME = MyDb_Log,FILENAME = 'D:\MyDb\MyDB.ldf',    SIZE = 1024MB)

Now Let us see how many VLF got created. To find out the number of VLF in database log file, we can make use of DBCC Loginfo.

DBCC loginfo('mydb')

The output is given below.















There are 12  records in the output each represent a VLF.Let us try to understand the result

FileId: This is the file id of the log file and will be same for all 12 records as we have only one log file.If we have multiple log file , we can multiple numbers here

FileSize: This is the size of the VLF. If you look into the first four, have same size except the fourth one. This because first 8KB of the log file is used for file header. If you add filesize value of first four records along with 8192(8KB) , you will get 64MB which is the initial size of the log file.

16711680+16711680+16711680+16965632 =67100672+8192 =67108864bytes =64MB

In the same if you add the last 8 records it will account the 960 MB (1024-64) , the growth happened due to the alter statement.

StartOffSet: This values is also in bytes, and is the sort column of the output. The first VLF alwasy start from 8192, which is the number of bytes in a page.As mentioned above, the first 8KB is used for file header and will not store any log.

FSeqNo: The file sequence number indicates the order of usage of the VLFs. The row with the highest FSeqNo value is the VLF where current log records are being written.FSeqNo values are not consistent. It will keep changing each time when VLF are getting reused. We will discuss more about this later in this post. A value of 0 in this column means that this VLF has never been used at all. That is the reason we have 0 for all records except one where it is currently logging.

Status: Status has two possible values : 0 and 2. A value of 2 means the VLF is not reusable and a value 0 means it can be reused.It will be more clear as we go further.

Parity: Parity has three possible values 0 ,64 and 128. If the VLF is not used yet, it will have a value 0 and will be set to 64 on first use.Every time a VLF is reused, the parity value is switched between 64 and 128.

CreateLSN: The value indicates when the VLF is created or to group the VLF based on the creation. A values 0 indicates, those VLFs are created as part of database creation. In our case first four records has a value 0 which indicate these VLFs are created as part of database creation with 64MB log size. The remaining 8 records has the same value. These VLF are created as part of our alter database statement to increase the size of the log file from 64 MB to 1024MB

The above output description is referred from Kalen Delaney Blog Post

Now our transaction log will looks like below

Now we have learned about the LSN and VLF. we will discuss more about transaction log in the next post.