Investigating CHECKPOINT

Investigating CHECKPOINT (Transact-SQL)

Writes all dirty pages for the current database to disk. Dirty pages are data pages that have been entered into the buffer cache and modified, but not yet written to disk. Checkpoints save time during a later recovery by creating a point at which all dirty pages are guaranteed to have been written to disk.

Well it is time to have a look at what exactly happens when a CHECKPOINT command occurs. If you have a quick read of the Microsoft article you can see that CHECKPOINTs happen for a variety of reasons, however in this post I will issue them directly via t-sql.

What you will need:

1. A SQL Server Installation 2005 or later preferably in a dev/test environment.
2. Process Monitor
3. A Calculator (Optional) – …But most will fire up calc
4. A Beverage… Tea, Coffee

Firstly we are going to need a new database to play with so lets start by creating one called test.

CREATE DATABASE [test]
GO
USE [test]
GO
CREATE TABLE [tbl] ([id] INT PRIMARY KEY IDENTITY(1,1))
GO

We will keep it nice and simple by starting with a CHECKPOINT so that there is a small active transaction log to look at.

CHECKPOINT
SELECT * FROM fn_dblog(NULL,NULL)

This will give an active log which should look something like this:

Current LSN Operation Context
00000017:0000003c:009b LOP_BEGIN_CKPT LCX_NULL
00000017:0000007b:0001 LOP_END_CKPT LCX_NULL

Obviously your LSN will vary.

B. Setup Process Monitor

Next we want to use Process Monitor to see what IO is occuring. This can be done by setting up a filter on the mdf file for our test database.

ProcessMonitorFilter

After issuing a CHECKPOINT command in SSMS you should see a corresponding entry in Process Monitor.

CHECKPOINT

In fact it will look like this:

Offset: 73,728
 Length: 8,192
 I/O Flags: Non-cached, Write Through
 Priority: Normal

The reason it will look like this is because there are no dirty pages as we have already flushed everything to disk with the previous CHECKPOINT.

Converting the Offset value into a Page number 73728 / 8192 we get Page 9. A page is 8192 bytes in SQL Server so the math is easy, well as long as you can divide by 8192 in your head. (sip beverage)

Page 9???

This is a very important page! Page 9 is in fact the boot page and it is always in the same place at offset 73728 in the first file of the primary filegroup. I know this because after realising it was Page 9 I found Paul Randall’s blog entry 🙂

There are two ways that we can look inside this Page

DBCC DBINFO WITH TABLERESULTS

DBCC PAGE ('Test',1,9,3) WITH TABLERESULTS
--http://blogs.msdn.com/b/sqlserverstorageengine/archive/2006/06/10/625659.aspx

If we root round and pull out the CHECKPOINT information:

dbi_checkptLSN m_fSeqNo 23
dbi_checkptLSN m_blockOffset 124
dbi_checkptLSN m_slotId 1

In these fields we can see it is recording the last CHECKPOINT position in the log.

Using the undocumented fn_dblog again we can see if this is correct.

SELECT * FROM fn_dblog(NULL,NULL)

Current LSN Operation
00000017:0000007c:0001 LOP_BEGIN_CKPT
00000017:0000007d:0001 LOP_END_CKPT

More calculations I am afraid! Convert hex parts 00000017:0000007c:0001 to int… definately beverage sipping time. Put Windows Calc into programmer mode… type in the hex, and change to dec…easy.

or you could do it yourself:

00000017 -> 23
0000007C -> 124
0001 -> 1

Now that you have gone to the trouble of doing it with a calculator… here is a script:

SELECT xx.*
,[Current LSN]
,CAST([Checkpoint Begin] AS DATETIME) [Checkpoint Begin]
,CAST([Checkpoint End] AS DATETIME) [Checkpoint End]
,[Dirty Pages] [DirtyPages],*
FROM fn_dblog(NULL,NULL)
CROSS APPLY
(
SELECT
CAST(CAST(CAST('' AS XML).value('xs:hexBinary(sql:column("x.v1"))', 'VARBINARY(MAX)') AS INT) AS VARCHAR(MAX))+':'+
CAST(CAST(CAST('' AS XML).value('xs:hexBinary(sql:column("x.v2"))', 'VARBINARY(MAX)') AS INT) AS VARCHAR(MAX))+':'+
CAST(CAST(CAST('' AS XML).value('xs:hexBinary(sql:column("x.v3"))', 'VARBINARY(MAX)') AS INT) AS VARCHAR(MAX)) [LogSequenceNumber]
FROM
(
SELECT
CAST(SUBSTRING([Current LSN],0,9) AS VARCHAR(MAX))  AS v1
,CAST(SUBSTRING([Current LSN],10,8) AS VARCHAR(MAX)) AS v2
,CAST(SUBSTRING([Current LSN],19,4) AS VARCHAR(MAX)) AS v3
) x
)xx
WHERE [Operation] IN ('LOP_BEGIN_CKPT','LOP_END_CKPT')

