Истории о данных: случай с упрямым файлом журнала

Каждому, кто работал с SQL Server, известны типичные ошибки, о которых часто спрашивают пользователи. Один из вопросов всегда относится к файлам журнала базы данных, которые растут, пока не начинают занимать все доступное место на диске.

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

Этот администратор работал со сравнительно малой базой данных размером около 90 Гбайт. В прошлом файл журнала занимал примерно 12 Гбайт. Был настроен шаг приращения файла в 100 Мбайт. Объем устройства, содержащего файл журнала, составлял чуть менее 40 Гбайт, поэтому администратор считал, что располагает обширным пространством. К сожалению, диск постоянно заполнялся.

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

Более сложная проблема с репликацией и файлами журнала возникает, когда параметр sync with backup используется с базой данных публикации или базой данных распространителя. В этом случае усечение журнала не только ожидает, пока средство чтения журнала репликации скопирует подробности в базу данных распространителя, но и дожидается завершения резервного копирования базы данных распространителя. В любом случае, заверил меня мой собеседник, репликация транзакций не использовалась.

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

DBCC SHRINKFILE ('ABCTest_log', 12000);

Администратор сказал, что ему пришлось выполнить эту команду несколько раз, но в конце концов файл удалось сжать до нужного размера, получилось около 12 Гбайт. Но спустя короткое время размер файла журнала вновь увеличился почти до 40 Гбайт, заполнив диск. Пришло время мне подключиться и внимательно взглянуть на проблему.

Третий пункт моего списка проверки — найти продолжительные транзакции. Независимо от выбранной модели восстановления файл журнала будет увеличиваться, пока активна продолжительная транзакция. Самый быстрый способ проверить это, а также выяснить, почему не удается ограничить (и повторно использовать) файл журнала — направить запрос к sys.databases:

SELECT log_reuse_wait_desc FROM
   sys.databases WHERE name = N'ABCTest';

Результат показан на рисунке 1.

Рисунок 1. Результаты проверки транзакции

Чтобы определить, является ли транзакция продолжительной, можно выполнить следующую команду:

USE ABCTest;
GO
DBCC OPENTRAN;
GO

Эта команда возвращает примерно такую информацию, как показано на рисунке 2.

Рисунок 2. Определение времени выполнения транзакции

Предпочтительно, чтобы большинство транзакций завершалось не более чем за несколько секунд, по крайней мере в интерактивном приложении обработки. Мне удалось выяснить, что со времени начала прошло более часа. Это означает, что, хотя база данных имеет простую модель восстановления, в файле журнала будут содержаться все сведения последнего часа. В этом была причина его постоянного роста.

Пришло время выяснить, какая команда вызывала проблему. Это удалось сделать, используя значение SPID, равное 61, которое также возвращено командой DBCC OPENTRAN. Для поиска данной информации будут полезны динамические административные представления (DMV) sys.dm_exec:

SELECT st.text AS SQLText,
       qp.query_plan AS QueryPlan
FROM sys.dm_exec_requests AS r
CROSS APPLY sys.dm_exec_sql_text(
   r.sql_handle) AS st
CROSS APPLY sys.dm_exec_query_plan
   (r.plan_handle) AS qp
WHERE r.session_id = 61;

Выполнение этой команды позволило выяснить два обстоятельства. Прежде всего, мы узнали, что проблемным запросом был следующий:

(@LogExpiryDate datetime,
   @LogExpiryTime decimal(6,0))
DELETE FROM ACTIVITY_LOG
WHERE LOG_DATE < @LogExpiryDate
OR (LOG_DATE = @LogExpiryDate
   AND LOG_TIME <= @LogExpiryTime)

Кроме того, как выяснилось, план запроса был таким, как показано на рисунке 3.

Рисунок 3. План проблемного запроса

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

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

В данном случае положение усугубляется тем, что код удаления запускается через каждые полчаса. Если выполнение запроса занимает более получаса, то другая копия того же запроса начинает выполняться и будет блокирована первым запросом. Это можно увидеть в мониторе активности (см. рисунок 4).

Рисунок 4. Взаимная блокировка запросов

Последняя проблема заключалась в том, что подсистема ввода-вывода также не справлялась с активностью операций. Быстрая проверка задержек показала, что их величина значительно превышает рекомендованные 5-10 мс для файлов данных (см. рисунок 5).

Рисунок 5. Аномальная величина задержек при выполнении операций ввода-вывода

Займемся устранением проблемы. Помимо разговора с администратором SAN о падении быстродействия SAN под нагрузкой, следует выполнить два простых шага.

Во-первых, необходим подходящий индекс для таблицы ACTIVITYLOG. Простой индекс для LOG_DATE и LOG_TIME оказался очень удобен:

CREATE INDEX
   IX_ACTIVITYLOG_DeletionPerf_20150813
ON dbo.ACTIVITYLOG
   (LOG_DATE, LOG_TIME);

Во-вторых, важно убедиться, что старые данные были удалены гораздо более мелкими фрагментами. Существует не много случаев применения для оператора TOP в инструкциях INSERT, UPDATE и DELETE, так как они не могут содержать предложение ORDER BY, но возможность выполнять удаления более мелкими фрагментами может быть очень полезна. Код удаления надлежит переписать следующим образом:

WHILE (1 = 1)
BEGIN
    DELETE TOP(100)
        FROM dbo.ACTIVITYLOG
        WHERE LOG_DATE < @LogExpiryDate;
    IF @@ROWCOUNT < 100 BREAK;
END;

WHILE (1 = 1)
BEGIN
    DELETE TOP(100)
        FROM dbo.ACTIVITYLOG
        WHERE LOG_DATE = @LogExpiryDate
        AND LOG_TIME <= @LogExpiryTime;
    IF @@ROWCOUNT < 100 BREAK;
END;

В первом цикле удаляются строки, предшествующие целевой дате, по 100 строк за один раз, пока все целевые строки не будут удалены. Во втором цикле удаляются строки в целевой день в часы, предшествующие целевому времени. Это можно было сделать в одном цикле, особенно если бы система содержала единый столбец datetime вместо отдельных столбцов для дат и часов. Однако гораздо проще оптимизировать запрос и индексацию, если запросы отдельные.

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