Выясняем причину длительных ожиданий ASYNC_IO_COMPLETION

Автор: Paul Randal, A cause of high-duration ASYNC_IO_COMPLETION waits

В некоторых данных статистики ожиданий, которые я анализировал, на некоторых серверах наблюдались очень длительные ожидания ASYNC_IO_COMPLETION, о чём у меня было предположение, но я хотел получить доказательства.

Официальное определение ASYNC_IO_COMPLETION: «Происходит, когда задача ожидает завершения операций ввода-вывода.» Очень полезно — НЕТ!

Используя код, о котором я написал вчера в блоге (How to determine what causes a particular wait type), я настроил сеанс XEvent для отслеживания всех ожиданий ASYNC_IO_COMPLETION и их длительности, изменив цель на ring_buffer, чтобы получать также длительность ожиданий:

CREATE EVENT SESSION [InvestigateWaits] ON SERVER
ADD EVENT [sqlos].[wait_info]
(
    ACTION ([package0].[callstack])
    WHERE [wait_type] = 98 -- ASYNC_IO_COMPLETION only, same on all versions
    AND [opcode] = 1 -- Just the end wait events
)
ADD TARGET [package0].[ring_buffer]
WITH
(
    MAX_MEMORY = 50 MB,
    MAX_DISPATCH_LATENCY = 5 SECONDS
)
GO

Затем я выполнил несколько команд. Хотя ASYNC_IO_COMPLETION появляется в различных местах, длительное ожидание происходит во время резервного копирования данных. Фактически, во время каждого полного резервного копирования, которое я выполнял, происходило три ожидания ASYNC_IO_COMPLETION:

.
<snip>
.
    <data name="duration">
      <type name="uint64" package="package0" />
      <value>7</value>
    </data>
