项目组有一个数据库备份的Job运行异常，该Job将备份数据存储到remote server上，平时5个小时就能完成的备份操作，现在运行19个小时还没有完成，backup命令的Wait type是 ASYNC_IO_COMPLETION：
SQL Server Wait Events: Taking the Guesswork out of Performance Profiling
SQL Server 2005或以上
22 March 2007
Select * from 某个表，表的数据量约为30万行，在执行语句时通过观察sys.dm_exec_requests中的wait_type列发现是ASYNC_NETWORK_IO等待，在本地MSSQL2012上测试时发现了PREEMPTIVE_新葡亰496net：品质调优。OS_WAITFORSINGLEOBJECT等待，在本地2008R2测试时发现只有ASYNC_NETWORK_IO等待。
根据MSDN 官方文档的定义：Occurs when a task is waiting for asynchronous I/O operations to finish.
by Mario Broodbakker
Measuring what is actually happening is always the best course of action when investigating performance issues on databases, rather than relying on cache hit ratios, or best practices, or worst of all, guesswork.
select session_id, db_name(database_id) as "db_name", status, wait_type, wait_time, text from sys.dm_exec_requests cross apply sys.dm_exec_sql_text(sql_handle) where session_id>50
查看SQL Server的Error Log，发现大量IO请求超时的记录，从File 的路径 [D:xxxyyy.ndf] 上看到，IO 请求是发送给Local Server，说明SQL Server发出的IO请求，Local Server的Disk不能及时完成：
In order to solve performance issues, you may take a gamble on buying a bigger box with the fastest CPUs, only to discover that it doesn't achieve anything. Understanding and measuring is the key to improving database performance. If, for example, you measure high log write times, then you know exactly what you should do: go look for ways to speed up your log drive(s), or take away the load on the log drives from other processes or queries.
SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [D:xxxyyy.ndf] in database [database_name] (8). The OS file handle is 0x00000000000010E4. The offset of the latest long I/O is: 0x00000482f60000
This article introduces some techniques that will allow you to pinpoint exactly where the performance issues are in your system, so you'll know exactly where to spend your time (and money) in solving them.
了解到：shared memory协议开启时，使用本机名登录会优先使用shared memory协议，因此此协议只适用于本地连接。
A long time ago in a galaxy far, far away a Dutch guy named Anjo Kolk wrote a paper called YAPP: "Yet Another Performance Profiling Method". The idea behind YAPP is simple, but powerful:
Response time = service time wait time
In other words, you either work or you wait for a resource to become available. Even 12 years ago, when Anjo first developed the method, this was not a new idea, since this is part of basic queuing theory that many of us should know. The other key idea behind YAPP is that, when optimizing, you should start with the largest time consumer – this principle is also based on an old (Amdahl) law. What was new was that Anjo showed how to apply this principle to working with databases (he originally developed the method for Oracle), using wait events and CPU statistics.
In the Oracle world, YAPP is now a generally accepted way of looking at performance, with many tools and products that use the ideas behind the method.
The YAPP paper can be found at: . Be warned, though, that it deals exclusively with Oracle.
The good news is that the YAPP method can be used in the SQL Server world too. With SQL Server 2005, Microsoft now documents wait events, and provides access to wait event information, through the Dynamic Management Views (DMVs). Older versions of SQL Server do provide wait statistics through the undocumented dbcc sqlperf(waitstat) command. However, apart from two smart people in the MS SQL Customer Advisory Team who started to write and present on this subject a couple of years ago (see references), Microsoft never really took the trouble to document or to promote the use of this command. Interestingly enough, most of the articles I've seen so far use wait events almost exclusively for detecting and solving locking and blocking issues. I haven't come across a paper that used them for 'simple' response time or other performance analysis.
In SQL Server2005, wait events are exposed in the DMV, sys.dm_os_wait_stats. This DMV shows the names, counts, and wait times of wait events encountered by the SQL Server engine, or to be exact the SQLOS. The SQLOS is a layer within SQL Server that, among many other things, takes care of scheduling workloads on worker processes. In SQL Server 2000 and before, this was done via the UMS, the User Mode Scheduler. This is now an integrated part of the SQLOS (see references for SQLOS and UMS, Slava Oks and Ken Henderson).
One column of sys.dm_os_wait_stats needs a little extra explanation: signal wait time. This time represents the time that the actual wait event finished, and the time the task is scheduled to run on the scheduler again. On busy schedulers this signal wait time can be an indication of CPU pressure.
Unfortunately, SQL Server only maintains wait event data at the server level. Wait events are also exposed in the DMV, sys.dm_os_waiting_tasks, but only for the duration of the wait event, which is in many cases just milleseconds (unless you ran into severe locking problems). In addition, to using dm_os_wait_stats, alternative and interesting ways of looking at live systems, can be sampling of dm_os_waiting_tasks or joining againstdm_exec_sql_text or dm_exec_sql_plan, using task_address, to get complete overviews of which queries and plans cause possible excessive waits.
Hopefully this example will demonstrate the power of wait events combined with CPU data. Two stored procedures are used to collect wait event and CPU data. You can access the scripts to create these procedures from the links below, or from the "Code Download" link at the top of this article. These stored procedures take snapshot copies ofsys.dm_os_wait_stats and sys.dm_exec_sessions. At the beginning of a test workload you executebegin_waitstats, and after the test workload is finished you execute end_waitstats. The end_waitstats procedure outputs the difference between the starting and ending snapshots.
The code to generate the workload is as follows:
SET ``nocount ``ON
DECLARE @rows INT
DECLARE @row INT
DECLARE @count INT
SELECT @rows = 100000
SELECT @row = 0
SELECT @count = 0
WHILE @row < @rows
INSERT INTO t100k
``SELECT @row = @row 1
``IF @count > 100
SELECT @count=@count 1
This code comprises a simple loop that creates a table and inserts 100,000 rows into it, committing every 100 rows. Note that you end your test workload with a GO. I found that the data that feeds the sys.dm_exec_sessionview is updated only after the batch is finished.
While executing this loop, I have an IOMeter (see references) program running that is generating 8K random reads on the transaction log disk belonging to the database in which the t100k table lives. It is running at full speed, with no queue and no pause between reads. This generates about 150 reads/sec on an idle system. This is all run on the same single CPU box on which SQL Server is running, with one SQL Scheduler.
The output of this query looks as follows (for clarity, I omitted non-relevant data)
wait_type waits wait_time signal_wait_time
ASYNC_NETWORK_IO 589 150 10
WRITELOG 998 18317 10
session_id cpu_time tot_sched_time elapsed_time
53 2123 2322 20669
NOTE:You can use the documentation in Books Online, SQL Server Language Reference: to find out the meaning of the above wait types.
What you can see here is that this query had an elapsed time (response time) of 20669 milliseconds (all times are in milliseconds). It spends 2123 ms burning CPU cycles so, according to the R=S W formula, for the rest of the time it must have been waiting.
As you can see, the majority of the wait time is consumed by a wait type called WRITELOG. This is the time spent waiting for log information to be written to the transaction log file. The count ('waits' column) is equal, more or less, to the number of rows we inserted in the loop.
The other wait, ASYNC_NETWORK_IO, is caused by the SQL Server client program dealing with commit feedback; SQL Server needs to wait for the client to accept the data. If you look at the wait time for this event, it's very small and insignificant for this demo.
Now if you add up the (CPU) service time of 2123 and the wait time of 18317 150, you end up with 20590 ms, which is pretty close to the 20669 response (elapsed) time, taken from sys.dm_os_exec_sessions.
The average wait time for the WRITELOG wait event is 18317/998= 18ms. This is good to know, and we will use that as a reference for the next example, where we will 'optimize' the transaction log write performance
In this example, we execute the same loop, with IOMeter running the same load of around 80 random 8K reads per second on the same disk transaction log disk, but this time every read is delayed for 10 ms. This gives more headroom for the Logwriter to do its job. This is what happens to the times:
wait_type waits wait_time signal_wait_time
ASYNC_NETWORK_IO 586 120 0
WRITELOG 998 7841 10
session_id cpu_time tot_sched_time elapsed_time
53 2453 2288 10464
What you see here is that the wait time for the log is reduced to 7841 ms, and the CPU time is relatively unchanged at 2453 ms. The total elapsed time is 10464 ms.
You see that the times don't exactly match. This trouble is, on this x86 box, the precision of the Windows timing is 10 ms, so this introduces all kinds of measurement errors. But in most cases you will see that this is within the 10% range. Even here you can see that the time this session was on the scheduler doing work (2288 ms) is more than the CPU use time, which shouldn't happen.
Anyway, the average wait time is now back to almost 8 ms per WRITELOG, so we did a pretty good job optimizing. What counts for the end user is, of course, the response time, which we've reducded to 10 seconds, compared to 20 seconds previously.
If we take out the IOMeter load completely, this is what we see:
wait_type waits wait_time signal_wait_time
ASYNC_NETWORK_IO 598 70 0
WRITELOG 998 160 0
session_id cpu_time tot_sched_time elapsed_time
53 2293 2245 2584
Hardly any wait time, mostly CPU and a response time of 2.5 second. So there's your time!
The great thing about these wait event statistics and CPU time measurements is that it takes the guessing out of the game. If you can measure what your application is doing with your system, then you can act accordingly.
For instance, if your SQL Server data is waiting for IO (which might be something like PAGEIOLATCHX waits) 90% of the time, and is only on the CPU 5% of the time, then buying a bigger box with the fastest CPUs won't achieve anything: you need to speed up IO response times, or reduce IO.
In our example, I tried to show that if you measure high log write times, then you should go look for ways to speed up your log drive(s), or take away the load on the log drives from other processes or queries.
As I mentioned at the start, measuring what is happening is always the best course of action. Don't rely on cache hit ratios, or best practices, or worst of all, guesswork.
select session_id, most_recent_session_id, net_transport, auth_scheme, client_net_address, client_tcp_port, local_net_address, local_tcp_port from sys.dm_exec_connections
我看到的这个异常的备份操作，是将备份数据存储到远程Server上，打开ResouceMonitor（点击Windows R，输入resmon），发现Disk Activity是2MB-4MB之间，而Network Activity在18MB-46MB之间，如图：
One of the biggest problems, I think, is the fact that the statistics are collected and exposed 'server wide' (technically they are collected per SQL Scheduler, but not exposed). This means you can only use them to say something sensible about resource utilization and response time composition on a server-wide basis. This is simply not enough, unless you have the luxury of testing your application and SQL statements on an isolated server, as in our example. But, of course, it's often hard or impossible to isolate and replicate production problems on an isolated test server.
What you really need is a "per session" or even "per statement" resource (wait and CPU usage) breakdown. Although I think it's very easy for Microsoft to implement things like this, they simply don't do it.
Another issue is that there can be quite a bit of asynchronous work going on in SQL Server, something that the Oracle world doesn't suffer from because of their process based UNIX implementation. For example, if you do a select from a table returning row data to a client, SQL Server can asynchronously scan your table, process the data, issue more I/O's and simultaneously send network packets to the client. This makes the R=S W method slightly more difficult to use with SQL Server than it is with Oracle.
In the past, I have hacked into SQL Server to collect the statistics I needed, per user and per session, and performed session tracing including sql-statements, batch statistics and wait events. The collection and presentation are done by external stored procedures. I still have a small website up () where you can see examples, a presentation and a paper on the techniques I used, along with download code to test them yourself on SQL Server 2000.
My tools come with a big disclaimer: the code is based on call replacing at the machine code level, which can be very tricky and is, of course, totally unsupported in a production environment.
However, just to whet your appetitive for the sort of power you gain from being able to measure at the session level, consider the following example of what these SQL 2000 tools can do. You can pick any session (by spid), and show the wait event and CPU statistics; even for Parallel Queries it will show a breakdown per Execution Context.
A user session, executes a script that contains one CPU intensive query and one physical read intensive query is ran on a 100Mhz CPU machine (100Mhz?! yes, that old slow stuff is still great for CPU related testing purposes). There is no concurrent work going on.
The response time for this script is 160 seconds. Uisng my per session tools, you can see exactly where those 160 seconds were spent:
Spid EC WaitDesc Time(ms) Count WaitSignalTime(ms)
55 0 CPU 146699 499 0
55 0 PAGEIOLATCH_SH 13101 483 173
55 0 PAGEIOLATCH_UP 20 2 0
The CPU time is about 146.7 seconds, and the wait time for physical I/O (新葡亰496net，PAGEIOLATCH_xx represents physical I/O) is around 13.1 seconds. Once you know that the major part of the response time for this user consists of CPU time then you can see immediately that upgrading CPU (speed) might help.
Following are the results obtained by doubling the CPU speed (200 MHz) and running the same script again:
Spid EC WaitDesc Time(ms) Count WaitSignalTime(ms)
55 0 CPU 73579 522 0
55 0 PAGEIOLATCH_SH 15706 498 100
55 0 PAGEIOLATCH_UP 28 2 0
CPU time is almost halved, as expected since we doubled the CPU speed and the wait time for physical I/O is about 15.7 seconds. The overall response time is down to 90 seconds.
Enabling a basic wait event trace produces the following output:
Startbatch tim=3433161, tid=0x43c, spid=51 ecid=0
user: 333 krnl: 69 ticks: 268470845
SqlExecute tim=3433162, tid=0x43c, spid=51, ecid=0,
len=176, Stmt=SELECT COUNT(*) FROM t1 a
INNER LOOP JOIN t1 b
ON b.c1 = a.c1 option (maxdop 1)
Waitaftersignal tim=3433197, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=20, sigt=0, res=7:1:15
Waitaftersignal tim=3433211, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=13, sigt=0, res=7:1:34
Waitaftersignal tim=3433222, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=11, sigt=0, res=7:1:76
Waitaftersignal tim=3433231, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=9, sigt=0, res=7:1:17
Waitaftersignal tim=3433237, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=5, sigt=0, res=7:1:74
Waitaftersignal tim=3433248, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=8, sigt=0, res=7:1:27
Waitaftersignal tim=3433257, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=9, sigt=0, res=7:1:90
Waitaftersignal tim=3442799, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=14, sigt=0
Waitaftersignal tim=3506860, tid=0x43c, spid=51, ecid=0,
WT=0x422, waited=16, sigt=0, res=2:1:75
Waitaftersignal tim=3506865, tid=0x43c, spid=51, ecid=0,
WT=0x423, waited=4, sigt=0, res=2:1:2
Batchsummary tim=3506866, tid=0x43c, spid=51, ecid=0,
user=72394, krnl=56, ela=73705
EndBatchOrSubproc tim=3506866, tid=0x43c, spid=51, ecid=0,
(totThread:) user=72727, krnl=125
TotIOForBatch(Spid) tim=3506866, tid=0x43c, spid=51, ecid=0,
The SqlExecute line shows the query being executed. Each wait event generates a line with a wait type and an elapsed wait time. When the statement is finished, it's easy to see the CPU consumption of 72727 ms, which can be attributed fully to the LIO count: the statement generated a huge amount of logical I/O, out of the buffer cache I/O's, which consume only CPU cycles.
I hope this at least gives you a feel for the potential power of these techniques. I do have a version for the first SQL Server 2005 release, but I haven't spend much time developing it, and bringing it up to the same level as the SQL Server 2000 code, so it's not on there (yet?).
Despite the fact that DMVs supply only server-level (and sometimes database-level) statistics, and don't drill down to the session level, they are still a very useful tool for performance profiling and diagnosis. Other interesting scenarios are parallel queries where multiple execution contexts are working for one SPID or session in SS2005. In that case you can not simply add all the wait and CPU times together and match with the response time, but you can add times at the Execution Context level.
In a next article I will show some more examples of dealing with different wait events and how to interpret them. Both SQL Server 2000 and 2005 will be addressed.
这说明，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是瓶颈。
Microsoft SQL Server Development Customer Advisory Team:
Unfortunately the two guys, Gert Drapers and Tom Davidson, who published and presented on the wait event subject have both moved on to other teams. Gert has some presentations available on his website:
Here also has a very good presentation on the subject and describes a lot of SQL Server 2005 wait events here:
This wait type is where SQL Server has sent some data to a client through TDS.aspx) and is waiting for the client to acknowledge that is has consumed the data, and can also show up with transaction replication if the Log Reader Agent job is running slowly for some reason.
分析Disk IO的性能，最好的方法是分析Performance Counter。打开Local Server的Performance Monitor（点击Windows R，输入perfmon），没有记录Data Collection，这样没有办法进行深入的分析了，下次遇到时，继续分析。
Slava Oks' Blog (where I just read he left his team also!):
Slava has some very good papers on the SQLOS subject, mostly focusing on memory management, but also on the scheduler. He also wrote excellent chapter in a new book edited by Ken Henderson: SQL Server 2005 Practical Troubleshooting. The same book has a very good chapter on SQLOS and scheduling issues, by Sameer Tejani, and a chapter called 'Waiting and blocking issues' by Santeri Voutilainen.
Ken Henderson also wrote 'The Guru's Guide to SQL Server: Architecture and Internals'. It is a bit of a strange book in my opinion, which probably should have been two books I think. The first half deals with SQL Server 2000 Internals very well, but the seconds half deals with all kinds of subjects, on a more superficial level. Some of the chapters of this book are available on MSDN. I am looking forward to his SQL Server 2005 version.
总之：在数据库备份或还原的过程中，出现长时间的ASYNC_IO_COMPLETION 等待，表示backup/restore操作正在等待获取IO资源，导致backup/restore 进程处于挂起状态（suspended），只有获取到IO资源，该操作才会继续进行下去。
IOMeter is an IO stress and measurement tool developed by Intel. It is now an Open Source tool, and freely downloadable from .
(Books Online description: “Occurs on network writes when the task is blocked behind the network. Verify that the client is processing data from the server.”)
在执行长时间的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的传输能力是系统的短板。
This wait type is never indicative of a problem with SQL Server, and the vast majority of the time it is nothing to do with the network either (it’s very common to see advice stating that this is a network issue). A simple test for network issues is to test the ping time between the SQL Server and the client/application/web server, and if the ping time is close to the average wait time, then the wait is because of the network (which may just be the normal network latency, not necessarily a problem).
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
There is usually nothing that you can do with your SQL Server code that will affect this wait type. There are a few causes of this on the client side, including:
推荐阅读《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:
We can also corelate this wait type between Memory pressure and Disk IO subsystem issues.
On the SQL Server side, the only possibility I know of for causing this is using MARS (Multiple Active Result Sets) with large result sets.
You can demonstrate this wait type easily by running a query with a large result set through SSMS on the SQL Server itself, with no network involved.
ASYNC_IO_COMPLETION Wait type
Some other things you can try:
This wait type is when a thread is calling the Windows WaitForSingleObject.aspx) function for synchronization with an external client process that is communicating using that object.
(Books Online description: N/A --表示联机丛书没有说明)
这个等待事件表示一个线程正在向外部客户端进程同步某个对象的数据，因此出现此种等待。一般此种等待出现在SQL Server 2012及以上的版本，以前用ASYNC_NETWORK_IO代替。
This wait type is commonly seen in conjunction（同时出现） with ASYNC_NETWORK_IO, depending on the network transport used to communicate with the client, so to troubleshoot, follow the same steps as for ASYNC_NETWORK_IO.
Note that when a thread calls out to Windows, the thread changes from non-preemptive (SQL Server controls the thread) to preemptive (Windows controls the thread) mode. The thread’s state will be listed as RUNNING, as SQL Server doesn’t know what Windows is doing with the thread.
注意，当一个连接线程被从SQL Server控制（非抢占式）到被Windows控制（抢占式）的后，线程的状态就会变为running,此时SQL Server并不知道windows在对此线程做什么。
关于抢占式与非抢占式的区别，参考官网博客中关SQL OS与Windows OS对线程的不同处理方式的介绍。