Как работают контрольные точки и что записывается в журнал транзакций

Автор: Paul Randal, How do checkpoints work and what gets logged

Давно собирался написать про это; к тому же недавно наткнулся в сети на несколько не вполне точных объяснений работы контрольных точек, поэтому хочу коротко описать, как они устроены с точки зрения журнальных записей.

Когда выполняется операция контрольной точки, неважно, чем она спровоцирована (ручной CHECKPOINT, резервной копией базы данных или дифференциальной, либо автоматически), происходит один и тот же набор действий:

• Все «грязные» страницы файлов данных базы записываются на диск (то есть все страницы, изменённые в памяти с момента чтения с диска или после последней контрольной точки), независимо от состояния транзакции, выполнившей изменение.
• Перед записью страницы данных на диск все журнальные записи вплоть до самой последней, описывающей изменение этой страницы, должны быть записаны на диск (да, журнальные записи тоже могут кэшироваться в памяти). Это гарантия корректной работы восстановления и называется принципом упреждающей записи (write‑ahead logging). Журнальные записи пишутся последовательно, и записи от нескольких транзакций перемешиваются в журнале. Нельзя записать в журнал «выборочно», поэтому запись на диск «грязной» страницы, на которую пришлась всего одна журнальная запись, может потребовать записи множества предыдущих журнальных записей тоже.
• Генерируются журнальные записи, описывающие контрольную точку.
• LSN контрольной точки записывается в загрузочную страницу базы (boot page) в поле dbi_checkptLSN (см. «Boot Page и их повреждения»).
• Если используется модель восстановления SIMPLE, проверяются VLF в журнале на предмет возможности пометки их как неактивных (это называют очисткой, truncation — оба термина неудачны, потому что физически ничего не «очищается» и не «обрезается»).

Я употребляю термины, с которыми вы могли не сталкиваться — в качестве вводного материала о журналировании, восстановлении и архитектуре журнала транзакций см. мою статью в TechNet Magazine (февраль 2009): «Ведение журнала и восстановление в SQL Server».

Контрольные точки как таковые в журнале транзакций особо не «журналируются» — журнал используется как удобное хранилище сведений о том, какие транзакции активны в момент контрольной точки. LSN последней контрольной точки записан в загрузочной странице базы — именно с неё начинается восстановление; если она недоступна, база не сможет быть подключена, открыта или обработана вообще никак — отчасти потому, что именно boot‑страница «знает», корректно ли завершалась база, отчасти потому, что только на ней хранится LSN последней записи контрольной точки. Можно сказать: «она ведь записана и в журнале» — но что, если журнал повреждён?

Одно из распространённых заблуждений — будто журнальные записи контрольной точки «перезаписываются» следующими контрольными точками. Абсолютно нет: будучи записанной, журнальная запись НИКОГДА не обновляется и не перезаписывается — она будет перезаписана только когда журнал «прокрутится» для повторного использования этого VLF (см. «Поговорим ещё о циклической природе журнала транзакций»). Отсюда возникает путаница, когда информация о контрольной точке доступна в журнале, если смотреть её через fn_dblog и подобные инструменты.

Далее я покажу, что происходит в журнале транзакций, когда контрольные точки выполняются при разных обстоятельствах.

[Правка: начиная с 2012 года добавляется ещё одна журнальная запись о обновлении загрузочной страницы.]

Рассмотрим пример:

CREATE DATABASE CheckpointTest;
GO
USE CheckpointTest;
GO
CREATE TABLE t1 (c1 INT);
GO
INSERT INTO t1 VALUES (1);
GO
CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- --------------------------------
00000047:00000051:009b  LOP_BEGIN_CKPT
00000047:00000091:0001  LOP_END_CKPT

Мы видим журнальные записи для контрольной точки. В данном случае она проста, поэтому всего две записи — начало и окончание.

Если запустить ещё одну контрольную точку, что увидим?

CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- --------------------------------
00000047:00000092:0001  LOP_BEGIN_CKPT
00000047:00000093:0001  LOP_END_CKPT

