Thursday, May 30, 2013

SQL Server: Storage internals, recovery model and log behavior

This is not a comprehensive post on SQL Server storage and internals, but we recently ran into an interesting issue. We were doing PCI scans on some of our servers for PCI compliance. There is a tool that scans each bit and byte inside the database and server and return a list of possible violations. Our developers identified data that needs to be removed in some legacy systems and they cleaned up the data by updating offending fields with blank values, deleting some tables altogether etc. But the scan tool would often find violations even after truncating/deleting data. Some of those databases were on simple and some were in FULL recovery mode and I had to explain how log backups, recovery and checkpoint affect the databases and I came up with this small tutorial.

Lets create a database to play with. Lets set that database in FULL recovery mode and create some data and see whats in the log.
CREATE DATABASE storagefun;
GO

ALTER DATABASE storagefun SET RECOVERY FULL
GO

A database with no data in it is no good. Lets create a table and see. I am going to define DEFAULTS just to save some time and effort while inserting records into that table. I'm just lazy:

USE storagefun
GO
 
CREATE TABLE CreditInfo 
(
id int identity,
name nvarchar(30) DEFAULT 'SQL Server is fun!',
ccnumber nvarchar(40) DEFAULT '1234-4567-7891-1023'
)

A full backup initiates an LSN chain, so lets do a FULL backup.
BACKUP DATABASE storagefun TO DISK = 'D:\SQLData\Backups\Storagefun.bak'

Lets check and try to find more details about our transaction log. There is a very useful DBCC command, LOGINFO which allows us to do that. Here is Paul Randal demonstrating the circular nature of the log using DBCC LOGINFO.

DBCC LOGINFO
GO

You should see some thing similar to the below image.



So there are a couple of VLFs (Virtual Log Files) and on one of them, the status is 2, which means 'Active'. Can we find more information? What is in those log files? Yes we can, using the undocumented function fn_dblog

SELECT
 [Previous LSN] ,
 [Current LSN] ,
 [Transaction ID] ,
 [Operation],
 [CONTEXT],
 [AllocUnitName] ,
 [Page ID],
 [Slot ID],
 [Offset in Row] ,
 [Transaction Name] ,
 [Begin Time],
 [End Time],
 [Number of Locks] ,
 [Lock Information] ,
 [RowLog Contents 0] ,
 [RowLog Contents 1] ,
 [RowLog Contents 2] ,
 [RowLog Contents 3] ,
 [RowLog Contents 4] ,
 [Log Record],
 [Log Record Fixed Length] ,
 [Log Record Length]
FROM fn_dblog (null,null)
GO

This will return a lot of data which may not make much sense to you at first. That's ok. We just created a table and there is no data in it. Let us insert some data and see how the log behaves.

INSERT INTO CreditInfo VALUES ( DEFAULT, DEFAULT);
GO 200

How does out VLF files look now?

DBCC LOGINFO
GO


Our VLF count has increased and now two VLFs are marked as Active. Let us insert some more records and see what happens to the log

INSERT INTO CreditInfo VALUES ( DEFAULT, DEFAULT);
GO 5000

DBCC LOGINFO
GO

Since we seem to have a lot of data, may be try and read the log and see if we can make sense of the output from fn_dlog function output. Lets use the query we used above, but only this time, we know we only ever dealt with the CreditInfo table. So lets narrow the scope of the results based on this.

SELECT
 [Previous LSN] ,
 [Current LSN] ,
 [Transaction ID] ,
 [Operation],
 [CONTEXT],
 [AllocUnitName] ,
 [Page ID],
 [Slot ID],
 [Offset in Row] ,
 [Transaction Name] ,
 [Begin Time],
 [End Time],
 [Number of Locks] ,
 [Lock Information] ,
 [RowLog Contents 0] ,
 [RowLog Contents 1] ,
 [RowLog Contents 2] ,
 [RowLog Contents 3] ,
 [RowLog Contents 4] ,
 [Log Record],
 [Log Record Fixed Length] ,
 [Log Record Length]
FROM fn_dblog (null,null)WHERE AllocUnitName LIKE '%CreditInfo%'

