WaitType：ASYNC_IO_COMPLETION

Posted 2020-08-09 悦光阴

项目组有一个数据库备份的Job运行异常，该Job将备份数据存储到remote server上，平时5个小时就能完成的备份操作，现在运行19个小时还没有完成，backup命令的Wait type是 ASYNC_IO_COMPLETION：

根据MSDN 官方文档的定义：Occurs when a task is waiting for asynchronous I/O operations to finish.

该等待类型表示：Task在等待异步IO操作的完成。进程申请了一个IO操作，但是系统（Disk/Network）不能立即完成该IO请求，因此该进程进入等待状态，等待Async IO完成。

查看SQL Server的Error Log，发现大量IO请求超时的记录，从File 的路径 [D:\xxx\yyy.ndf] 上看到，IO 请求是发送给Local Server，说明SQL Server发出的IO请求，Local Server的Disk不能及时完成：

SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [D:\xxx\yyy.ndf] in database [database_name] (8).  The OS file handle is 0x00000000000010E4.  The offset of the latest long I/O is: 0x00000482f60000

出现长时间的ASYNC_IO_COMPLETION 等待的原因可能是：

1. 同时有其他Application在进行大量的IO操作，导致用来存储备份数据的Disk特别忙，备份操作必须等待Disk IO完成。
2. 如果备份数据存储到remote server上，那么可能是network被其他application占用，导致用于传输备份数据的带宽变小。

我看到的这个异常的备份操作，是将备份数据存储到远程Server上，打开ResouceMonitor（点击Windows+R，输入resmon），发现Disk Activity是2MB-4MB之间，而Network Activity在18MB-46MB之间，如图：

这说明，Remote Server的network相对比较忙，网络传输很可能是导致备份操作长时间运行的root cause。但是，从SQL Server的Error Log中得知，是本地Disk的不能及时响应IO请求。

由于备份操作已经结束，没有办法查看Local Server的Disk IO和 Network Activity，而此时，Remote Server上的Disk Activity 和 Network Activity 十分平静，都在几百KB水平上，间接说明Remote Server不是backup操作等待异步IO操作完成的root cause，Local Server的Disk IO是瓶颈。

分析Disk IO的性能，最好的方法是分析Performance Counter。打开Local Server的Performance Monitor（点击Windows+R，输入perfmon），没有记录Data Collection，这样没有办法进行深入的分析了，下次遇到时，继续分析。

总之：在数据库备份或还原的过程中，出现长时间的ASYNC_IO_COMPLETION 等待，表示backup/restore操作正在等待获取IO资源，导致backup/restore 进程处于挂起状态（suspended），只有获取到IO资源，该操作才会继续进行下去。

在执行长时间的IO密集的操作时，SQL Server进程经常会发生ASYNC_IO_COMPLETION等待，同时会在Error Log中记录 “I/O requests are taking longer than 15 seconds to complete” 消息，IO密集的操作主要有：backup/restore操作，新建一个大的数据库文件，和数据库文件增长。长时间执行IO密集操作，本来就需要大量的IO才能完成，但是，长时间处于ASYNC_IO_COMPLETION 等待，在很大程度上，表明IO是系统的瓶颈，Disk的读写能力或Network的传输能力是系统的短板。

 

Appendix：使用以下脚本查看备份操作的等待类型，已经完成的百分比，对于预估的剩余时间，只是个预估值，不可信。

select  r.session_id,
        r.blocking_session_id as blocking,
        r.wait_type as Current_Wait_Type,
        r.wait_time/1000/60/60 as wait_h,
        r.status,
        r.command,
        r.total_elapsed_time/1000/60/60 as total_h,
        r.percent_complete,
        r.estimated_completion_time/1000/60/60 as estimated_h
from sys.dm_exec_requests r
outer APPLY sys.dm_exec_sql_text(r.sql_handle) as st
where (r.wait_type<>‘MISCELLANEOUS‘ or r.wait_type is null)
    and r.session_id>50
    and r.session_id<>@@spid

 

推荐阅读《ASYNC_IO_COMPLETION Wait type》：

Normally this wait type can be seen in backup and restore transactions, and whenever you will see this wait type your backup/restore process will be in suspended state most of the time because the process is waiting to get IO resource to proceed its operation and it will wait till certain time period then moved in suspended state. In that case your process will take more than its usual time to complete or most of the time it will hung or will showing in executing state for unknown time duration.

This wait type occurs when a task is waiting for asynchronous I/Os to finish. This wait type is normally seen with few other wait types like BACKUPBUFFER,BUCKIO etc. This is clear indication of DISK IO issue.You can also get the Average disk queue length or current disk queue length value at the same time when you are getting this wait type.Compare both counters and if these counters have high value then you should look into your storage subsystem. Identify disk bottlenecks, by using Perfmon Counters, Profiler, sys.dm_io_virtual_file_stats and SHOWPLAN.

Any of the following reduces these waits:

1. Adding additional IO bandwidth.
2. Balancing IO across other drives.
3. Reducing IO with appropriate indexing.
4. Check for bad query plans.
5. Check for memory pressure

We can also corelate this wait type between Memory pressure and Disk IO subsystem issues.

参考文档：

ASYNC_IO_COMPLETION Wait type

ASYNC_IO_COMPLETION