LogSequenceNumber Current LSN Checkpoint Begin Checkpoint End DirtyPages
23:124:1 00000017:0000007c:0001 2011-08-11 00:00:00.000 NULL NULL
23:125:1 00000017:0000007d:0001 NULL 2011-08-11 00:00:00.000 0

Lets now do an insert so that we have some dirty pages

INSERT INTO tbl DEFAULT VALUES;

Now verify that there are some dirty pages.

SELECT
	 [DatabaseName]
,[0] [CleanCachePages]
,[1] [DirtyCachePages]
,[TotalCachePages]
,CONVERT(DECIMAL (15,3),[0]*CONVERT(FLOAT,8)/1024) [CleanCache_MiB]
,CONVERT(DECIMAL (15,3),[1]*CONVERT(FLOAT,8)/1024) [DirtyCache_MiB]
,CONVERT(DECIMAL (15,3),[TotalCachePages]*CONVERT(FLOAT,8)/1024) [TotalCache_MiB]
FROM
(
	SELECT
	CASE dobd.[database_id] WHEN 32767 THEN 'ResourceDB' ELSE DB_NAME(dobd.[database_id]) END AS [DatabaseName]
	,COUNT_BIG(*) [CachePages]
	,SUM(COUNT_BIG(*))
	 OVER (PARTITION BY dobd.[database_id]) [TotalCachePages]
	,[is_modified]
	FROM sys.dm_os_buffer_descriptors dobd
	GROUP BY dobd.[database_id],DB_NAME(dobd.[database_id]),[is_modified]
) s
PIVOT (SUM([CachePages]) FOR [is_modified] IN ([0],[1])) p
WHERE [DatabaseName] = DB_NAME()
GO
SELECT *
FROM sys.dm_os_buffer_descriptors dobd
WHERE dobd.[database_id] = DB_ID()
AND [is_modified] = 1

page_id page_type
78 IAM_PAGE
130 DATA_PAGE
1 PFS_PAGE
77 DATA_PAGE
3 SGAM_PAGE

So 5 dirty pages. CLEAR the Process Monitor window and then call another checkpoint.

CHECKPOINT

Checking the log:

SELECT [Dirty Pages],* FROM fn_dblog(NULL,NULL) WHERE [Operation] IN ('LOP_BEGIN_CKPT','LOP_END_CKPT')

It has written 8 dirty pages according to the log. In Process Monitor I can see it has written 9 pages, with one of them being an update at Offset 73728 which is our boot page 9. (Note Process Monitor might show IOs which are multiple pages e.g 16384 = 2)

ProcessMonitorCheckPointIO

Calc time again…

1064960/8192 = Page 130
696320/8192 = Page 85
417792/8192 = Page 51
24576/8192 = Page 3
630784/8192 = Page 77 + Page 78 (Length is 16384 so 2 pages)
147456/8192 = Page 18
8192/8192 = Page 1
73728/8192 = Page 9

So we expected 5 dirty pages to be written, but we got a few extra. We know that Page 9 is the boot page so that is merely updating the latest checkpoint location. So what are pages 18,51 and 85?

DBCC PAGE ('Test',1,18,3) WITH TABLERESULTS --Metadata: ObjectId 5 sys.sysrowsets
DBCC PAGE ('Test',1,51,3) WITH TABLERESULTS --Metadata: ObjectId 3 sys.sysrscols
DBCC PAGE ('Test',1,85,3) WITH TABLERESULTS --Metadata: ObjectId 41 sys.syscolpars

Looking for the Metadata: ObjectId I can see 5,3 and 41 respectively. Checking the objectid in the sys.all_objects table:

sys.sysrowsets
sys.sysrscols
sys.syscolpars

So these are system tables and they will be tracking information about our inserted row.

CLEAR the Process Monitor window, insert another row and then run another checkpoint.

This time less pages are written because we do not need to change some of the allocation tracking pages. e.g. 78 IAM_PAGE,1 PFS_PAGE,3 SGAM_PAGE

9 Boot Page
18 sys.sysrowsets
51 sys.sysrscols
77 DATA_PAGE
85 sys.syscolpars
130 DATA_PAGE

As more data is added; so more pages will need to be allocated, as well as this we may also see updates to the allocation tracking pages, but for now I think that is enough.

WAIT! I have changed my mind… I will finish with a question (better than a song and dance…maybe).

Q. If you insert a row into a table in an explicit transaction and then roll it back are the pages affected marked as clean or dirty in the cache? and what will happen if a CHECKPOINT is issued?

Leave a Reply