Загадки SQL Server. Долго висит восстановление базы данных на 100%

Меня недавно спросили:

«Я использую восстановление базы данных с опцией WITH STATS, которая показывает процент восстановления базы данных, но когда процент восстановления доходит до 100%, то процесс может ещё долго висеть на 100%, что происходит в этот момент?»

Я не смог сразу ответить на этот вопрос, поэтому решил провести исследование. Первым делом я настроил extendev events (XEvent) и запустил восстановление БД WideWorldImporters sample database. После восстановления я получил следующий вывод в SSMS:

10 percent processed.
20 percent processed.
30 percent processed.
Processed 1464 pages for database ‘wideworldimporters’, file ‘WWI_Primary’ on file 1.
Processed 53096 pages for database ‘wideworldimporters’, file ‘WWI_UserData’ on file 1.
Processed 33 pages for database ‘wideworldimporters’, file ‘WWI_Log’ on file 1.
Processed 3862 pages for database ‘wideworldimporters’, file ‘WWI_InMemory_Data_1’ on file 1.
100 percent processed.
RESTORE DATABASE successfully processed 58455 pages in 8.250 seconds (55.354 MB/sec).

Когда я посмотрел на события в XEvent, то увидел следующее:

После восстановления БД до 100% есть ещё несколько событий. Давайте рассмотрим этапы восстановления БД и их влияние на время восстановления.

Эта восстановления БД

1. Создание файла БД
2. Копирование всех страниц данных из backup
3. Создание файла логов
4. Копирование блоков данных в файл лога из backup
5. Запуск Recovery БД

Сделаю предположение, что большинство людей использует Instant File Initialization, поэтому не будем останавливаться на 1 шаге, так как с этой возможностью создание файла на файловой системе происходит быстро.

Пункт 3 выглядит наиболее подходящим для наших исследований, так как к нему не может быть применено Instant File Initialization и файл лога должен быть заполнен нулями полностью, так же нам может помешать большое количество виртуальных файлов логов.

Я решил проверить моё предположение с помощью доработки XEvent и увеличения размера БД до 10 Гб файла данных и 5 Гб файл лога (реальных данных всего 13 Мб). После запуска нового восстановления я получил следующий результат:

Обратите внимание, что процент восстановление указывает количество байт, которое было восстановлено и когда восстановление дошло до 100% мы получили наши 13 Мб (реальный размер данных).  Но самое важно для нас — это шаги «Waiting for Log zeroing» и “Log Zeroing is complete”. Если посмотреть внимательно, то мы обнаружим, что эти шаги заняли значительно больше времени (около 2-х минут), чем процесс восстановления, выраженный в процентах (секунды).

Из данного эксперимента можно сделать несколько выводов:

1. Заполнение файла лога нулями и есть та причина, по которой восстановление так долго висит на 100%
2. Проценты восстановления показывают только восстановленный объём файла данных.

Надеюсь раскрытие этой загадки SQL Server было вам интересно.

Вырезка из статьи — 
SQL Server Mysteries: The Case of the Not 100% RESTORE