项目组有一个数据库备份的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 等待的原因可能是:
- 同时有其他Application在进行大量的IO操作,导致用来存储备份数据的Disk特别忙,备份操作必须等待Disk IO完成。
- 如果备份数据存储到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》:
- Adding additional IO bandwidth.
- Balancing IO across other drives.
- Reducing IO with appropriate indexing.
- Check for bad query plans.
- Check for memory pressure
参考文档: