Why are virtual log files not always allocated in order?

Question

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.

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.

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

Answer 1

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

Answer 2

There is 115GB log file, with hourly backups. The VLF are all approximately 1GB and autogrowth set to create one new VLF of 1GB at each grow event. 2014 instance with a grow of less then 1/8 current size

After extensive searching and some testing, I find that log files always write sequentially (line 1,2,3,etc) EXCEPT when the next next VLF is still Status 2. The next write will occur on either the next available Status 0 VLF, or if there are none an autogrow will occur.

With Hourly t-log backups and out of order FSeqNo it means there were recently VLF remaining at Status 2 after the t-log backup ran (long running incomplete) With the order noticed at line 108,109 & 110 it is possible some VLF where not released through 2 backups.

Check the backups size on msdb..backupset to get more information, as this is an AG backing up on the secondary, run the following on the secondary server.

    --Find how big were the logs when backed up.  
    SELECT database_name
    , CONVERT(varchar, CAST ((backup_size/1024/1024) AS MONEY), 1) as 'BackUpSizeMB'
    , user_name as 'BackUpBy'
    , backup_start_date
    , backup_finish_date
    , recovery_model
    , CONVERT(varchar, CAST ((compressed_backup_size/1024/1024) AS MONEY), 1) as 'compressed_backup_sizeMB'
    FROM msdb..backupset
    WHERE backup_finish_date > DATEADD(MONTH, -12, CURRENT_TIMESTAMP) -- If want month(s)
    --WHERE backup_finish_date > DATEADD(DAY, -1, CURRENT_TIMESTAMP)  -- or only day(s)
    And type = 'L' --Log
    and database_name = 'MyDB'
    order by backup_start_date desc
    --order by backup_size desc

    /*
    Backup type. Can be:
    D = Database
    I = Differential database
    L = Log
    F = File or filegroup
    G = Differential file
    P = Partial
    Q = Differential partial
    Can be NULL.
    */

You will probably find something like this

There are recurring backups of around 100GB with fairly large backups on either side. In my instance I found that most t-log backups outside of these large events where about 500MB. Something runs for maybe 2 hours, and holds lots of VLF across backups. Then activity falls very low, and only a single VLF is cleared and the next taken. With configuration in the question it would take several days of low usage to return the expect straight forward sequence you might expect to find.

Next you will want check for auto growth, Kendra has a blog post that shows how to check This only works if there were recent events but you might find something like this.

There are several blog posts suggesting that "Optimal" VLF configuration is not more than 50 VLF at not more than 500MB (or 512) each. Obviously that only works for logs upto about 25GB.

In the scenario from the question. Each VLF is 1GB and there are hourly backups, additional the out of order FSeqNo indicate several VLF are locked at the time of backup. In the history shown in this answer (posted by OP from same database and instance in question) there is a 10GB auto grow in the minute before a 83GB t-log backup completed.

Optimally you don't want auto grows to occur, these only happen when the system is already strained. To address this you want to have sufficient space to meet recurring events, with anticipated pre-grows occurring off peak.

There are three options.

1. PreGrow the logs (use backup history to estimate required space)
2. Backup more frequently
3. Create more smaller VLF using the same total log file space.

The option needs to be selected, considering the entire system configuration in your environment, there is no single right choice.

TL:DR Even with hourly backups, there is something locking VLFs from being reused. This may indicate strain in your current configuration. I recommend you identify the issue, decide if it is a recurring event and address appropriately.