Sql-server – Why are virtual log files not always allocated in order

sql serversql-server-2012transaction-log

Quarterly I check the VLF on all of my servers through CMS with a query from the tigertoolbox/Fixing-VLFs/ on github. This includes suggestions (and code) for correcting what is found. I always try to get a full understanding of what is going before making any adjustments. 90% of the time the VLF solution I apply is not the same as the recommendation, though it is usually close.

Using DBCC LOGINFO I find that several of the VLFs are not used in sequential order. I am trying to understand why. This highly voted answer to; DBCC SHRINKFILE on log file not reducing size even after BACKUP LOG TO DISK
 says it can happen, but not why.

Because virtual log files are not always allocated in order,

This would seem to conflict with Jonathan Kehayias; An XEvent a Day (23 of 31) – How it Works – Multiple Transaction Log Files

We can see that of the 130 VLF only two (line 51 & 52) are currently used. The largest FSeqNo is 41808, subtract 130 = 41678. I don't see any FSeqNo lower then 41678 so presumably all have been used in the last 130 VLF rollovers.

IF we look at lines 108 – 109, we see line 110 is written to first, then line 109, then line 108. Also the parity is off (not sure what this adds to the scenario) The LSN show they are created in the opposite order.

enter image description here

I would expect that once whatever caused the disruption in sequence order has passed, the next time through the VLFs would be written to in order created. Why are they not?

Notice line 86 is in both images, to show consistency.
enter image description here

enter image description here

The example is from a SQL 2014 server, the database is currently in FUll recovery and has been for a year or more. The server has is part of 3 node AG, the results above are taken from the secondary server where the t-logs are backed up hourly. The last 10 grows occurred through auto grow of 1000MB (2014+ creates 1VLF). The log file currently has a Initial size of 115,000MB and autogrow of 1,000MB.

Edit
Max Vernon Thank you for the link in your answer. I understood how they got written out of order, but I am making an assumption that they continued to written out of order once the blocking event was cleared. By following FSegNo backwards you can recreate how it occured. Line 52 is the current VFL with FSeqNo 41808.. At line 35 the FSeqNo is 41791. The FSeqNo 41790 is at line 130 (last line). Presumably VFL 130 was created when FSeqNo 41790 was being written. BUT there have been 40,000 events of writing to the next VLF, with 130 VLF that would be more than 300 cycles through the log.

A couple of hours later the list looks this

enter image description here

Best Answer

Paul Randal details a scenario where log VLFs may be allocated out of the expected sequence in this blog post.

Essentially, log file growth may result in unexpected allocation order, even in simple mode, when the existing VLFs cannot be re-used.

Why are you wondering about the order-of-allocation? VLFs are used in FSeqNo order, both when writing new log records, and when performing rollback and rollforward recovery operations.

Having a database in Full Recovery model does not prevent out-of-order VLF allocation order. I've created a minimally complete verifiable example:

SET NOCOUNT ON;
USE master;
GO
IF EXISTS (SELECT 1 FROM sys.databases d WHERE d.name = N'TestVLFSeq')
BEGIN
    ALTER DATABASE TestVLFSeq SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
    DROP DATABASE TestVLFSeq;
END
GO
CREATE DATABASE TestVLFSeq
ON (NAME = 'system', FILENAME = 'C:\temp\TestVLFSeq.mdf', SIZE = 10MB, FILEGROWTH = 10MB, MAXSIZE = 100MB)
LOG ON (NAME = 'log', FILENAME = 'C:\temp\TestVLFSeq.ldf', SIZE = 1MB, FILEGROWTH = 1MB, MAXSIZE = 10MB);
GO

ALTER DATABASE TestVLFSeq SET RECOVERY FULL;
BACKUP DATABASE TestVLFSeq TO DISK = 'NUL:';
GO

SELECT d.name
    , d.recovery_model_desc
FROM sys.databases d
WHERE d.name = N'TestVLFSeq';
GO

output:

╔════════════╦═════════════════════╗
║    name    ║ recovery_model_desc ║
╠════════════╬═════════════════════╣
║ TestVLFSeq ║ FULL                ║
╚════════════╩═════════════════════╝

USE TestVLFSeq;
GO

