{"id":4342,"date":"2014-03-19T21:40:42","date_gmt":"2014-03-20T04:40:42","guid":{"rendered":"http:\/\/3.209.169.194\/blogs\/paul\/?p=4342"},"modified":"2016-05-12T08:11:09","modified_gmt":"2016-05-12T15:11:09","slug":"cause-high-duration-async_io_completion-waits","status":"publish","type":"post","link":"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/","title":{"rendered":"A cause of high-duration ASYNC_IO_COMPLETION waits"},"content":{"rendered":"

[Edit 2016: Check out my new resource – a comprehensive library of all wait types and latch classes – see here<\/a>.]<\/p>\n

In some of the wait statistics data I’ve been analyzing, some servers have been showing very long ASYNC_IO_COMPLETION<\/a><\/em> waits, which I had a hunch about but wanted proof.<\/p>\n

The official definition of ASYNC_IO_COMPLETION<\/em> is ‘Occurs when a task is waiting for I\/Os to finish.’ Very helpful – NOT!<\/p>\n

Using the code I blogged yesterday (How to determine what causes a particular wait type<\/a>), I set up an XEvent session to track all the ASYNC_IO_COMPLETION<\/em> waits and their durations, changing to a ring_buffer target so I get the wait durations too:<\/p>\n

\r\nCREATE EVENT SESSION [InvestigateWaits] ON SERVER\r\nADD EVENT [sqlos].[wait_info]\r\n(\r\n    ACTION ([package0].[callstack])\r\n    WHERE [wait_type] = 98 -- ASYNC_IO_COMPLETION only, same on all versions\r\n    AND [opcode] = 1 -- Just the end wait events\r\n)\r\nADD TARGET [package0].[ring_buffer]\r\nWITH\r\n(\r\n    MAX_MEMORY = 50 MB,\r\n    MAX_DISPATCH_LATENCY = 5 SECONDS\r\n)\r\nGO\r\n<\/pre>\n
And then I ran some commands. Although ASYNC_IO_COMPLETION<\/em> pops up in various locations, the long-running wait happens during a data backup. In fact, three ASYNC_IO_COMPLETION<\/em> waits occurred during each full backup I ran:<\/p>\n
\r\n.\r\n<snip>\r\n.\r\n    <data name="duration">\r\n      <type name="uint64" package="package0" \/>\r\n      <value>7<\/value>\r\n    <\/data>\r\n.\r\n<snip>\r\n.\r\nXeSosPkg::wait_info::Publish+138 [ @ 0+0x0\r\nSOS_Scheduler::UpdateWaitTimeStats+30c [ @ 0+0x0\r\nSOS_Task::PostWait+90 [ @ 0+0x0\r\nEventInternal<SuspendQueueSLock>::Wait+1f9 [ @ 0+0x0\r\nAsynchronousDiskPool::WaitUntilDoneOrTimeout+fb [ @ 0+0x0\r\nCheckpointDB2+2cd [ @ 0+0x0\r\nBackupDatabaseOperation::PerformDataCopySteps+c2 [ @ 0+0x0\r\nBackupEntry::BackupDatabase+2ca [ @ 0+0x0\r\nCStmtDumpDb::XretExecute+ef [ @ 0+0x0\r\nCMsqlExecContext::ExecuteStmts<1,1>+400 [ @ 0+0x0\r\nCMsqlExecContext::FExecute+a33 [ @ 0+0x0\r\nCSQLSource::Execute+866 [ @ 0+0x0\r\nprocess_request+73c [ @ 0+0x0\r\nprocess_commands+51c [ @ 0+0x0\r\nSOS_Task::Param::Execute+21e [ @ 0+0x0\r\nSOS_Scheduler::RunTask+a8 [ @ 0+0x0\r\nSOS_Scheduler::ProcessTasks+29a [ @ 0+0x0\r\nSchedulerManager::WorkerEntryPoint+261 [ @ 0+0x0\r\nSystemThread::RunWorker+8f [ @ 0+0x0\r\nSystemThreadDispatcher::ProcessWorker+3c8 [ @ 0+0x0\r\nSchedulerManager::ThreadEntryPoint+236 [ @ 0+0x0\r\nBaseThreadInitThunk+d [ @ 0+0x0\r\nRtlUserThreadStart+21 [ @ 0+0x0<\/value\r\n.\r\n<snip>\r\n.\r\n    <data name="duration">\r\n      <type name="uint64" package="package0" \/>\r\n      <value>0<\/value>\r\n    <\/data>\r\n.\r\n<snip>\r\n.\r\nSOS_Scheduler::UpdateWaitTimeStats+30c [ @ 0+0x0\r\nSOS_Task::PostWait+90 [ @ 0+0x0\r\nEventInternal<SuspendQueueSLock>::Wait+1f9 [ @ 0+0x0\r\nAsynchronousDiskPool::WaitUntilDoneOrTimeout+fb [ @ 0+0x0\r\nBackupOperation::GenerateExtentMaps+34c [ @ 0+0x0\r\nBackupDatabaseOperation::PerformDataCopySteps+179 [ @ 0+0x0\r\nBackupEntry::BackupDatabase+2ca [ @ 0+0x0\r\nCStmtDumpDb::XretExecute+ef [ @ 0+0x0\r\nCMsqlExecContext::ExecuteStmts<1,1>+400 [ @ 0+0x0\r\nCMsqlExecContext::FExecute+a33 [ @ 0+0x0\r\nCSQLSource::Execute+866 [ @ 0+0x0\r\nprocess_request+73c [ @ 0+0x0\r\nprocess_commands+51c [ @ 0+0x0\r\nSOS_Task::Param::Execute+21e [ @ 0+0x0\r\nSOS_Scheduler::RunTask+a8 [ @ 0+0x0\r\nSOS_Scheduler::ProcessTasks+29a [ @ 0+0x0\r\nSchedulerManager::WorkerEntryPoint+261 [ @ 0+0x0\r\nSystemThread::RunWorker+8f [ @ 0+0x0\r\nSystemThreadDispatcher::ProcessWorker+3c8 [ @ 0+0x0\r\nSchedulerManager::ThreadEntryPoint+236 [ @ 0+0x0\r\nBaseThreadInitThunk+d [ @ 0+0x0\r\nRtlUserThreadStart+21 [ @ 0+0x0<\/value>\r\n.\r\n<snip>\r\n.\r\n    <data name="duration">\r\n      <type name="uint64" package="package0" \/>\r\n      <value>1958<\/value>\r\n    <\/data>\r\n.\r\n<snip>\r\n.\r\nXeSosPkg::wait_info::Publish+138 [ @ 0+0x0\r\nSOS_Scheduler::UpdateWaitTimeStats+30c [ @ 0+0x0\r\nSOS_Task::PostWait+90 [ @ 0+0x0\r\nEventInternal<SuspendQueueSLock>::Wait+1f9 [ @ 0+0x0\r\nAsynchronousDiskPool::WaitUntilDoneOrTimeout+fb [ @ 0+0x0\r\nBackupOperation::BackupData+272 [ @ 0+0x0\r\nBackupEntry::BackupDatabase+2ca [ @ 0+0x0\r\nCStmtDumpDb::XretExecute+ef [ @ 0+0x0\r\nCMsqlExecContext::ExecuteStmts<1,1>+400 [ @ 0+0x0\r\nCMsqlExecContext::FExecute+a33 [ @ 0+0x0\r\nCSQLSource::Execute+866 [ @ 0+0x0\r\nprocess_request+73c [ @ 0+0x0\r\nprocess_commands+51c [ @ 0+0x0\r\nSOS_Task::Param::Execute+21e [ @ 0+0x0\r\nSOS_Scheduler::RunTask+a8 [ @ 0+0x0\r\nSOS_Scheduler::ProcessTasks+29a [ @ 0+0x0\r\nSchedulerManager::WorkerEntryPoint+261 [ @ 0+0x0\r\nSystemThread::RunWorker+8f [ @ 0+0x0\r\nSystemThreadDispatcher::ProcessWorker+3c8 [ @ 0+0x0\r\nSchedulerManager::ThreadEntryPoint+236 [ @ 0+0x0\r\nBaseThreadInitThunk+d [ @ 0+0x0\r\nRtlUserThreadStart+21 [ @ 0+0x0\r\n<\/pre>\n
One wait for each of the following:<\/p>\n
    \n
  1. The start of the initial checkpoint at the start of the backup<\/li>\n
  2. Reading the GAM pages from the data files to figure out what to back up<\/li>\n
  3. Reading the actual data from the data files (the writes to the backup files are tracked by BACKUPIO<\/em> waits)<\/li>\n<\/ol>\n
    The third wait is for almost the full duration of the backup. As there are three of these per data backup, the per wait average will be a bit skewed.<\/p>\n
    The aggregate waits for the single backup operation are as follows, showing the BACKUPIO<\/a><\/em> and BACKUPBUFFER<\/a><\/em> waits each adding up to almost the total backup run time of about 2 seconds:<\/p>\n
    \r\nWaitType                Wait_S   Resource_S   Signal_S   WaitCount   Percentage   AvgWait_S   AvgRes_S   AvgSig_S\r\nBACKUPBUFFER            2.69     2.68         0.01       505         37.23        0.0053      0.0053     0.0000\r\nASYNC_IO_COMPLETION     2.33     2.33         0.00       3           32.29        0.7773      0.7773     0.0000\r\nBACKUPIO                1.96     1.96         0.00       171         27.08        0.0114      0.0114     0.0000\r\nPREEMPTIVE_OS_WRITEFILE\t0.20     0.20         0.00       2           2.78         0.1005      0.1005     0.0000\r\nBACKUPTHREAD            0.04     0.04         0.00       15          0.50         0.0024      0.0024     0.0000\r\nPREEMPTIVE_OS_FILEOPS   0.00     0.00         0.00       5           0.06         0.0008      0.0008     0.0000\r\nWRITELOG                0.00     0.00         0.00       11          0.06         0.0004      0.0004     0.0000\r\n<\/pre>\n
    So there you have it. XEvents and a little internals knowledge let us understand what could otherwise be seen as a worrying high-duration wait type. Long-duration ASYNC_IO_COMPLETION<\/em> waits commonly are from data backups (they don’t happen for regular log backups).<\/p>\n
    Enjoy!<\/p>\n","protected":false},"excerpt":{"rendered":"
    [Edit 2016: Check out my new resource – a comprehensive library of all wait types and latch classes – see here.] In some of the wait statistics data I’ve been analyzing, some servers have been showing very long ASYNC_IO_COMPLETION waits, which I had a hunch about but wanted proof. The official definition of ASYNC_IO_COMPLETION is […]<\/p>\n","protected":false},"author":5,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[66,101],"tags":[],"class_list":["post-4342","post","type-post","status-publish","format-standard","hentry","category-performance-tuning","category-wait-stats"],"yoast_head":"\nA cause of high-duration ASYNC_IO_COMPLETION waits - Paul S. Randal<\/title>\n<meta name=\"robots\" content=\"index, follow, max-snippet:-1, max-image-preview:large, max-video-preview:-1\" \/>\n<link rel=\"canonical\" href=\"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"A cause of high-duration ASYNC_IO_COMPLETION waits - Paul S. Randal\" \/>\n<meta property=\"og:description\" content=\"[Edit 2016: Check out my new resource – a comprehensive library of all wait types and latch classes – see here.] In some of the wait statistics data I’ve been analyzing, some servers have been showing very long ASYNC_IO_COMPLETION waits, which I had a hunch about but wanted proof. The official definition of ASYNC_IO_COMPLETION is […]\" \/>\n<meta property=\"og:url\" content=\"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/\" \/>\n<meta property=\"og:site_name\" content=\"Paul S. Randal\" \/>\n<meta property=\"article:published_time\" content=\"2014-03-20T04:40:42+00:00\" \/>\n<meta property=\"article:modified_time\" content=\"2016-05-12T15:11:09+00:00\" \/>\n<meta name=\"author\" content=\"Paul Randal\" \/>\n<meta name=\"twitter:label1\" content=\"Written by\" \/>\n\t<meta name=\"twitter:data1\" content=\"Paul Randal\" \/>\n\t<meta name=\"twitter:label2\" content=\"Est. reading time\" \/>\n\t<meta name=\"twitter:data2\" content=\"4 minutes\" \/>\n<script type=\"application\/ld+json\" class=\"yoast-schema-graph\">{\"@context\":\"https:\/\/schema.org\",\"@graph\":[{\"@type\":\"WebPage\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/\",\"url\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/\",\"name\":\"A cause of high-duration ASYNC_IO_COMPLETION waits - Paul S. Randal\",\"isPartOf\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/#website\"},\"datePublished\":\"2014-03-20T04:40:42+00:00\",\"dateModified\":\"2016-05-12T15:11:09+00:00\",\"author\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/#\/schema\/person\/ffcec826c18782e1e0adf173826a7fce\"},\"breadcrumb\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Home\",\"item\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"A cause of high-duration ASYNC_IO_COMPLETION waits\"}]},{\"@type\":\"WebSite\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/#website\",\"url\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/\",\"name\":\"Paul S. Randal\",\"description\":\"In Recovery...\",\"potentialAction\":[{\"@type\":\"SearchAction\",\"target\":{\"@type\":\"EntryPoint\",\"urlTemplate\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/?s={search_term_string}\"},\"query-input\":{\"@type\":\"PropertyValueSpecification\",\"valueRequired\":true,\"valueName\":\"search_term_string\"}}],\"inLanguage\":\"en-US\"},{\"@type\":\"Person\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/#\/schema\/person\/ffcec826c18782e1e0adf173826a7fce\",\"name\":\"Paul Randal\",\"image\":{\"@type\":\"ImageObject\",\"inLanguage\":\"en-US\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/#\/schema\/person\/image\/\",\"url\":\"https:\/\/secure.gravatar.com\/avatar\/0b6a266bba2f088f2551ef529293001bd73bf026bc1908b9866728c062beeeb6?s=96&d=mm&r=g\",\"contentUrl\":\"https:\/\/secure.gravatar.com\/avatar\/0b6a266bba2f088f2551ef529293001bd73bf026bc1908b9866728c062beeeb6?s=96&d=mm&r=g\",\"caption\":\"Paul Randal\"},\"sameAs\":[\"http:\/\/3.209.169.194\/blogs\/paul\"],\"url\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/author\/paul\/\"}]}<\/script>\n<!-- \/ Yoast SEO plugin. -->","yoast_head_json":{"title":"A cause of high-duration ASYNC_IO_COMPLETION waits - Paul S. Randal","robots":{"index":"index","follow":"follow","max-snippet":"max-snippet:-1","max-image-preview":"max-image-preview:large","max-video-preview":"max-video-preview:-1"},"canonical":"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/","og_locale":"en_US","og_type":"article","og_title":"A cause of high-duration ASYNC_IO_COMPLETION waits - Paul S. Randal","og_description":"[Edit 2016: Check out my new resource – a comprehensive library of all wait types and latch classes – see here.] In some of the wait statistics data I’ve been analyzing, some servers have been showing very long ASYNC_IO_COMPLETION waits, which I had a hunch about but wanted proof. The official definition of ASYNC_IO_COMPLETION is […]","og_url":"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/","og_site_name":"Paul S. Randal","article_published_time":"2014-03-20T04:40:42+00:00","article_modified_time":"2016-05-12T15:11:09+00:00","author":"Paul Randal","twitter_misc":{"Written by":"Paul Randal","Est. reading time":"4 minutes"},"schema":{"@context":"https:\/\/schema.org","@graph":[{"@type":"WebPage","@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/","url":"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/","name":"A cause of high-duration ASYNC_IO_COMPLETION waits - Paul S. Randal","isPartOf":{"@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/#website"},"datePublished":"2014-03-20T04:40:42+00:00","dateModified":"2016-05-12T15:11:09+00:00","author":{"@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/#\/schema\/person\/ffcec826c18782e1e0adf173826a7fce"},"breadcrumb":{"@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/cause-high-duration-async_io_completion-waits\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Home","item":"https:\/\/www.sqlskills.com\/blogs\/paul\/"},{"@type":"ListItem","position":2,"name":"A cause of high-duration ASYNC_IO_COMPLETION waits"}]},{"@type":"WebSite","@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/#website","url":"https:\/\/www.sqlskills.com\/blogs\/paul\/","name":"Paul S. Randal","description":"In Recovery...","potentialAction":[{"@type":"SearchAction","target":{"@type":"EntryPoint","urlTemplate":"https:\/\/www.sqlskills.com\/blogs\/paul\/?s={search_term_string}"},"query-input":{"@type":"PropertyValueSpecification","valueRequired":true,"valueName":"search_term_string"}}],"inLanguage":"en-US"},{"@type":"Person","@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/#\/schema\/person\/ffcec826c18782e1e0adf173826a7fce","name":"Paul Randal","image":{"@type":"ImageObject","inLanguage":"en-US","@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/#\/schema\/person\/image\/","url":"https:\/\/secure.gravatar.com\/avatar\/0b6a266bba2f088f2551ef529293001bd73bf026bc1908b9866728c062beeeb6?s=96&d=mm&r=g","contentUrl":"https:\/\/secure.gravatar.com\/avatar\/0b6a266bba2f088f2551ef529293001bd73bf026bc1908b9866728c062beeeb6?s=96&d=mm&r=g","caption":"Paul Randal"},"sameAs":["http:\/\/3.209.169.194\/blogs\/paul"],"url":"https:\/\/www.sqlskills.com\/blogs\/paul\/author\/paul\/"}]}},"_links":{"self":[{"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/posts\/4342","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/users\/5"}],"replies":[{"embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/comments?post=4342"}],"version-history":[{"count":0,"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/posts\/4342\/revisions"}],"wp:attachment":[{"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/media?parent=4342"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/categories?post=4342"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/tags?post=4342"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}