Относительно недавно я начал помогать на новом для себя продуктовом проекте TMetric, который на поверку разрабатывается как бесплатный веб-сервис для трекинга рабочего времени.

Стек технологий был изначально выбран мелкомягкий, а в качестве хранилища данных использовался SQL Server 2014. Одним из первых тасков, которые мне поручили — это поисследовать возможность ускорения автотестов.


До того как я включился в работу, проект существовал продолжительное время и уже успел обрасти изрядным количество тестов (на тот момент я насчитал 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

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

В моем случае, сохранность тестовых данных не требовалась. Для тестовой базы на который крутились автотесты TMetric установили 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Кб данных в случае сбоя.