CREATE TABLE dbo.TestData
(
    someVal varchar(8000) NOT NULL
        CONSTRAINT DF_TestData
        DEFAULT ((CRYPT_GEN_RANDOM(8000)))
);
GO

INSERT INTO dbo.TestData DEFAULT VALUES
 /* insert 64 rows - ~512 KB of log usage */
GO 64

DBCC LOGINFO
GO

output:

╔════════════════╦════════╦══════════╦═════════════╦════════╦════════╦════════╦═══════════╗
║ RecoveryUnitId ║ FileId ║ FileSize ║ StartOffset ║ FSeqNo ║ Status ║ Parity ║ CreateLSN ║
╠════════════════╬════════╬══════════╬═════════════╬════════╬════════╬════════╬═══════════╣
║              0 ║      2 ║   253952 ║        8192 ║     34 ║      2 ║     64 ║         0 ║
║              0 ║      2 ║   253952 ║      262144 ║     35 ║      2 ║     64 ║         0 ║
║              0 ║      2 ║   253952 ║      516096 ║     36 ║      2 ║     64 ║         0 ║
║              0 ║      2 ║   278528 ║      770048 ║      0 ║      0 ║      0 ║         0 ║
╚════════════════╩════════╩══════════╩═════════════╩════════╩════════╩════════╩═══════════╝

As you can see in the above output, we have 3 VLFs allocated.

Now, in a separate query window, run this to create log records that cannot be cleared, even by a log backup:

USE TestVLFSeq;
BEGIN TRANSACTION
INSERT INTO dbo.TestData DEFAULT VALUES
GO

Now, switch back to the first query window, and backup the database and the log to clear any VLFs that cleared:

BACKUP DATABASE TestVLFSeq TO DISK = 'NUL:' WITH INIT;
BACKUP LOG TestVLFSeq TO DISK = 'NUL:' WITH INIT;
GO