.
<snip>
.
XeSosPkg::wait_info::Publish+138 [ @ 0+0x0
SOS_Scheduler::UpdateWaitTimeStats+30c [ @ 0+0x0
SOS_Task::PostWait+90 [ @ 0+0x0
EventInternal<SuspendQueueSLock>::Wait+1f9 [ @ 0+0x0
AsynchronousDiskPool::WaitUntilDoneOrTimeout+fb [ @ 0+0x0
CheckpointDB2+2cd [ @ 0+0x0
BackupDatabaseOperation::PerformDataCopySteps+c2 [ @ 0+0x0
BackupEntry::BackupDatabase+2ca [ @ 0+0x0
CStmtDumpDb::XretExecute+ef [ @ 0+0x0
CMsqlExecContext::ExecuteStmts<1,1>+400 [ @ 0+0x0
CMsqlExecContext::FExecute+a33 [ @ 0+0x0
CSQLSource::Execute+866 [ @ 0+0x0
process_request+73c [ @ 0+0x0
process_commands+51c [ @ 0+0x0
SOS_Task::Param::Execute+21e [ @ 0+0x0
SOS_Scheduler::RunTask+a8 [ @ 0+0x0
SOS_Scheduler::ProcessTasks+29a [ @ 0+0x0
SchedulerManager::WorkerEntryPoint+261 [ @ 0+0x0
SystemThread::RunWorker+8f [ @ 0+0x0
SystemThreadDispatcher::ProcessWorker+3c8 [ @ 0+0x0
SchedulerManager::ThreadEntryPoint+236 [ @ 0+0x0
BaseThreadInitThunk+d [ @ 0+0x0
RtlUserThreadStart+21 [ @ 0+0x0</value
.
<snip>
.
    <data name="duration">
      <type name="uint64" package="package0" />
      <value>0</value>
    </data>
.
<snip>
.
SOS_Scheduler::UpdateWaitTimeStats+30c [ @ 0+0x0
SOS_Task::PostWait+90 [ @ 0+0x0
EventInternal<SuspendQueueSLock>::Wait+1f9 [ @ 0+0x0
AsynchronousDiskPool::WaitUntilDoneOrTimeout+fb [ @ 0+0x0
BackupOperation::GenerateExtentMaps+34c [ @ 0+0x0
BackupDatabaseOperation::PerformDataCopySteps+179 [ @ 0+0x0
BackupEntry::BackupDatabase+2ca [ @ 0+0x0
CStmtDumpDb::XretExecute+ef [ @ 0+0x0
CMsqlExecContext::ExecuteStmts<1,1>+400 [ @ 0+0x0
CMsqlExecContext::FExecute+a33 [ @ 0+0x0
CSQLSource::Execute+866 [ @ 0+0x0
process_request+73c [ @ 0+0x0
process_commands+51c [ @ 0+0x0
SOS_Task::Param::Execute+21e [ @ 0+0x0
SOS_Scheduler::RunTask+a8 [ @ 0+0x0
SOS_Scheduler::ProcessTasks+29a [ @ 0+0x0
SchedulerManager::WorkerEntryPoint+261 [ @ 0+0x0
SystemThread::RunWorker+8f [ @ 0+0x0
SystemThreadDispatcher::ProcessWorker+3c8 [ @ 0+0x0
SchedulerManager::ThreadEntryPoint+236 [ @ 0+0x0
BaseThreadInitThunk+d [ @ 0+0x0
RtlUserThreadStart+21 [ @ 0+0x0</value>
.
<snip>
.
    <data name="duration">
      <type name="uint64" package="package0" />
      <value>1958</value>
    </data>
.
<snip>
.
XeSosPkg::wait_info::Publish+138 [ @ 0+0x0
SOS_Scheduler::UpdateWaitTimeStats+30c [ @ 0+0x0
SOS_Task::PostWait+90 [ @ 0+0x0
EventInternal<SuspendQueueSLock>::Wait+1f9 [ @ 0+0x0
AsynchronousDiskPool::WaitUntilDoneOrTimeout+fb [ @ 0+0x0
BackupOperation::BackupData+272 [ @ 0+0x0
BackupEntry::BackupDatabase+2ca [ @ 0+0x0
CStmtDumpDb::XretExecute+ef [ @ 0+0x0
CMsqlExecContext::ExecuteStmts<1,1>+400 [ @ 0+0x0
CMsqlExecContext::FExecute+a33 [ @ 0+0x0
CSQLSource::Execute+866 [ @ 0+0x0
process_request+73c [ @ 0+0x0
process_commands+51c [ @ 0+0x0
SOS_Task::Param::Execute+21e [ @ 0+0x0
SOS_Scheduler::RunTask+a8 [ @ 0+0x0
SOS_Scheduler::ProcessTasks+29a [ @ 0+0x0
SchedulerManager::WorkerEntryPoint+261 [ @ 0+0x0
SystemThread::RunWorker+8f [ @ 0+0x0
SystemThreadDispatcher::ProcessWorker+3c8 [ @ 0+0x0
SchedulerManager::ThreadEntryPoint+236 [ @ 0+0x0
BaseThreadInitThunk+d [ @ 0+0x0
RtlUserThreadStart+21 [ @ 0+0x0

Сокращённый вывод XEvent: три события с длительностью 7, 0 и 1958 мс

По одному ожиданию для каждого из следующих действий:

1. Контрольная точка в начале резервного копирования.
2. Чтение страниц GAM из файлов данных для определения того, что нужно резервировать.
3. Чтение фактических данных из файлов данных (записи в файлы резервных копий отслеживаются через ожидания BACKUPIO).

Третье ожидание длится почти всё время резервного копирования. Поскольку их три на каждое резервное копирование данных, среднее значение на ожидание будет несколько искажено.

Агрегированные ожидания для одной операции резервного копирования выглядят следующим образом, показывая, что ожидания BACKUPIO и BACKUPBUFFER в сумме составляют почти всё время выполнения резервного копирования, около 2 секунд:

WaitType	Wait_S	Resource_S	Signal_S	WaitCount	Percentage	AvgWait_S	AvgRes_S	AvgSig_S
BACKUPBUFFER	2.69	2.68	0.01	505	37.23	0.0053	0.0053	0.0000
ASYNC_IO_COMPLETION	2.33	2.33	0.00	3	32.29	0.7773	0.7773	0.0000
BACKUPIO	1.96	1.96	0.00	171	27.08	0.0114	0.0114	0.0000
PREEMPTIVE_OS_WRITEFILE	0.20	0.20	0.00	2	2.78	0.1005	0.1005	0.0000
BACKUPTHREAD	0.04	0.04	0.00	15	0.50	0.0024	0.0024	0.0000
PREEMPTIVE_OS_FILEOPS	0.00	0.00	0.00	5	0.06	0.0008	0.0008	0.0000
WRITELOG	0.00	0.00	0.00	11	0.06	0.0004	0.0004	0.0000

Итак, вот оно. XEvents и немного знаний о внутреннем устройстве позволяют нам понять то, что иначе могло бы выглядеть как тревожный тип ожидания с высокой длительностью. Длительные ожидания ASYNC_IO_COMPLETION обычно возникают из-за резервного копирования данных (они не происходят при обычном резервном копировании журнала).