Снова информация только об одной контрольной точке, но с другими LSN. Это не значит, что предыдущая контрольная точка была «перезаписана» — просто мы сделали ещё одну контрольную точку, активная часть журнала сдвинулась вперёд, и журнальные записи предыдущей контрольной точки больше не считаются активными (они не нужны, например, для зеркального отображения базы, активной транзакции, резервной копии журнала, репликации транзакций). Они всё ещё находятся в журнале, но уже не относятся к необходимой его части, и поэтому fn_dblog их не выводит.

А что если я создам активную транзакцию? В другом подключении выполню:

USE CheckpointTest;
GO
BEGIN TRAN;
GO
INSERT INTO t1 VALUES (1);
GO

Теперь сделаем контрольную точку и посмотрим журнал:

CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- --------------------------------
00000047:00000094:0001  LOP_BEGIN_XACT
00000047:00000094:0002  LOP_INSERT_ROWS
00000047:00000094:0003  LOP_COUNT_DELTA
00000047:00000094:0004  LOP_COUNT_DELTA
00000047:00000094:0005  LOP_COUNT_DELTA
00000047:00000094:0006  LOP_BEGIN_CKPT
00000047:00000096:0001  LOP_XACT_CKPT
00000047:00000096:0002  LOP_END_CKPT

Мы видим начало открытой транзакции, вставку строки, обновление счётчиков строк в метаданных и саму контрольную точку.

Обратите внимание: появилась дополнительная журнальная запись для контрольной точки — LOP_XACT_CKPT. Она создаётся только при наличии активных (не зафиксированных) транзакций и содержит сведения обо всех активных транзакциях в момент начала контрольной точки. Эти сведения используются при восстановлении после сбоя, чтобы определить, как далеко нужно отмотать журнал назад для начала фаз REDO и UNDO (строго говоря, так далеко назад понадобится идти только UNDO). Посмотрим на эту запись:

SELECT [Current LSN], [Operation], [Num Transactions], [Log Record]
FROM fn_dblog (NULL, NULL) WHERE [Operation] = 'LOP_XACT_CKPT';
GO

Current LSN             Operation                       Num Transactions
----------------------- -------------------------------- ---------------
00000047:00000096:0001  LOP_XACT_CKPT                   1

Log Record
--------------------------------------------------------------------------------
0x000018 <snip> 780500000000000047000000940000000100040147000000940000000200000001 <snip> 6621000000000000

Эта запись содержит сведения о каждой активной (не зафиксированной) транзакции в момент контрольной точки. Не вдаваясь в детали полезной нагрузки, можно увидеть два числа:

• LSN записи LOP_BEGIN_XACT для самой старой активной транзакции (первое выделенное число — сопоставьте его с LOP_BEGIN_XACT в дампе журнала выше);
• LSN первой записи, вносящей изменение данных для этой транзакции (второе выделенное число — сопоставьте с LOP_INSERT_ROWS выше).

Заметьте, эти LSN хранятся в «перевёрнутом» (по байтам) виде.

Что если сделать ещё одну контрольную точку?

CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- --------------------------------
00000047:00000094:0001  LOP_BEGIN_XACT
00000047:00000094:0002  LOP_INSERT_ROWS
00000047:00000094:0003  LOP_COUNT_DELTA
00000047:00000094:0004  LOP_COUNT_DELTA
00000047:00000094:0005  LOP_COUNT_DELTA
00000047:00000094:0006  LOP_BEGIN_CKPT
00000047:00000096:0001  LOP_XACT_CKPT
00000047:00000096:0002  LOP_END_CKPT
00000047:00000097:0001  LOP_BEGIN_CKPT
00000047:00000098:0001  LOP_XACT_CKPT
00000047:00000098:0002  LOP_END_CKPT

Теперь видно записи и текущей контрольной точки, и предыдущей — поскольку активная часть журнала тянется до начала самой старой активной транзакции, сколько бы контрольных точек мы ни делали, пока есть активная транзакция.

А если начать ещё одну активную транзакцию (в третьем соединении)?

USE CheckpointTest;
GO
BEGIN TRAN;
GO
INSERT INTO t1 VALUES (2);
GO

Вернёмся в исходное соединение, сделаем ещё одну контрольную точку и снова посмотрим журнал:

CHECKPOINT;
GO
SELECT [Current LSN], [Operation] FROM fn_dblog (NULL, NULL);
GO

