ASYNC_IO_COMPLETION

項目組有一個數據庫備份的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