Why are virtual log files not always allocated in order?
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:
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
CHECKPOINTT-SQL command within the context of the database in question.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 2017Run
BACKUP LOG <database> TO ...to create a backup of the log.ACTIVE_BACKUP_OR_RESTORE- Applies to SQL Server 2008 through SQL Server 2017Use 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';ACTIVE_TRANSACTION- Applies to SQL Server 2008 through SQL Server 2017There 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.
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 2017If 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.
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.DATABASE_SNAPSHOT_CREATION- Applies to SQL Server 2008 through SQL Server 2017A 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;LOG_SCAN- This is a routine, and typically brief, cause of delayed log truncation.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.OLDEST_PAGE- Applies to SQL Server 2012 through SQL Server 2017If 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).
OTHER_TRANSIENT- This value is currently not used. Applies to SQL Server 2012 through SQL Server 2017XTP_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
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.
- PreGrow the logs (use backup history to estimate required space)
- Backup more frequently
- 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.