Current LSN             Operation
----------------------- --------------------------------
00000047:00000094:0001  LOP_BEGIN_XACT
00000047:00000094:0002  LOP_INSERT_ROWS
00000047:00000094:0003  LOP_COUNT_DELTA
00000047:00000094:0004  LOP_COUNT_DELTA
00000047:00000094:0005  LOP_COUNT_DELTA
00000047:00000094:0006  LOP_BEGIN_CKPT
00000047:00000096:0001  LOP_XACT_CKPT
00000047:00000096:0002  LOP_END_CKPT
00000047:00000097:0001  LOP_BEGIN_CKPT
00000047:00000098:0001  LOP_XACT_CKPT
00000047:00000098:0002  LOP_END_CKPT
00000047:00000099:0001  LOP_BEGIN_XACT
00000047:00000099:0002  LOP_INSERT_ROWS
00000047:00000099:0003  LOP_COUNT_DELTA
00000047:00000099:0004  LOP_COUNT_DELTA
00000047:00000099:0005  LOP_COUNT_DELTA
00000047:00000099:0006  LOP_BEGIN_CKPT
00000047:0000009b:0001  LOP_XACT_CKPT
00000047:0000009b:0002  LOP_END_CKPT

Теперь у нас три набора записей контрольной точки и две активные транзакции. По сути важен лишь один набор — два предыдущих уже «устарели», однако журнальные записи, как видите, никуда не исчезли и не перезаписаны.

Если заглянуть внутрь всех записей LOP_XACT_CKPT (немного отформатировав вывод), увидим:

SELECT [Current LSN], [Operation], [Num Transactions], [Log Record]
FROM fn_dblog (NULL, NULL) WHERE [Operation] = 'LOP_XACT_CKPT';
GO

Current LSN             Operation                       Num Transactions
----------------------- -------------------------------- ---------------
00000047:00000096:0001  LOP_XACT_CKPT                   1
00000047:00000098:0001  LOP_XACT_CKPT                   1
00000047:0000009b:0001  LOP_XACT_CKPT                   2

Log Record
----------------------------------------------------------------------------------
0x000018 <snip> 780500000000000047000000940000000100040147000000940000000200000001 <snip> 21000000000000
0x000018 <snip> 780500000000000047000000940000000100040147000000940000000200000001 <snip> 21000000000000
0x000018 <snip> 780500000000000047000000940000000100040147000000940000000200000001 <snip> 21000000000000 …
… 79050000000000004700000099000000010004014700000099000000020000000100000002000000DC000000

В первых двух контрольных точках числится одна активная транзакция, в самой свежей — две, как и ожидалось. Полезная нагрузка первой и второй записей указывает одну и ту же самую старую активную транзакцию (выделено). В последней записи указан тот же «старейший» LSN (он не менялся), плюс добавлена вторая транзакция (сопоставьте 470000009900000001000 с LSN второй LOP_BEGIN_XACT в дампе журнала выше) и указан счётчик «2».

Напоследок заглянем в загрузочную страницу базы (через DBCC PAGE или DBCC DBINFO):

DBCC TRACEON (3604);
GO
DBCC DBINFO ('CheckpointTest');
GO

DBINFO STRUCTURE:
DBINFO @0x6711EF64

dbi_dbid = 18                        dbi_status = 65536                   dbi_nextid = 2089058478
dbi_dbname = CheckpointTest          dbi_maxDbTimestamp = 2000            dbi_version = 611
dbi_createVersion = 611              dbi_ESVersion = 0
dbi_nextseqnum = 1900-01-01 00:00:00.000                                  dbi_crdate = 2009-09-28 07:06:35.873
dbi_filegeneration = 0
dbi_checkptLSN

m_fSeqNo = 71                        m_blockOffset = 153                  m_slotId = 6
dbi_RebuildLogs = 0                  dbi_dbccFlags = 2
dbi_dbccLastKnownGood = 1900-01-01 00:00:00.000
<snip>

dbi_checkptLSN выводится в десятичном виде — преобразовав в шестнадцатеричный, получим (47:99:6), что в точности совпадает с LSN самой последней записи LOP_BEGIN_CKPT в дампе журнала выше.

Надеюсь, получилось достаточно ясно.