T-SQL Tuesday #31: Paradox of the Sawtooth Log

merrillaldrich — Tue, 12 Jun 2012 07:10:29 GMT

Today’s T-SQL Tuesday, hosted by Aaron Nelson (@sqlvariant | sqlvariant.com) has the theme Logging. I was a little pressed for time today to pull this post together, so this will be short and sweet. For a long time, I wondered why and how a database in Full Recovery Mode, which you’d expect to have an ever-growing log -- as all changes are written to the log file -- could in fact have a log usage pattern that looks like this:

This graph shows the Percent Log Used (bold, red) and the Log File(s) Used Size KB (light, green) counters for a demo database. The database was in Full Recovery mode the whole time this graph was generated, and there were no log backups taken. It seems, naively, that the graph should just climb ever upward as changes are added. How could it possibly drop and then start to climb again? Mysterious.

>> If I had time and wit, this is where I would do some clever Scooby Doo or Nancy Drew thing. Not tonight, I’m afraid. <<

I learned the answer in an amazing session with SQL Skills, during their IE1 class. The answer is that the amount of space counted as “used” in the log includes the log records physically present in the log file and in use (for full recovery, mirroring, replication, etc.) plus the amount of space that would be required to add rollback records, which do not actually exist, for all inflight transactions.

When you make a change to a database, the change is recorded first, obviously, as a series of transaction log records that can be played forward. In the event of a crash, when recovery runs, those records are replayed forward to recreate the changes, as one stage of the recovery process. But if a transaction is incomplete, somehow the instructions need to be present to undo and reverse out the changes made in that transaction. The way that works is that at the time of rollback, the reverse operations from the original log records are added to the log, then those reversal records are also played forward, which “undoes” all the changes. The reversal records do not exist, though, unless a rollback is actually invoked.

If the server ran out of space in the log file to append these rollback records, obviously there would be a major problem, and we might not be able to recover the database. In order to prevent that condition, SQL Server will reserve the space necessary in the log file(s) and have it appear “used” until a given transaction commits, at which point the crash recovery space for these hypothetical reversal records is no longer a requirement.

Here’s a demo script if you want to see this in action. Note that it takes a fair amount of disk space:

USE master ;
GO

-- Make a demo database:

CREATE DATABASE LogDemo ;
GO

ALTER DATABASE LogDemo SET RECOVERY FULL ;
GO

ALTER DATABASE LogDemo 
     MODIFY FILE ( NAME = N'LogDemo', SIZE = 2000MB , FILEGROWTH = 0)
ALTER DATABASE LogDemo 
     MODIFY FILE ( NAME = N'LogDemo_log', SIZE = 2000MB , FILEGROWTH = 0)
GO

USE LogDemo
GO

CREATE TABLE DummyData ( Padding char(800) ) ;
GO

-- Init full recovery mode by taking a full backup:

BACKUP DATABASE LogDemo TO DISK = 'LogDemo.BAK'
GO

-- At this point, start Performance Monitor, and add the counters
-- Percent Log Used and Log File(s) Size Used (KB) for the demo DB
-- Set the display scale of the latter to 0.00001 to match
-- the screenshot

-- Fill the test table with a generous amount of data:

DECLARE @i int = 1 ;

-- You can experiment with how much data by adjusting this
-- limit:

WHILE @i < 2 BEGIN

    BEGIN TRANSACTION ;

    WAITFOR DELAY '00:00:03' ;

    -- With each iteration of this loop, the log use will ramp up
    -- in the "intuitive" way we expect, growing after each insert:
    
    WITH  
        t1 AS ( SELECT REPLICATE( 'x', 800 ) AS Padding 
                UNION ALL SELECT REPLICATE( 'x', 800 ) AS Padding ),
        t2 AS ( SELECT x.Padding FROM t1 x CROSS JOIN t1 y ),
        t3 AS ( SELECT x.Padding FROM t2 x CROSS JOIN t2 y ),
        t4 AS ( SELECT x.Padding FROM t3 x CROSS JOIN t3 y )
        INSERT INTO DummyData ( Padding )
        SELECT x.Padding from t4 x CROSS JOIN t4 y ;
        
    COMMIT ;
    
    SET @i = @i + 1 ;
    
END ;
        
GO

CHECKPOINT ;

WAITFOR DELAY '00:00:05' ;

-- Here you can see the log usage for an index create:

CREATE CLUSTERED INDEX clust ON DummyData( Padding ) ;

CHECKPOINT ;

WAITFOR DELAY '00:00:05' ;

-- And this is where the "sawtooth" becomes visible:

BEGIN TRANSACTION ;

    UPDATE DummyData 
    SET Padding = REPLICATE( 'z', 800 ) ;

WAITFOR DELAY '00:00:02' ;

-- Log use drops here:

COMMIT ;

WAITFOR DELAY '00:00:02' ;

BEGIN TRANSACTION ;

    UPDATE DummyData 
    SET Padding = REPLICATE( 'z', 800 ) ;

WAITFOR DELAY '00:00:02' ;

-- Log use drops here:

COMMIT ;

WAITFOR DELAY '00:00:02' ;

BEGIN TRANSACTION ;

    UPDATE DummyData 
    SET Padding = REPLICATE( 'z', 800 ) ;

WAITFOR DELAY '00:00:02' ;

-- Log use drops here:

COMMIT ;

WAITFOR DELAY '00:00:02' ;

USE master ;
GO

DROP DATABASE LogDemo ;
GO

The best way to try this out is probably to highlight and execute a few lines at a time, and watch Performance Monitor to see if it does what you expect. Happy logging!

Search results matching tags 'log' and 'T-SQL Tuesday'

T-SQL Tuesday #31: Paradox of the Sawtooth Log