(The BACKUP DATABASE is not strictly required, but what the heck, we're backing up to "ether" anyway).

Now, when we check DBCC LOGINFO, we see:

╔════════════════╦════════╦══════════╦═════════════╦════════╦════════╦════════╦═══════════╗
║ RecoveryUnitId ║ FileId ║ FileSize ║ StartOffset ║ FSeqNo ║ Status ║ Parity ║ CreateLSN ║
╠════════════════╬════════╬══════════╬═════════════╬════════╬════════╬════════╬═══════════╣
║              0 ║      2 ║   253952 ║        8192 ║     34 ║      0 ║     64 ║         0 ║
║              0 ║      2 ║   253952 ║      262144 ║     35 ║      0 ║     64 ║         0 ║
║              0 ║      2 ║   253952 ║      516096 ║     36 ║      2 ║     64 ║         0 ║
║              0 ║      2 ║   278528 ║      770048 ║      0 ║      0 ║      0 ║         0 ║
╚════════════════╩════════╩══════════╩═════════════╩════════╩════════╩════════╩═══════════╝

The first and second VLF have been cleared. If we now insert another 64 rows into the table, and look at DBCC LOGINFO:

INSERT INTO dbo.TestData DEFAULT VALUES
 /* insert 64 rows - ~512 KB of log usage */
GO 64

DBCC LOGINFO
GO

We see:

╔════════════════╦════════╦══════════╦═════════════╦════════╦════════╦════════╦═══════════════════╗
║ RecoveryUnitId ║ FileId ║ FileSize ║ StartOffset ║ FSeqNo ║ Status ║ Parity ║     CreateLSN     ║
╠════════════════╬════════╬══════════╬═════════════╬════════╬════════╬════════╬═══════════════════╣
║              0 ║      2 ║   253952 ║        8192 ║     38 ║      2 ║    128 ║                 0 ║
║              0 ║      2 ║   253952 ║      262144 ║     35 ║      0 ║     64 ║                 0 ║
║              0 ║      2 ║   253952 ║      516096 ║     36 ║      2 ║     64 ║                 0 ║
║              0 ║      2 ║   278528 ║      770048 ║     37 ║      2 ║     64 ║                 0 ║
║              0 ║      2 ║   253952 ║     1048576 ║     39 ║      2 ║     64 ║ 38000000039500007 ║
║              0 ║      2 ║   253952 ║     1302528 ║      0 ║      0 ║      0 ║ 38000000039500007 ║
║              0 ║      2 ║   253952 ║     1556480 ║      0 ║      0 ║      0 ║ 38000000039500007 ║
║              0 ║      2 ║   286720 ║     1810432 ║      0 ║      0 ║      0 ║ 38000000039500007 ║
╚════════════════╩════════╩══════════╩═════════════╩════════╩════════╩════════╩═══════════════════╝

Pretty clearly, we have VLFs that are "out of sequence". However, since SQL Server uses the FSeqNo to perform recovery-related operations, it doesn't matter that the VLFs are not physically "in order".

If, for some reason, you programmatically expect the VLFs to be in FSeqNo order, you could query DBCC LOGINFO; like this:

DECLARE @cmd nvarchar(max);
IF OBJECT_ID(N'tempdb..#loginfo', N'U') IS NOT NULL
DROP TABLE #loginfo;
CREATE TABLE #loginfo
(
    RecoveryUnitID int
    , FileID int
    , FileSize int
    , StartOffset bigint
    , FSeqNo int
    , [Status] tinyint
    , Parity tinyint
    , CreateLSN bigint
);
SET @cmd = 'DBCC LOGINFO;';
INSERT INTO #loginfo
EXEC sys.sp_executesql @cmd;
SELECT *
FROM #loginfo li
ORDER BY /* put "0" FSeqNo rows at the end */
    CASE 
        WHEN li.FSeqNo = 0 THEN CONVERT(int, POWER(CONVERT(bigint,2),31) - 1) 
        ELSE li.FSeqNo 
    END;

Which has the following output for the "strange" VLF arrangement:

╔════════════════╦════════╦══════════╦═════════════╦════════╦════════╦════════╦═══════════════════╗
║ RecoveryUnitID ║ FileID ║ FileSize ║ StartOffset ║ FSeqNo ║ Status ║ Parity ║     CreateLSN     ║
╠════════════════╬════════╬══════════╬═════════════╬════════╬════════╬════════╬═══════════════════╣
║              0 ║      2 ║   253952 ║      262144 ║     35 ║      0 ║     64 ║                 0 ║
║              0 ║      2 ║   253952 ║      516096 ║     36 ║      2 ║     64 ║                 0 ║
║              0 ║      2 ║   278528 ║      770048 ║     37 ║      2 ║     64 ║                 0 ║
║              0 ║      2 ║   253952 ║        8192 ║     38 ║      2 ║    128 ║                 0 ║
║              0 ║      2 ║   253952 ║     1048576 ║     39 ║      2 ║     64 ║ 38000000039500007 ║
║              0 ║      2 ║   253952 ║     1302528 ║      0 ║      0 ║      0 ║ 38000000039500007 ║
║              0 ║      2 ║   253952 ║     1556480 ║      0 ║      0 ║      0 ║ 38000000039500007 ║
║              0 ║      2 ║   286720 ║     1810432 ║      0 ║      0 ║      0 ║ 38000000039500007 ║
╚════════════════╩════════╩══════════╩═════════════╩════════╩════════╩════════╩═══════════════════╝

VLFs marked with a Status of "2" indicates the VLF cannot be re-used. You can determine what is preventing log re-use using the following query:

SELECT d.name
    , d.recovery_model_desc
    , d.log_reuse_wait_desc
FROM sys.databases d
WHERE d.name = N'TestVLFSeq';

If you run this code while there is an open transaction in the database, as in the example above, you'll see the output looks like:

╔════════════╦═════════════════════╦═════════════════════╗
║    name    ║ recovery_model_desc ║ log_reuse_wait_desc ║
╠════════════╬═════════════════════╬═════════════════════╣
║ TestVLFSeq ║ FULL                ║ ACTIVE_TRANSACTION  ║
╚════════════╩═════════════════════╩═════════════════════╝

The log_reuse_wait_desc column can have the following possible values, taken from the Microsoft Transaction Log Documentation:

  1. CHECKPOINT - No checkpoint has occurred since the last log truncation, or the head of the log has not yet moved beyond a virtual log file (VLF). Applies to all recovery models. Applies to SQL Server 2008 through SQL Server 2017.

    This is a routine reason for delaying log truncation.

    When a database has a memory-optimized data filegroup, you should expect to see the log_reuse_wait column indicate checkpoint or xtp_checkpoint.

    You can force a checkpoint using the CHECKPOINT T-SQL command within the context of the database in question.

  2. LOG_BACKUP - A log backup is required before the transaction log can be truncated. Applies to full or bulk-logged recovery models only. Applies to SQL Server 2008 through SQL Server 2017

    Run BACKUP LOG <database> TO ... to create a backup of the log.

  3. ACTIVE_BACKUP_OR_RESTORE - Applies to SQL Server 2008 through SQL Server 2017

    Use the following query to see what backups are currently running:

    SELECT d.name
    , der.command
    , der.start_time
    , der.percent_complete
FROM sys.dm_exec_requests der
    INNER JOIN sys.databases d ON der.database_id = d.database_id
WHERE der.command = N'BACKUP DATABASE'
    OR der.command = N'BACKUP LOG';

  4. ACTIVE_TRANSACTION - Applies to SQL Server 2008 through SQL Server 2017

    There is an open transaction that has not been committed or rolled-back. Note this open transaction may not be actively running - it may be poorly written code that opens a transaction then performs some long-running action at the client, finally committing the transaction much later.

    Consider the following:

    • A long-running transaction might exist at the start of the log backup. In this case, freeing the space might require another log backup. Note that long-running transactions prevent log truncation under all recovery models, including the simple recovery model, under which the transaction log is generally truncated on each automatic checkpoint.

    • A transaction is deferred. A deferred transaction is effectively an active transaction whose rollback is blocked because of some unavailable resource. For information about the causes of deferred transactions and how to move them out of the deferred state, see Deferred Transactions.

    • Long-running transactions might also fill up tempdb's transaction log. Tempdb is used implicitly by user transactions for internal objects such as work tables for sorting, work files for hashing, cursor work tables, and row versioning. Even if the user transaction includes only reading data (SELECT queries), internal objects may be created and used under user transactions. Then the tempdb transaction log can be filled.

  5. DATABASE_MIRRORING - Database mirroring is paused, or under high-performance mode, the mirror database is significantly behind the principal database. Applies to full recovery model only. Applies to SQL Server 2008 through SQL Server 2017

    If you see a large number of VLFs with Status = 2, and database mirroring is enabled, ensure database transactions are being applied to the mirror in a timely fashion.

  6. REPLICATION - During transactional replication, publication-relevant-transactions have not been delivered to the distribution database. Applies to full recovery model only. Applies to SQL Server 2008 through SQL Server 2017.

  7. DATABASE_SNAPSHOT_CREATION - Applies to SQL Server 2008 through SQL Server 2017

    A database snapshot is being created. Check the following for details on snapshots that exist on your SQL Server:

    SELECT SnapshotDBName = d.name
    , SnapshotCreateDate = d.create_date
    , SourceDBName = d_source.name
    , SourceCreateDate = d_source.create_date
FROM sys.databases d
    INNER JOIN sys.databases d_source ON d.source_database_id = d_source.database_id
WHERE d.source_database_id IS NOT NULL
ORDER BY d.create_date;

  8. LOG_SCAN - This is a routine, and typically brief, cause of delayed log truncation.

  9. AVAILABILITY_REPLICA - An Always On Availability Groups secondary replica is applying transaction log records of this database to a corresponding secondary database. Applies to SQL Server 2012 through SQL Server 2017.

  10. OLDEST_PAGE - Applies to SQL Server 2012 through SQL Server 2017

    If a database is configured to use indirect checkpoints, the oldest page on the database might be older than the checkpoint log sequence number (LSN). In this case, the oldest page can delay log truncation. (All recovery models)

    For information about indirect checkpoints, see Database Checkpoints (SQL Server).

  11. OTHER_TRANSIENT - This value is currently not used. Applies to SQL Server 2012 through SQL Server 2017

  12. XTP_CHECKPOINT - When a database uses a recovery model and has a memory-optimized data filegroup, you should expect to see the log_reuse_wait column indicate checkpoint or xtp_checkpoint. - Applies to SQL Server 2014 through SQL Server 2017

Related Question