{"id":553,"date":"2011-07-11T09:00:00","date_gmt":"2011-07-11T09:00:00","guid":{"rendered":"\/blogs\/paul\/post\/Capturing-wait-stats-for-a-single-operation.aspx"},"modified":"2017-04-13T09:50:50","modified_gmt":"2017-04-13T16:50:50","slug":"capturing-wait-stats-for-a-single-operation","status":"publish","type":"post","link":"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/","title":{"rendered":"Capturing wait stats for a single operation"},"content":{"rendered":"

\nThis is a performance tuning post that's been on my to-do list for quite a while. Wait stats analysis is a great way of looking at the symptoms of performance problems (see my <\/font>Wait Stats category<\/font><\/a> for more posts on this) but using the sys.dm_os_wait_stats<\/font> DMV shows everything that's happening on a server. If you want to see what waits are occuring because of a single query or operation on a production system (e.g. the effect of MAXDOP<\/font> hints on number and length of CXPACKET<\/font> waits for a query) then using the DMV isn't usually feasible – you'd need to clear the wait stats and then have nothing else running on the system except the query\/operation you want to investigate. The way to do it is with extended events.<\/font>\n<\/p>\n

\nWhenever a thread state changes to SUSPENDED because of a wait, the wait_info<\/font> event from the sqlos<\/font> event package fires to mark the beginning of the wait. When the thread gets back on the CPU again, the wait_info<\/font> event fires again, noting the total wait time and the signal wait time (spent on the RUNNABLE queue). Just like with the DMV, we need to calculate the resource wait time (spent being SUSPENDED) ourselves.<\/font>\n<\/p>\n

\nHere's a simple example for you – imagine we want to investigate the waits that occur during an index rebuild. First thing is to create the event session:<\/font>\n<\/p>\n

\n

\n\t— Drop the session if it exists.
\n\tIF EXISTS (SELECT * FROM sys.server_event_sessions WHERE name = 'MonitorWaits')
\n\t    DROP EVENT SESSION MonitorWaits ON SERVER
\n\tGO<\/font>\n\t<\/p>\n

\n\tCREATE EVENT SESSION MonitorWaits ON SERVER
\n\tADD EVENT sqlos.wait_info
\n\t    (WHERE sqlserver.session_id = 53 \/* session_id of connection to monitor *\/)
\n\tADD TARGET package0.asynchronous_file_target
\n\t    (SET FILENAME = N'C:\\SQLskills\\EE_WaitStats.xel',
\n\t    METADATAFILE = N'C:\\SQLskills\\EE_WaitStats.xem')
\n\tWITH (max_dispatch_latency = 1 seconds);
\n\tGO<\/font>\n\t<\/p>\n<\/blockquote>\n

\nYou'll need to plug in the session ID of the SQL Server connection where you'll run the operation under investigation. I created a dummy production database with a table and some data so I can monitor the waits from rebuilding its clustered index.<\/font>\n<\/p>\n

\nYou can also filter out any wait types you're not interested in by adding another predicate to the session that filters on the sqlos.wait_type<\/font>. You'll need to specify numbers, and you can list the mapping between numbers and human-understandable wait types using this code:<\/font>\n<\/p>\n

\n

\n\tSELECT xmv.map_key, xmv.map_value
\n\tFROM sys.dm_xe_map_values xmv
\n\tJOIN sys.dm_xe_packages xp
\n\t    ON xmv.object_package_guid = xp.guid
\n\tWHERE xmv.name = 'wait_types'
\n\t    AND xp.name = 'sqlos';
\n\tGO<\/font>\n\t<\/p>\n<\/blockquote>\n

\nNow I turn on the session and run my rebuild.<\/font>\n<\/p>\n

\n

\n\t— Start the session
\n\tALTER EVENT SESSION MonitorWaits ON SERVER STATE = START;
\n\tGO<\/font>\n\t<\/p>\n

\n\t— Go do the query<\/font>\n\t<\/p>\n

\n\t— Stop the event session
\n\tALTER EVENT SESSION MonitorWaits ON SERVER STATE = STOP;
\n\tGO<\/font>\n\t<\/p>\n<\/blockquote>\n

\nAnd then I can see how many events fired:<\/font>\n<\/p>\n

\n

\n\tSELECT COUNT (*)
\n\tFROM sys.fn_xe_file_target_read_file
\n\t    ('C:\\SQLskills\\EE_WaitStats*.xel',
\n\t    'C:\\SQLskills\\EE_WaitStats*.xem', null, null);
\n\tGO<\/font>\n\t<\/p>\n

\n\t13324<\/font>\n\t<\/p>\n<\/blockquote>\n

\nAnd then pull them into a temporary table and aggregate them (various ways of doing this, I prefer this one):<\/font>\n<\/p>\n

\n

\n\t— Create intermediate temp table for raw event data
\n\tCREATE TABLE #RawEventData (
\n\t    Rowid  INT IDENTITY PRIMARY KEY,
\n\t    event_data XML);
\n\t 
\n\tGO<\/font>\n\t<\/p>\n

\n\t— Read the file data into intermediate temp table
\n\tINSERT INTO #RawEventData (event_data)
\n\tSELECT
\n\t    CAST (event_data AS XML) AS event_data
\n\tFROM sys.fn_xe_file_target_read_file (
\n\t    'C:\\SQLskills\\EE_WaitStats*.xel',
\n\t    'C:\\SQLskills\\EE_WaitStats*.xem', null, null);
\n\tGO<\/font>\n\t<\/p>\n

\n\tSELECT
\n\t    waits.[Wait Type],
\n\t    COUNT (*) AS [Wait Count],
\n\t    SUM (waits.[Duration]) AS [Total Wait Time (ms)],
\n\t    SUM (waits.[Duration]) – SUM (waits.[Signal Duration]) AS [Total Resource Wait Time (ms)],
\n\t    SUM (waits.[Signal Duration]) AS [Total Signal Wait Time (ms)]
\n\tFROM
\n\t    (SELECT
\n\t        event_data.value ('(<\/font>\/event\/@timestamp)[1]'<\/font>, 'DATETIME') AS [Time],
\n\t        event_data.value ('(\/event\/data[@name=''wait_type'']\/text)[1]', 'VARCHAR(100)') AS [Wait Type],
\n\t        event_data.value ('(\/event\/data[@name=''opcode'']\/text)[1]', 'VARCHAR(100)') AS [Op],
\n\t        event_data.value ('(\/event\/data[@name=''duration'']\/value)[1]', 'BIGINT') AS [Duration],
\n\t        event_data.value ('(\/event\/data[@name=''signal_duration'']\/value)[1]', 'BIGINT') AS [Signal Duration]
\n\t     FROM #RawEventData
\n\t    ) AS waits
\n\tWHERE waits.[op] = 'End'
\n\tGROUP BY waits.[Wait Type]
\n\tORDER BY [Total Wait Time (ms)] DESC;
\n\tGO<\/font>\n\t<\/p>\n

\n\t— Cleanup
\n\tDROP TABLE #RawEventData;
\n\tGO<\/font>\n\t<\/p>\n

\n\tWait Type             Wait Count  Total Wait Time (ms) Total Resource Wait Time (ms) Total Signal Wait Time (ms)
\n\t——————— ———– ——————– —————————– —————————
\n\tLATCH_EX              4919        15783                15693                         90
\n\tLATCH_SH              18          4399                 4398                          1
\n\tCXPACKET              16          3039                 3038                          1
\n\tPAGEIOLATCH_SH        813         468                  457                           11
\n\tPAGELATCH_SH          246         113                  109                           4
\n\tWRITELOG              99          71                   66                            5
\n\tPAGELATCH_UP          203         65                   63                            2
\n\tLOGBUFFER             123         58                   57                            1
\n\tWRITE_COMPLETION      82          55                   55                            0
\n\tPAGEIOLATCH_UP        35          27                   27                            0
\n\tIO_COMPLETION         80          25                   25                            0
\n\tSQLTRACE_LOCK         1           6                    6                             0
\n\tPAGEIOLATCH_EX        4           3                    3                             0
\n\tCMEMTHREAD            17          1                    0                             1
\n\tSOS_SCHEDULER_YIELD   6           0                    0                             0<\/font>\n\t<\/p>\n<\/blockquote>\n

\nYou can easily change this to give average times and add filters to remove uninteresting waits.<\/font>\n<\/p>\n

\nIf you're interested in getting more involved with extended events, check out Jonathan's excellent series from last December<\/a>.<\/font>\n<\/p>\n

\nHappy waiting!<\/font>\n<\/p>\n

\n<\/font><\/p>\n","protected":false},"excerpt":{"rendered":"

This is a performance tuning post that's been on my to-do list for quite a while. Wait stats analysis is a great way of looking at the symptoms of performance problems (see my Wait Stats category for more posts on this) but using the sys.dm_os_wait_stats DMV shows everything that's happening on a server. If you […]<\/p>\n","protected":false},"author":5,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[38,39,66,101],"tags":[],"class_list":["post-553","post","type-post","status-publish","format-standard","hentry","category-example-scripts","category-extended-events","category-performance-tuning","category-wait-stats"],"yoast_head":"\nCapturing wait stats for a single operation - 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\/capturing-wait-stats-for-a-single-operation\/\" \/>\n<meta property=\"og:locale\" content=\"en_US\" \/>\n<meta property=\"og:type\" content=\"article\" \/>\n<meta property=\"og:title\" content=\"Capturing wait stats for a single operation - Paul S. Randal\" \/>\n<meta property=\"og:description\" content=\"This is a performance tuning post that's been on my to-do list for quite a while. Wait stats analysis is a great way of looking at the symptoms of performance problems (see my Wait Stats category for more posts on this) but using the sys.dm_os_wait_stats DMV shows everything that's happening on a server. If you […]\" \/>\n<meta property=\"og:url\" content=\"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/\" \/>\n<meta property=\"og:site_name\" content=\"Paul S. Randal\" \/>\n<meta property=\"article:published_time\" content=\"2011-07-11T09:00:00+00:00\" \/>\n<meta property=\"article:modified_time\" content=\"2017-04-13T16:50:50+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=\"9 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\/capturing-wait-stats-for-a-single-operation\/\",\"url\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/\",\"name\":\"Capturing wait stats for a single operation - Paul S. Randal\",\"isPartOf\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/#website\"},\"datePublished\":\"2011-07-11T09:00:00+00:00\",\"dateModified\":\"2017-04-13T16:50:50+00:00\",\"author\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/#\/schema\/person\/ffcec826c18782e1e0adf173826a7fce\"},\"breadcrumb\":{\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/#breadcrumb\"},\"inLanguage\":\"en-US\",\"potentialAction\":[{\"@type\":\"ReadAction\",\"target\":[\"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/\"]}]},{\"@type\":\"BreadcrumbList\",\"@id\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/#breadcrumb\",\"itemListElement\":[{\"@type\":\"ListItem\",\"position\":1,\"name\":\"Home\",\"item\":\"https:\/\/www.sqlskills.com\/blogs\/paul\/\"},{\"@type\":\"ListItem\",\"position\":2,\"name\":\"Capturing wait stats for a single operation\"}]},{\"@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":"Capturing wait stats for a single operation - 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\/capturing-wait-stats-for-a-single-operation\/","og_locale":"en_US","og_type":"article","og_title":"Capturing wait stats for a single operation - Paul S. Randal","og_description":"This is a performance tuning post that's been on my to-do list for quite a while. Wait stats analysis is a great way of looking at the symptoms of performance problems (see my Wait Stats category for more posts on this) but using the sys.dm_os_wait_stats DMV shows everything that's happening on a server. If you […]","og_url":"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/","og_site_name":"Paul S. Randal","article_published_time":"2011-07-11T09:00:00+00:00","article_modified_time":"2017-04-13T16:50:50+00:00","author":"Paul Randal","twitter_misc":{"Written by":"Paul Randal","Est. reading time":"9 minutes"},"schema":{"@context":"https:\/\/schema.org","@graph":[{"@type":"WebPage","@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/","url":"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/","name":"Capturing wait stats for a single operation - Paul S. Randal","isPartOf":{"@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/#website"},"datePublished":"2011-07-11T09:00:00+00:00","dateModified":"2017-04-13T16:50:50+00:00","author":{"@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/#\/schema\/person\/ffcec826c18782e1e0adf173826a7fce"},"breadcrumb":{"@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/#breadcrumb"},"inLanguage":"en-US","potentialAction":[{"@type":"ReadAction","target":["https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/"]}]},{"@type":"BreadcrumbList","@id":"https:\/\/www.sqlskills.com\/blogs\/paul\/capturing-wait-stats-for-a-single-operation\/#breadcrumb","itemListElement":[{"@type":"ListItem","position":1,"name":"Home","item":"https:\/\/www.sqlskills.com\/blogs\/paul\/"},{"@type":"ListItem","position":2,"name":"Capturing wait stats for a single operation"}]},{"@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\/553","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=553"}],"version-history":[{"count":0,"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/posts\/553\/revisions"}],"wp:attachment":[{"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/media?parent=553"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/categories?post=553"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.sqlskills.com\/blogs\/paul\/wp-json\/wp\/v2\/tags?post=553"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}