You'll notice the details of the operation we performed, LOP_INSERT_ROWS. So is that the actual data? Yes and no. Its not actual data in the sense of data in a data file. It is knowledge about what happened to that data for SQL Server's use. I had to demonstrate this to our devs because they were claiming that there is credit card info in the log files as per the scanning tool.



Coming back to log, observe how the log file grows and how most of the VLFs are in Active mode. This means they are currently being used and are not marked for reuse yet. We obviously dont want our log file to grow indefinitely. It needs to be cleared, right? So what clears a transaction log file when the database is in Full Recovery Mode? Two things- First, When a checkpoint has occurs since the last full backup AND a transaction log backup. Lets issue a manual CHECKPOINT and do a log backup and see what happens to our log.

CHECKPOINT
GO

BACKUP LOG storagefun TO DISK = 'D:\SQLData\storagefun_log.trn'
GO

What happened? All the VLFs are still there, but the log backup has cleared the transaction log and the existing virtual log files are marked as inactive. So they can be used again for any transactions in future. Now, try to read the log again and limit your scope to CreditInfo table.

SELECT
 [Previous LSN] ,
 [Current LSN] ,
 [Transaction ID] ,
 [Operation],
 [CONTEXT],
 [AllocUnitName] ,
 [Page ID],
 [Slot ID],
 [Offset in Row] ,
 [Transaction Name] ,
 [Begin Time],
 [End Time],
 [Number of Locks] ,
 [Lock Information] ,
 [RowLog Contents 0] ,
 [RowLog Contents 1] ,
 [RowLog Contents 2] ,
 [RowLog Contents 3] ,
 [RowLog Contents 4] ,
 [Log Record],
 [Log Record Fixed Length] ,
 [Log Record Length]
FROM fn_dblog (null,null) WHERE AllocUnitName LIKE '%CreditInfo%'
GO

Boom! there is nothing related to CreditInfo object. Didn't I tell you that the log backup cleared the transaction log?

But you can see that data in the data file. Use a simple select.

Ok, this is credit card data and one internet kitten will die for each row you keep in your database. Its vile. So lets get rid of it. After you truncate the table, will you find any information about it in the log file? Yes, you will. You'll see LOP_MODIFY_ROW operation.

TRUNCATE TABLE CreditInfo;

SELECT
 [Previous LSN] ,
 [Current LSN] ,
 [Transaction ID] ,
 [Operation],
 [CONTEXT],
 [AllocUnitName] ,
 [Page ID],
 [Slot ID],
 [Offset in Row] ,
 [Transaction Name] ,
 [Begin Time],
 [End Time],
 [Number of Locks] ,
 [Lock Information] ,
 [RowLog Contents 0] ,
 [RowLog Contents 1] ,
 [RowLog Contents 2] ,
 [RowLog Contents 3] ,
 [RowLog Contents 4] ,
 [Log Record],
 [Log Record Fixed Length] ,
 [Log Record Length]
FROM fn_dblog (null,null) WHERE AllocUnitName LIKE '%CreditInfo%'

The credit card scan utility still sees the data, we just truncated the table and still. Ok, lets do a log backup.

BACKUP LOG storagefun TO DISK  = 'D:\SQLData\storagefun_lon1.trn'

Read the log again

SELECT
 [Previous LSN] ,
 [Current LSN] ,
 [Transaction ID] ,
 [Operation],
 [CONTEXT],
 [AllocUnitName] ,
 [Page ID],
 [Slot ID],
 [Offset in Row] ,
 [Transaction Name] ,
 [Begin Time],
 [End Time],
 [Number of Locks] ,
 [Lock Information] ,
 [RowLog Contents 0] ,
 [RowLog Contents 1] ,
 [RowLog Contents 2] ,
 [RowLog Contents 3] ,
 [RowLog Contents 4] ,
 [Log Record],
 [Log Record Fixed Length] ,
 [Log Record Length]
FROM fn_dblog (null,null) WHERE AllocUnitName LIKE '%CreditInfo%'

Still see the records? How about a checkpoint

CHECKPOINT
GO

At this point, if you try to read again, you wont see any records related to CreditInfo and its completely gone. I was able to explain about FULL Recovery mode, nature of log using this example to our devs and I hope you find it useful too.