Относительно недавно я начал помогать на новом для себя продуктовом проекте, который на поверку разрабатывается как бесплатный веб-сервис для трекинга рабочего времени.
Стек технологий был изначально выбран мелкомягкий, а в качестве хранилища данных использовался SQL Server 2014 Express. Одним из первых тасков, которые мне поручили — это поисследовать возможность ускорения автотестов.
До того как я включился в работу, проект существовал продолжительное время и уже успел обрасти изрядным количество тестов (на тот момент я насчитал 1300 автотестов). На билдовой машине с SSD тесты выполнялись за 4-5 минут, а на обычном HDD более 11-12 минут. Можно было бы поставить всей команде SSD, но сути проблемы это бы не решило, тем более, что в скором будущем планировалось расширять функционал и тестов стало бы еще больше.
Все тесты были сгруппированы и перед выполнением каждой из групп очищалась база от старых данных. Раньше очистка происходила путем пересоздания базы данных, но данный подход оказался очень медленным на практике. Гораздо быстрее было просто чистить все таблицы от данных и сбрасывать значение IDENTITY в ноль, чтобы последующие вставки формировали правильные тестовые данные. Скрипт именно с таким подходом и стал моей отправной точкой:
EXEC sys.sp_msforeachtable 'ALTER TABLE ? NOCHECK CONSTRAINT ALL'
DELETE FROM [dbo].[Project]
DBCC CHECKIDENT('[dbo].[Project]', RESEED, 0)
DBCC CHECKIDENT('[dbo].[Project]', RESEED)
DELETE FROM [dbo].[RecentWorkTask]
...
EXEC sys.sp_msforeachtable 'ALTER TABLE ? WITH CHECK CHECK CONSTRAINT ALL'
Первое, что бросилось в глаза, это выключение и повторное включение всех констрейнтов на базе. Такое поведение задумывалось, чтобы ускорить операции удаления, но на деле оказалось ресурсоемкой операцией для сервера. Решил отказаться от использования этого подхода.
Также сразу возникла идея использовать динамический SQL для формирования запроса по удалению данных. Например, если на таблице есть внешние ключи, то использовать как и раньше операцию DELETE в противном случае можно удалять данные с минимальные протоколированием с помощью команды TRUNCATE.
В итоге запрос по удалению данных принял следующий вид:
DECLARE @SQL NVARCHAR(MAX) = ''
SELECT @SQL = (
SELECT
CASE WHEN p.[object_id] IS NOT NULL
THEN
CASE WHEN f.referenced_object_id IS NULL
THEN N'TRUNCATE TABLE '
ELSE N'DELETE FROM '
END + obj_name
ELSE ''
END + CHAR(13) + CHAR(10) +
CASE WHEN has_identity > 0
THEN N'DBCC CHECKIDENT('''+ obj_name + N''', RESEED, 0) WITH NO_INFOMSGS'
ELSE ''
END + CHAR(13) + CHAR(10)
FROM (
SELECT obj_name = QUOTENAME(s.name) + '.' + QUOTENAME(o.name)
, o.[object_id]
, has_identity = IdentityProperty(o.[object_id], 'LastValue')
FROM sys.objects o
JOIN sys.schemas s ON o.[schema_id] = s.[schema_id]
WHERE o.is_ms_shipped = 0
AND o.[type] = 'U'
) t
LEFT JOIN (
SELECT DISTINCT [object_id]
FROM sys.partitions
WHERE [rows] > 0
AND index_id IN (0, 1)
) p ON t.[object_id] = p.[object_id]
LEFT JOIN (
SELECT DISTINCT referenced_object_id
FROM sys.foreign_keys
) f ON f.referenced_object_id = t.[object_id]
FOR XML PATH(''), TYPE).value('.', 'NVARCHAR(MAX)')
PRINT @SQL
--EXEC sys.sp_executesql @SQL
И если изначально автотесты выполнялись 11 минут на моей машине:
То после того, как я выкинул ALTER стейтменты и переписал запрос все тесты начали выполнятся на 40 секунд быстрее:
Конечно, можно бы порадоваться и поставить по тихому для таска статус Resolved, но основная проблема осталась:
При выполнении тестов очень сильно нагружался диск. Решил посмотреть какие возникают ожидания на сервере. Для этого вначале очистил sys.dm_os_wait_stats:
DBCC SQLPERF("sys.dm_os_wait_stats", CLEAR)
Повторно запустил выполнения автотестов и после выполнил запрос:
SELECT TOP(20)
wait_type
, wait_time = wait_time_ms / 1000.
, wait_resource = (wait_time_ms - signal_wait_time_ms) / 1000.
, wait_signal = signal_wait_time_ms / 1000.
, waiting_tasks_count
, percentage = 100.0 * wait_time_ms / SUM(wait_time_ms) OVER ()
, avg_wait = wait_time_ms / 1000. / waiting_tasks_count
, avg_wait_resource = (wait_time_ms - signal_wait_time_ms) / 1000. / [waiting_tasks_count]
, avg_wait_signal = signal_wait_time_ms / 1000.0 / waiting_tasks_count
FROM sys.dm_os_wait_stats
WHERE [waiting_tasks_count] > 0
AND max_wait_time_ms > 0
AND [wait_type] NOT IN (
N'BROKER_EVENTHANDLER', N'BROKER_RECEIVE_WAITFOR',
N'BROKER_TASK_STOP', N'BROKER_TO_FLUSH',
N'BROKER_TRANSMITTER', N'CHECKPOINT_QUEUE',
N'CHKPT', N'CLR_AUTO_EVENT',
N'CLR_MANUAL_EVENT', N'CLR_SEMAPHORE',
N'DBMIRROR_DBM_EVENT', N'DBMIRROR_EVENTS_QUEUE',
N'DBMIRROR_WORKER_QUEUE', N'DBMIRRORING_CMD',
N'DIRTY_PAGE_POLL', N'DISPATCHER_QUEUE_SEMAPHORE',
N'EXECSYNC', N'FSAGENT',
N'FT_IFTS_SCHEDULER_IDLE_WAIT', N'FT_IFTSHC_MUTEX',
N'HADR_CLUSAPI_CALL', N'HADR_FILESTREAM_IOMGR_IOCOMPLETION',
N'HADR_LOGCAPTURE_WAIT', N'HADR_NOTIFICATION_DEQUEUE',
N'HADR_TIMER_TASK', N'HADR_WORK_QUEUE',
N'KSOURCE_WAKEUP', N'LAZYWRITER_SLEEP',
N'LOGMGR_QUEUE', N'ONDEMAND_TASK_QUEUE',
N'PWAIT_ALL_COMPONENTS_INITIALIZED',
N'QDS_PERSIST_TASK_MAIN_LOOP_SLEEP',
N'QDS_CLEANUP_STALE_QUERIES_TASK_MAIN_LOOP_SLEEP',
N'REQUEST_FOR_DEADLOCK_SEARCH', N'RESOURCE_QUEUE',
N'SERVER_IDLE_CHECK', N'SLEEP_BPOOL_FLUSH',
N'SLEEP_DBSTARTUP', N'SLEEP_DCOMSTARTUP',
N'SLEEP_MASTERDBREADY', N'SLEEP_MASTERMDREADY',
N'SLEEP_MASTERUPGRADED', N'SLEEP_MSDBSTARTUP',
N'SLEEP_SYSTEMTASK', N'SLEEP_TASK',
N'SLEEP_TEMPDBSTARTUP', N'SNI_HTTP_ACCEPT',
N'SP_SERVER_DIAGNOSTICS_SLEEP', N'SQLTRACE_BUFFER_FLUSH',
N'SQLTRACE_INCREMENTAL_FLUSH_SLEEP',
N'SQLTRACE_WAIT_ENTRIES', N'WAIT_FOR_RESULTS',
N'WAITFOR', N'WAITFOR_TASKSHUTDOWN',
N'WAIT_XTP_HOST_WAIT', N'WAIT_XTP_OFFLINE_CKPT_NEW_LOG',
N'WAIT_XTP_CKPT_CLOSE', N'XE_DISPATCHER_JOIN',
N'XE_DISPATCHER_WAIT', N'XE_TIMER_EVENT'
)
ORDER BY [wait_time_ms] DESC
Наибольшее задержка наблюдается с WRITELOG.
wait_type wait_time waiting_tasks_count percentage
----------------------- ------------ -------------------- -----------
WRITELOG 546.798 60261 96.07
PAGEIOLATCH_EX 13.151 96 2.31
PAGELATCH_EX 5.768 46097 1.01
PAGEIOLATCH_UP 1.243 86 0.21
IO_COMPLETION 1.158 89 0.20
MEMORY_ALLOCATION_EXT 0.480 683353 0.08
LCK_M_SCH_S 0.200 34 0.03
ASYNC_NETWORK_IO 0.115 688 0.02
LCK_M_S 0.082 10 0.01
PAGEIOLATCH_SH 0.052 1 0.00
PAGELATCH_UP 0.037 6 0.00
SOS_SCHEDULER_YIELD 0.030 3598 0.00
Открываем «энциклопедию ожиданий» за авторством Paul Randal-а и находим там WRITELOG попутно сверяясь с MSDN:
This is the log management system waiting for a log flush to disk. It commonly indicates that the I/O subsystem can’t keep up with the log flush volume, but on very high-volume systems it could also be caused by internal log flush limits, that may mean you have to split your workload over multiple databases or even make your transactions a little longer to reduce log flushes. To be sure it’s the I/O subsystem, use the DMV sys.dm_io_virtual_file_stats to examine the I/O latency for the log file and see if it correlates to the average WRITELOG time. If WRITELOG is longer, you’ve got internal contention and need to shard. If not, investigate why you’re creating so much transaction log.
Подсистема управления логом ожидает записи лога на диск. Как правило, означает, что дисковая система не может обеспечить своевременную запись всего объема лога, но на высоконагруженных системах это может быть вызвано общими ограничениями записи лога/ Это может означать, что вам следует разделить нагрузку между несколькими базами, или даже сделать ваши транзакции чуть более долгими, чтобы уменьшить количество записей лога на диск. Для того, чтобы убедиться, что причина в системе ввода/вывода, используйте DMV sys.dm_io_virtual_file_stats для того, чтобы изучить задержку ввода/вывода для файла лога и увидеть, совпадает ли она с временем задержки WRITELOG. Если WRITELOG длится дольше, вы получили внутреннюю конкуренцию за запись на диск и должны разделить нагрузку. Если нет, выясняйте, почему вы создаете такой большой лог транзакций.
И что же мне теперь нужно еще выяснять? Да каждый автотест при выполнении что-то записывает в базу. В качестве решения проблемы с ожиданиями WRITELOG можно было бы вставлять данные не построчно, а более большими кусками. Но в SQL Server 2014 появилась новая опция на уровне базы Delayed Durability, т. е. возможность не сбрасывать данные на диск сразу при коммите транзакции.
Как происходит модификация данных в SQL Server? Предположим мы выполняем вставку новой строки. SQL Server вызывает компонент Storage Engine, тот, в свою очередь, обращяется к Buffer Manager (который работает с буферами в памяти и диском) и говорит, что я хочу изменить данные.
После этого Buffer Manager обращяется к Buffer Pool (кеш в памяти для всех наших данных, который хранит информацию постранично — по 8Кб на страницу) и потом модифицирует нужные страницы в памяти. Если этих страниц нет, то он их подгрузит с диска. В момент, когда страница в памяти изменилась, SQL Server еще не может сказать, что запрос выполнен. Иначе бы нарушался один из принципов ACID, а именно Durability, когда в конце модификации гарантируется, что данные будут записаны на диск.
После модификации страницы в памяти Storage Engine вызывает Log Manager, который записывает данные в лог. Но делает он это не сразу, а через Log Buffer, который имеет размер 60Кб и используется для оптимизации производительности при работе с логом. Сброс данных из буфера в файл лога происходит в ситуации когда:
- Буфер заполнился и данные сохранились в логе.
- Пользователь выполнил sys.sp_flush_log.
- Произошел коммит транзакции и все что было в Log Buffer было записано в лог.
Когда данные были сохранены в логе идет подтверждение, что модификация данных произошла и SQL Server извешяет об этом клиент.
Согласно этой логике можно заметить, что данные не попадают в файл данных. SQL Server использует асинхронный механизм для записи в файлы данных. Всего таких механизмов два:
1) Lazy Writer, который периодически запускается, проверяет достаточно ли памяти для SQL Server. Если нет, то страницы из памяти вытесняются и записываются в файл данных. А те которые были изменены сбрасывает на диск и выкидывает из памяти.
2) Checkpoint, который примерно раз в минуту сканирует грязные страницы, сбрасывает их на диск и оставляет в памяти.
Предположим ситуацию, когда в системе происходит куча мелких транзакций, которые, к примеру, модифицируют данные построчно. После каждого изменения данные уходят из Log Buffer в лог транзакций. Помним, что в лог все изменения попадает синхронно и другим транзакциям приходится ждать своей очереди.
Покажу на примере:
USE [master]
GO
SET NOCOUNT ON
IF DB_ID('TT') IS NOT NULL BEGIN
ALTER DATABASE TT SET SINGLE_USER WITH ROLLBACK IMMEDIATE
DROP DATABASE TT
END
GO
CREATE DATABASE TT
GO
ALTER DATABASE TT
MODIFY FILE (NAME = N'TT', SIZE = 25MB, FILEGROWTH = 5MB)
GO
ALTER DATABASE TT
MODIFY FILE (NAME = N'TT_log', SIZE = 25MB, FILEGROWTH = 5MB)
GO
USE TT
GO
CREATE TABLE dbo.tbl (
a INT IDENTITY PRIMARY KEY
, b INT
, c CHAR(2000)
)
GO
IF OBJECT_ID('tempdb.dbo.#temp') IS NOT NULL
DROP TABLE #temp
GO
SELECT t.[file_id], t.num_of_writes, t.num_of_bytes_written
INTO #temp
FROM sys.dm_io_virtual_file_stats(DB_ID(), NULL) t
DECLARE @WaitTime BIGINT
, @WaitTasks BIGINT
, @StartTime DATETIME = GETDATE()
, @LogRecord BIGINT = (
SELECT COUNT_BIG(*)
FROM sys.fn_dblog(NULL, NULL)
)
SELECT @WaitTime = wait_time_ms
, @WaitTasks = waiting_tasks_count
FROM sys.dm_os_wait_stats
WHERE [wait_type] = N'WRITELOG'
DECLARE @i INT = 1
WHILE @i < 5000 BEGIN
INSERT INTO dbo.tbl (b, c)
VALUES (@i, 'text')
SELECT @i += 1
END
SELECT elapsed_seconds = DATEDIFF(MILLISECOND, @StartTime, GETDATE()) * 1. / 1000
, wait_time = (wait_time_ms - @WaitTime) / 1000.
, waiting_tasks_count = waiting_tasks_count - @WaitTasks
, log_record = (
SELECT COUNT_BIG(*) - @LogRecord
FROM sys.fn_dblog(NULL, NULL)
)
FROM sys.dm_os_wait_stats
WHERE [wait_type] = N'WRITELOG'
SELECT [file] = FILE_NAME(o.[file_id])
, num_of_writes = t.num_of_writes - o.num_of_writes
, num_of_mb_written = (t.num_of_bytes_written - o.num_of_bytes_written) * 1. / 1024 / 1024
FROM #temp o
CROSS APPLY sys.dm_io_virtual_file_stats(DB_ID(), NULL) t
WHERE o.[file_id] = t.[file_id]
Вставка 5 тысяч строк заняла примерно 42,5 секунды при этом задержки при вставке в лог составили 42 секунды.
elapsed_seconds wait_time waiting_tasks_count log_record
---------------- ---------- -------------------- -----------
42.54 42.13 5003 18748
Физически к логу SQL Server обратился 5 тысяч раз и в общей сложности записал 20Мб.
file num_of_writes num_of_mb_written
------- -------------- ------------------
TT 79 8.72
TT_log 5008 19.65
Именно для таких ситуаций нужен Delayed Durability. При его включении запись в лог происходит только, когда Log Buffer полностью заполнен. Включить Delayed Durability можно для всей базы:
ALTER DATABASE TT SET DELAYED_DURABILITY = FORCED
GO
или для отдельных транзакций:
ALTER DATABASE TT SET DELAYED_DURABILITY = ALLOWED
GO
BEGIN TRANSACTION t
...
COMMIT TRANSACTION t WITH (DELAYED_DURABILITY = ON)
Включим на уровне базы и повторно выполним скрипт.
Ожидания пропали и запрос отработал на моей машине за 170мс:
elapsed_seconds wait_time waiting_tasks_count log_record
---------------- ---------- -------------------- -----------
0.17 0.00 0 31958
За счет того, что запись в лог происходила менее интенсивно:
file num_of_writes num_of_mb_written
------- -------------- ------------------
TT 46 9.15
TT_log 275 12.92
Разумеется есть и ложка дегтя. Еще до того как данные физически попали в файл лога, клиенту уже идет оповещение, что изменения зафиксированы. В случае сбоя, мы можем потерять данные равные размеру буфера и побить базу.
В моем случае, сохранность тестовых данных не требовалась. Для тестовой базы на который крутились автотесты установили DELAYED_DURABILITY в FORCED и следующий запуск всех тестов отработал уже за 2.5 минуты.
И при этом все задержки связанные с записью в лог стали оказывать минимальное влияние на производительность:
wait_type wait_time waiting_tasks_count percentage
-------------------- ----------- -------------------- -----------
PAGEIOLATCH_EX 16.031 61 43.27
WRITELOG 15.454 787 41.72
PAGEIOLATCH_UP 2.210 36 5.96
PAGEIOLATCH_SH 1.472 2 3.97
LCK_M_SCH_M 0.756 9 2.04
ASYNC_NETWORK_IO 0.464 735 1.25
PAGELATCH_UP 0.314 8 0.84
SOS_SCHEDULER_YIELD 0.154 2759 0.41
PAGELATCH_EX 0.154 44785 0.41
LCK_M_SCH_S 0.021 7 0.05
PAGELATCH_SH 0.011 378 0.02
Подведем небольшие итоги по Delayed Durability:
- Доступен во всех редакциях начиная с SQL Server 2014.
- Его можно использовать, если у вас наблюдается узкое место при записи в журнал транзакций (отложенная запись большими блоками может быть эффективнее, чем много маленьких).
- Одновременно выполняемые транзакции с меньшей долей вероятности буду соперничать за IO операции при записи в журнал транзакций.
- При его включении операция COMMIT не ждет записи в журнал транзакций и мы можем получить существенный прирост производительности в OLTP системах.
- Можно смело включать Delayed Durability, если есть готовность поиграть в «русскую рулетку» и при «удачном» стечении обстоятельств потерять примерно 60Кб данных в случае сбоя.
UPDATE 2016-07-12: Скрипт по удалению данных сделал более функциональным
DECLARE @SQL NVARCHAR(MAX)
, @FK_TurnOff NVARCHAR(MAX)
, @FK_TurnOn NVARCHAR(MAX)
SELECT @SQL = (
SELECT CHAR(13) + CHAR(10) +
IIF(p.[rows] > 0,
IIF(t2.referenced_object_id IS NULL, N'TRUNCATE TABLE ', N'DELETE FROM ') + obj_name,
''
) + CHAR(13) + CHAR(10) +
IIF(IdentityProperty(t.[object_id], 'LastValue') > 0,
N'DBCC CHECKIDENT('''+ obj_name + N''', RESEED, 0) WITH NO_INFOMSGS',
''
)
FROM (
SELECT obj_name = QUOTENAME(s.name) + '.' + QUOTENAME(o.name), o.[object_id]
FROM sys.objects o
JOIN sys.schemas s ON o.[schema_id] = s.[schema_id]
WHERE o.is_ms_shipped = 0
AND o.[type] = 'U'
AND o.name != N'__MigrationHistory'
) t
JOIN sys.partitions p ON t.[object_id] = p.[object_id] AND p.index_id IN (0, 1)
LEFT JOIN (
SELECT DISTINCT f.referenced_object_id
FROM sys.foreign_keys f
) t2 ON t2.referenced_object_id = t.[object_id]
FOR XML PATH(''), TYPE).value('.', 'NVARCHAR(MAX)')
SELECT @FK_TurnOff = CAST(x.query('off/text()') AS NVARCHAR(MAX))
, @FK_TurnOn = CAST(x.query('on/text()') AS NVARCHAR(MAX))
FROM (
SELECT [off] = CHAR(10) + 'ALTER TABLE ' + obj + ' NOCHECK CONSTRAINT ' + fk
, [on] = CHAR(10) + 'ALTER TABLE ' + obj + ' CHECK CONSTRAINT ' + fk
FROM (
SELECT fk = QUOTENAME(f.name)
, obj = QUOTENAME(SCHEMA_NAME(f.[schema_id])) + '.' + QUOTENAME(OBJECT_NAME(f.parent_object_id))
FROM sys.foreign_keys f
WHERE f.delete_referential_action = 0
AND EXISTS(
SELECT *
FROM sys.partitions p
WHERE p.[object_id] = f.parent_object_id
AND p.[rows] > 0
AND p.index_id IN (0, 1)
)
) t
FOR XML PATH(''), TYPE
) t(x)
IF @SQL LIKE '%[a-z]%' BEGIN
SET @SQL = ISNULL(@FK_TurnOff, '') + @SQL + ISNULL(@FK_TurnOn, '')
PRINT @SQL
--EXEC sys.sp_executesql @SQL
END
Если хотите поделиться этой статьей с англоязычной аудиторией:
Delayed Durability, or The Story of How to Speed Up Autotests From 11 to 2.5 Minutes
