Что происходит с данными и журналом при сбросах в tempdb

Автор: Paul Randal, Understanding data vs log usage for spills in tempdb

В списке рассылки SQL MCM (в котором участвуют все действующие инструкторы MCM) было обсуждение, где пытались понять огромное несоответствие между использованием файлов данных tempdb и файлов журнала. Я объяснил ответ и решил поделиться им со всеми вами.

Ситуация была такова: файлы данных tempdb выросли с 30 ГБ до 120 ГБ, на диске закончилось место, но файл журнала tempdb вообще не вырос по сравнению с его начальным размером в 1 ГБ! Как такое могло произойти?

Одна из вещей, которые следует учитывать в отношении tempdb, — это то, что ведение журнала в tempdb является сверхэффективным. Например, записи журнала для обновлений в tempdb регистрируют только образ данных «до» (before image) вместо того, чтобы регистрировать как образ «до», так и образ «после» (after image). Нет необходимости регистрировать образ «после» — он используется только для части REDO при аварийном восстановлении. Поскольку tempdb никогда не восстанавливается после сбоя, REDO никогда не происходит. Однако образ «до» необходим, потому что транзакции могут быть откачены в tempdb, как и в других базах данных, и поэтому образ «до» обновления должен быть доступен для успешного отката обновления.

Однако, возвращаясь к вопросу, я могу легко объяснить наблюдаемое поведение, рассмотрев, как происходит сброс сортировки (sort spill) в tempdb.

Я могу смоделировать это, используя сложный запрос к базе данных SalesDB, которую вы можете скачать с нашей страницы ресурсов (см. начало страницы для загрузки примеров баз данных).

Я собираюсь выполнить соединение таблиц Sales и Products, а затем отсортировать результирующий набор из нескольких миллионов строк по имени продукта:

SELECT S.*, P.* from Sales S
JOIN Products P ON P.ProductID = S.ProductID
ORDER BY P.Name;
GO

План запроса для этого (с использованием Plan Explorer):

Я знаю, что в этом случае сортировка будет сброшена из памяти в tempdb. Сначала я выполняю контрольную точку для tempdb (чтобы очистить журнал), а затем после выполнения запроса я могу проанализировать журнал транзакций для tempdb.

Рассмотрим операции в журнале:

SELECT
     [Current LSN],
     [Operation],
     [Context],
     [Transaction ID],
     [Log Record Length],
     [Description]
FROM fn_dblog (null, null);
GO

Результат (сокращён):

Current LSN            Operation       Context  Transaction ID Len Description
---------------------  --------------  -------- ------------- --- ------------------------------
000000c0:00000077:0001 LOP_BEGIN_XACT  LCX_NULL 0000:00005e4d  120 sort_init;<snip>
000000c0:00000077:0002 LOP_BEGIN_XACT  LCX_NULL 0000:00005e4e  132 FirstPage Alloc;<snip>
000000c0:00000077:0003 LOP_SET_BITS    LCX_GAM  0000:00005e4e  60  Allocated 1 extent(s) starting at page 0001:0000aa48
000000c0:00000077:0004 LOP_MODIFY_ROW  LCX_PFS  0000:00005e4e  88  Allocated 0001:0000aa48;Allocated 0001:0000aa49;
000000c0:00000077:0005 LOP_MODIFY_ROW  LCX_PFS  0000:00005e4d  80  Allocated 0001:00000123
000000c0:00000077:0006 LOP_FORMAT_PAGE LCX_IAM  0000:00005e4d  84               
000000c0:00000077:0007 LOP_SET_BITS    LCX_IAM  0000:00005e4e  60               
000000c0:00000077:0009 LOP_COMMIT_XACT LCX_NULL 0000:00005e4e  52               
000000c0:00000077:000a LOP_BEGIN_XACT  LCX_NULL 0000:00005e4f  128 soAllocExtents;<snip>
000000c0:00000077:000b LOP_SET_BITS    LCX_GAM  0000:00005e4f  60  Allocated 1 extent(s) starting at page 0001:0000aa50
000000c0:00000077:000c LOP_MODIFY_ROW  LCX_PFS  0000:00005e4f  88  Allocated 0001:0000aa50;Allocated 0001:0000aa51;<snip>
...
000000cd:00000088:01d3 LOP_SET_BITS    LCX_GAM  0000:000078fc  60  Deallocated 1 extent(s) starting at page 0001:00010e50
000000cd:00000088:01d4 LOP_COMMIT_XACT LCX_NULL 0000:000078fc  52               
000000cd:00000088:01d5 LOP_BEGIN_XACT  LCX_NULL 0000:000078fd  140 ExtentDeallocForSort;<snip>
000000cd:00000088:01d6 LOP_SET_BITS    LCX_IAM  0000:000078fd  60               
000000cd:00000088:01d7 LOP_MODIFY_ROW  LCX_PFS  0000:000078fd  88  Deallocated 0001:00010e68;Deallocated 0001:00010e69;<snip>
000000cd:00000088:01d8 LOP_SET_BITS    LCX_GAM  0000:000078fd  60  Deallocated 1 extent(s) starting at page 0001:00010e68
000000cd:00000088:01d9 LOP_COMMIT_XACT LCX_NULL 0000:000078fd  52               
...

(Я удалил несколько посторонних записей журнала, а также 6 дополнительных операций 'Allocated' и 'Deallocated' для каждой из модификаций строк PFS.)

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

Посмотрите на транзакцию soAllocExtents с идентификатором транзакции 00005e50. Она выделяет 4 экстента — т.е. 256 КБ — в одной системной транзакции (4 раза отметить экстент как недоступный в GAM, 4 раза массово установить 8 байт PFS для 8 страниц в экстенте, 4 раза отметить экстент как выделенный в IAM). Общий размер записей журнала для этой транзакции составляет 1012 байт. (Первая системная транзакция soAllocExtents выделяет только 3 экстента, все остальные выделяют по 4 экстента.)

Когда сортировка заканчивается, экстенты освобождаются по одному в системных транзакциях, называемых ExtentDeallocForSort. Примером является транзакция с идентификатором 000078fd. Она генерирует записи журнала общим объёмом 400 байт. Это означает, что каждый 256 КБ требует 4 × 400 = 1600 байт для освобождения.

Объединяя операции выделения и освобождения, каждый 256 КБ сортировки, сбрасываемой в tempdb, генерирует 2612 байт записей журнала.

Теперь рассмотрим исходное поведение, которое я объяснил. Если 90 ГБ — это всё пространство для сортировки:

90 ГБ = 90 × 1024 × 1024 = 94 371 840 КБ, что составляет 94 371 840 / 256 = 368 640 блоков по 256 КБ.

Каждый блок по 256 КБ требует 2612 байт для выделения и освобождения, поэтому наши 90 ГБ потребовали бы 368 640 × 2612 = 962 887 680 байт журнала, что составляет 962 887 680 / 1024 / 1024 ≈ 918 МБ журнала.

И это объяснило бы наблюдаемое поведение. 90 ГБ пространства tempdb могут быть выделены и использованы для сброса сортировки с примерно 918 МБ журнала транзакций, плюс-минус погрешность моих приблизительных расчётов.

Tempdb ведёт журнал очень эффективно — особенно для того, что сбрасывается из памяти. Следующим шагом в отладке такой проблемы был бы регулярный захват вывода sys.dm_db_task_space_usage, чтобы выяснить, кто использует всё пространство, и затем копать дальше оттуда.

Надеюсь, это поможет объяснить ситуацию!