patternsqlModerate
Why is CHECKDB reading the transaction log file on a database with a memory optimized table?
Viewed 0 times
whyreadingthefilelogwithoptimizeddatabasecheckdbtransaction
Problem
tl;dr: why is CHECKDB reading the transaction log for a user database with memory optimized tables?
It appears that CHECKDB is reading the transaction log file of the user database when it's checking on one of my databases - in particular, a database that uses in-memory OLTP tables.
CHECKDB for this database still finishes in a reasonable amount of time, so I'm mostly just curious about the behavior; but it's definitely the longest duration for CHECKDB of all the databases on this instance.
In looking over Paul Randal's epic "CHECKDB From Every Angle: Complete description of all CHECKDB stages," I see that pre-SQL 2005 CHECKDB used to read the log in order to get a consistent view of the database. But since this is 2016, it uses an internal database snapshot.
However, one of the prerequisites for snapshots is that:
The source database must not contain a MEMORY_OPTIMIZED_DATA filegroup
My user database has one of these filegroups, so it looks like snapshots are off the table.
According to the CHECKDB docs:
If a snapshot cannot be created, or TABLOCK is specified, DBCC CHECKDB acquires locks to obtain the required consistency. In this case, an exclusive database lock is required to perform the allocation checks, and shared table locks are required to perform the table checks.
Okay, so we're doing database and table locking instead of snapshots. But that still doesn't explain why it has to read the transaction log. So what gives?
I've provided a script below to reproduce the scenario. It uses
Note that most of the time it reads a small portion of the log (480 KB), but it occasionally reads much more (48.2 MB). In my production scenario, it reads most of the log file (~1.3 GB of the 2 GB file) every night at midnight when we run CHECKDB.
Here's an example of the outputs I've gotten so far with the script:
```
collection_time num_of_reads num_of_bytes_read
2018-04-04 15:12:29.
It appears that CHECKDB is reading the transaction log file of the user database when it's checking on one of my databases - in particular, a database that uses in-memory OLTP tables.
CHECKDB for this database still finishes in a reasonable amount of time, so I'm mostly just curious about the behavior; but it's definitely the longest duration for CHECKDB of all the databases on this instance.
In looking over Paul Randal's epic "CHECKDB From Every Angle: Complete description of all CHECKDB stages," I see that pre-SQL 2005 CHECKDB used to read the log in order to get a consistent view of the database. But since this is 2016, it uses an internal database snapshot.
However, one of the prerequisites for snapshots is that:
The source database must not contain a MEMORY_OPTIMIZED_DATA filegroup
My user database has one of these filegroups, so it looks like snapshots are off the table.
According to the CHECKDB docs:
If a snapshot cannot be created, or TABLOCK is specified, DBCC CHECKDB acquires locks to obtain the required consistency. In this case, an exclusive database lock is required to perform the allocation checks, and shared table locks are required to perform the table checks.
Okay, so we're doing database and table locking instead of snapshots. But that still doesn't explain why it has to read the transaction log. So what gives?
I've provided a script below to reproduce the scenario. It uses
sys.dm_io_virtual_file_stats to identify the log file reads.Note that most of the time it reads a small portion of the log (480 KB), but it occasionally reads much more (48.2 MB). In my production scenario, it reads most of the log file (~1.3 GB of the 2 GB file) every night at midnight when we run CHECKDB.
Here's an example of the outputs I've gotten so far with the script:
```
collection_time num_of_reads num_of_bytes_read
2018-04-04 15:12:29.
Solution
Even though the SQL Server documentation states that databases with "In-Memory" tables do not support snapshots, the "internal" snapshot required for
Presumably, Microsoft chose to prevent user-created snapshots on databases with In-Memory tables since they would need to duplicate the in-memory structures in order for the snapshot to really be a complete snapshot from the normal, user-centric, sense. Duplicating the in-memory tables for a snapshot could easily make the server run out of memory, which is not A Good Thing™
You can prove for yourself that an internal DBCC snapshot is being created by watching the data folder where the primary database datafile resides while running
Once the snapshot file has been created, it is necessary for SQL Server to run recovery on the database to bring it into a consistent state that is required for DBCC CHECKDB to run. Any log-reading action you're seeing is likely to be a result of that recovery process. I built a quick rig for checking the output of multiple
```
USE master;
SET IMPLICIT_TRANSACTIONS OFF;
USE [master];
IF (DB_ID(N'LogFileRead_Test') IS NOT NULL)
BEGIN
ALTER DATABASE [LogFileRead_Test]
SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
DROP DATABASE [LogFileRead_Test];
END
CREATE DATABASE [LogFileRead_Test]
ALTER DATABASE [LogFileRead_Test]
MODIFY FILE
(
NAME = LogFileRead_Test_log,
SIZE = 128MB
);
ALTER DATABASE [LogFileRead_Test]
ADD FILEGROUP [LatencyTestInMemoryFileGroup] CONTAINS MEMORY_OPTIMIZED_DATA;
ALTER DATABASE [LogFileRead_Test]
ADD FILE
(
NAME = [LatencyTestInMemoryFile],
FILENAME = 'C:\temp\LogFileRead_Test_SessionStateInMemoryFile'
) TO FILEGROUP [LatencyTestInMemoryFileGroup];
GO
USE LogFileRead_Test;
CREATE TABLE [dbo].[InMemoryStuff] (
[InMemoryId] NVARCHAR (88) COLLATE Latin1_General_100_BIN2 NOT NULL,
[Created] DATETIME2 (7) NOT NULL,
CONSTRAINT [PK_InMemoryStuff_InMemoryId]
PRIMARY KEY NONCLUSTERED
HASH ([InMemoryId]) WITH (BUCKET_COUNT = 240)
)
WITH (MEMORY_OPTIMIZED = ON);
;WITH src AS (
SELECT n.Num
FROM (VALUES (0), (1), (2), (3), (4), (5), (6), (7), (8), (9))n(Num)
)
INSERT INTO [dbo].[InMemoryStuff] (InMemoryId, Created)
SELECT 'Description' + CONVERT(varchar(30)
, ((s1.Num * 10000)
+ (s2.Num * 1000)
+ (s3.Num * 100)
+ (s4.Num * 10)
+ (s5.Num)))
, GETDATE()
FROM src s1
CROSS JOIN src s2
CROSS JOIN src s3
CROSS JOIN src s4
CROSS JOIN src s5;
USE master;
DECLARE @cmd nvarchar(max);
DECLARE @msg nvarchar(1000);
DECLARE @l int;
DECLARE @m int;
SET @m = 10;
SET @l = 1;
IF OBJECT_ID(N'tempdb..#vfs', N'U') IS NOT NULL DROP TABLE #vfs;
CREATE TABLE #vfs (
vfs_run int NOT NULL IDENTITY(1,1) PRIMARY KEY CLUSTERED
, collection_time datetime2(7)
, num_of_reads bigint
, num_of_bytes_read bigint
);
WHILE @l <= @m
BEGIN
SET @msg = N'loop ' + CONVERT(nvarchar(10), @l);
RAISERROR (@msg, 0, 1) WITH NOWAIT;
SET @cmd = 'USE [LogFileRead_Test];
-- grab a baseline of virtual file stats to be diff''d later
select f.num_of_reads, f.num_of_bytes_read
into #dm_io_virtual_file_stats
from sys.dm_io_virtual_file_stats(default, default) f
where database_id = db_id(''LogFileRead_Test'') and file_id = FILE_IDEX(''LogFileRead_Test_log'');
DBCC CHECKDB ([LogFileRead_Test]) WITH NO_INFOMSGS, ALL_ERRORMSGS, DATA_PURITY;
-- grab the latest virtual file stats, and compare with the previous capture
select f.num_of_reads, f.num_of_bytes_read
into #checkdb_stats
from sys.dm_io_virtual_file_stats(default, default) f
where database_id = db_id(''LogFileRead_Test'') and file_id = FILE_IDEX(''LogFileRead_Test_log'');
select
collection_time = GETDATE()
, num_of_reads = - f.num_of_reads + t.num_of_reads
, num_of_bytes_read = - f.num_of_bytes_read + t.num_of_bytes_read
into #dm_io_virtual_file_stats_diff
from #dm_io_virtual_file_stats f, #checkdb_stats t;
--drop table #checkdb_stats;
--drop table #dm_io_virtual_file_stats;
-- CHECKDB ignored my comment
select collection_time, num_of_reads, num_of_bytes_read
from #dm_io_virtual_file_stats_diff d
order by d.collection_time;
--drop table #dm_io_virtual_file_stats_diff;
';
INSERT INTO #vfs (collection_time, num_of_reads, num_of_bytes_read)
EXEC sys.sp_executesql @cmd;
SET @l += 1;
END
USE master;
SET @cmd = 'USE [master];
ALTER DATABASE [LogFileRead_Test]
SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
DROP DATABASE [LogFileRead_Test];
';
EXEC sys.sp_executesql @cmd;
SELECT *
FROM
DBCC CHECKDB can still be created since the checkdb operation does not touch in-memory tables, and the snapshot only captures changes to the on-disk tables.Presumably, Microsoft chose to prevent user-created snapshots on databases with In-Memory tables since they would need to duplicate the in-memory structures in order for the snapshot to really be a complete snapshot from the normal, user-centric, sense. Duplicating the in-memory tables for a snapshot could easily make the server run out of memory, which is not A Good Thing™
You can prove for yourself that an internal DBCC snapshot is being created by watching the data folder where the primary database datafile resides while running
DBCC CHECKDB. If an internal snapshot is created, you'll see a file named LogFileRead_Test.mdf_MSSQL_DBCC7 (the 7 may be different - it represents the database id for your database).Once the snapshot file has been created, it is necessary for SQL Server to run recovery on the database to bring it into a consistent state that is required for DBCC CHECKDB to run. Any log-reading action you're seeing is likely to be a result of that recovery process. I built a quick rig for checking the output of multiple
DBCC CHECKDB actions, which proves that if there are no transactions between checkdbs, there are no log-file reads.```
USE master;
SET IMPLICIT_TRANSACTIONS OFF;
USE [master];
IF (DB_ID(N'LogFileRead_Test') IS NOT NULL)
BEGIN
ALTER DATABASE [LogFileRead_Test]
SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
DROP DATABASE [LogFileRead_Test];
END
CREATE DATABASE [LogFileRead_Test]
ALTER DATABASE [LogFileRead_Test]
MODIFY FILE
(
NAME = LogFileRead_Test_log,
SIZE = 128MB
);
ALTER DATABASE [LogFileRead_Test]
ADD FILEGROUP [LatencyTestInMemoryFileGroup] CONTAINS MEMORY_OPTIMIZED_DATA;
ALTER DATABASE [LogFileRead_Test]
ADD FILE
(
NAME = [LatencyTestInMemoryFile],
FILENAME = 'C:\temp\LogFileRead_Test_SessionStateInMemoryFile'
) TO FILEGROUP [LatencyTestInMemoryFileGroup];
GO
USE LogFileRead_Test;
CREATE TABLE [dbo].[InMemoryStuff] (
[InMemoryId] NVARCHAR (88) COLLATE Latin1_General_100_BIN2 NOT NULL,
[Created] DATETIME2 (7) NOT NULL,
CONSTRAINT [PK_InMemoryStuff_InMemoryId]
PRIMARY KEY NONCLUSTERED
HASH ([InMemoryId]) WITH (BUCKET_COUNT = 240)
)
WITH (MEMORY_OPTIMIZED = ON);
;WITH src AS (
SELECT n.Num
FROM (VALUES (0), (1), (2), (3), (4), (5), (6), (7), (8), (9))n(Num)
)
INSERT INTO [dbo].[InMemoryStuff] (InMemoryId, Created)
SELECT 'Description' + CONVERT(varchar(30)
, ((s1.Num * 10000)
+ (s2.Num * 1000)
+ (s3.Num * 100)
+ (s4.Num * 10)
+ (s5.Num)))
, GETDATE()
FROM src s1
CROSS JOIN src s2
CROSS JOIN src s3
CROSS JOIN src s4
CROSS JOIN src s5;
USE master;
DECLARE @cmd nvarchar(max);
DECLARE @msg nvarchar(1000);
DECLARE @l int;
DECLARE @m int;
SET @m = 10;
SET @l = 1;
IF OBJECT_ID(N'tempdb..#vfs', N'U') IS NOT NULL DROP TABLE #vfs;
CREATE TABLE #vfs (
vfs_run int NOT NULL IDENTITY(1,1) PRIMARY KEY CLUSTERED
, collection_time datetime2(7)
, num_of_reads bigint
, num_of_bytes_read bigint
);
WHILE @l <= @m
BEGIN
SET @msg = N'loop ' + CONVERT(nvarchar(10), @l);
RAISERROR (@msg, 0, 1) WITH NOWAIT;
SET @cmd = 'USE [LogFileRead_Test];
-- grab a baseline of virtual file stats to be diff''d later
select f.num_of_reads, f.num_of_bytes_read
into #dm_io_virtual_file_stats
from sys.dm_io_virtual_file_stats(default, default) f
where database_id = db_id(''LogFileRead_Test'') and file_id = FILE_IDEX(''LogFileRead_Test_log'');
DBCC CHECKDB ([LogFileRead_Test]) WITH NO_INFOMSGS, ALL_ERRORMSGS, DATA_PURITY;
-- grab the latest virtual file stats, and compare with the previous capture
select f.num_of_reads, f.num_of_bytes_read
into #checkdb_stats
from sys.dm_io_virtual_file_stats(default, default) f
where database_id = db_id(''LogFileRead_Test'') and file_id = FILE_IDEX(''LogFileRead_Test_log'');
select
collection_time = GETDATE()
, num_of_reads = - f.num_of_reads + t.num_of_reads
, num_of_bytes_read = - f.num_of_bytes_read + t.num_of_bytes_read
into #dm_io_virtual_file_stats_diff
from #dm_io_virtual_file_stats f, #checkdb_stats t;
--drop table #checkdb_stats;
--drop table #dm_io_virtual_file_stats;
-- CHECKDB ignored my comment
select collection_time, num_of_reads, num_of_bytes_read
from #dm_io_virtual_file_stats_diff d
order by d.collection_time;
--drop table #dm_io_virtual_file_stats_diff;
';
INSERT INTO #vfs (collection_time, num_of_reads, num_of_bytes_read)
EXEC sys.sp_executesql @cmd;
SET @l += 1;
END
USE master;
SET @cmd = 'USE [master];
ALTER DATABASE [LogFileRead_Test]
SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
DROP DATABASE [LogFileRead_Test];
';
EXEC sys.sp_executesql @cmd;
SELECT *
FROM
Code Snippets
USE master;
SET IMPLICIT_TRANSACTIONS OFF;
USE [master];
IF (DB_ID(N'LogFileRead_Test') IS NOT NULL)
BEGIN
ALTER DATABASE [LogFileRead_Test]
SET SINGLE_USER WITH ROLLBACK IMMEDIATE;
DROP DATABASE [LogFileRead_Test];
END
CREATE DATABASE [LogFileRead_Test]
ALTER DATABASE [LogFileRead_Test]
MODIFY FILE
(
NAME = LogFileRead_Test_log,
SIZE = 128MB
);
ALTER DATABASE [LogFileRead_Test]
ADD FILEGROUP [LatencyTestInMemoryFileGroup] CONTAINS MEMORY_OPTIMIZED_DATA;
ALTER DATABASE [LogFileRead_Test]
ADD FILE
(
NAME = [LatencyTestInMemoryFile],
FILENAME = 'C:\temp\LogFileRead_Test_SessionStateInMemoryFile'
) TO FILEGROUP [LatencyTestInMemoryFileGroup];
GO
USE LogFileRead_Test;
CREATE TABLE [dbo].[InMemoryStuff] (
[InMemoryId] NVARCHAR (88) COLLATE Latin1_General_100_BIN2 NOT NULL,
[Created] DATETIME2 (7) NOT NULL,
CONSTRAINT [PK_InMemoryStuff_InMemoryId]
PRIMARY KEY NONCLUSTERED
HASH ([InMemoryId]) WITH (BUCKET_COUNT = 240)
)
WITH (MEMORY_OPTIMIZED = ON);
;WITH src AS (
SELECT n.Num
FROM (VALUES (0), (1), (2), (3), (4), (5), (6), (7), (8), (9))n(Num)
)
INSERT INTO [dbo].[InMemoryStuff] (InMemoryId, Created)
SELECT 'Description' + CONVERT(varchar(30)
, ((s1.Num * 10000)
+ (s2.Num * 1000)
+ (s3.Num * 100)
+ (s4.Num * 10)
+ (s5.Num)))
, GETDATE()
FROM src s1
CROSS JOIN src s2
CROSS JOIN src s3
CROSS JOIN src s4
CROSS JOIN src s5;
USE master;
DECLARE @cmd nvarchar(max);
DECLARE @msg nvarchar(1000);
DECLARE @l int;
DECLARE @m int;
SET @m = 10;
SET @l = 1;
IF OBJECT_ID(N'tempdb..#vfs', N'U') IS NOT NULL DROP TABLE #vfs;
CREATE TABLE #vfs (
vfs_run int NOT NULL IDENTITY(1,1) PRIMARY KEY CLUSTERED
, collection_time datetime2(7)
, num_of_reads bigint
, num_of_bytes_read bigint
);
WHILE @l <= @m
BEGIN
SET @msg = N'loop ' + CONVERT(nvarchar(10), @l);
RAISERROR (@msg, 0, 1) WITH NOWAIT;
SET @cmd = 'USE [LogFileRead_Test];
-- grab a baseline of virtual file stats to be diff''d later
select f.num_of_reads, f.num_of_bytes_read
into #dm_io_virtual_file_stats
from sys.dm_io_virtual_file_stats(default, default) f
where database_id = db_id(''LogFileRead_Test'') and file_id = FILE_IDEX(''LogFileRead_Test_log'');
DBCC CHECKDB ([LogFileRead_Test]) WITH NO_INFOMSGS, ALL_ERRORMSGS, DATA_PURITY;
-- grab the latest virtual file stats, and compare with the previous capture
select f.num_of_reads, f.num_of_bytes_read
into #checkdb_stats
from sys.dm_io_virtual_file_stats(default, default) f
where database_id = db_id(''LogFileRead_Test'') and file_id = FILE_IDEX(''LogFileRead_Test_log'');
select
collection_time = GETDATE()
, num_of_reads = - f.num_of_reads + t.num_of_reads
, num_of_bytes_read = - f.num_of_bytes_read + t.num_of_bytes_read
into #dm_io_virtual_file_stats_diff
from #dm_io_virtual_file_stats f, #checkdb_stats t;
--drop table #checkdb_stats;
--drop table #dm_io_virtual_file_stats;
-- ;WITH src AS (
SELECT n.Num
FROM (VALUES (0), (1), (2), (3), (4), (5), (6), (7), (8), (9))n(Num)
)
INSERT INTO [dbo].[InMemoryStuff] (InMemoryId, Created)
SELECT 'Description' + CONVERT(varchar(30)
, ((s1.Num * 10000)
+ (s2.Num * 1000)
+ (s3.Num * 100)
+ (s4.Num * 10)
+ (s5.Num)))
, GETDATE()
FROM src s1
CROSS JOIN src s2
CROSS JOIN src s3
CROSS JOIN src s4
CROSS JOIN src s5;Context
StackExchange Database Administrators Q#203063, answer score: 10
Revisions (0)
No revisions yet.