{"id":408,"date":"2008-07-24T00:00:00","date_gmt":"2008-07-24T00:00:00","guid":{"rendered":"https:\/\/test.simple-talk.com\/uncategorized\/investigating-sql-server-2008-wait-events-with-xevents\/"},"modified":"2021-06-03T16:44:21","modified_gmt":"2021-06-03T16:44:21","slug":"investigating-sql-server-2008-wait-events-with-xevents","status":"publish","type":"post","link":"https:\/\/www.red-gate.com\/simple-talk\/databases\/sql-server\/performance-sql-server\/investigating-sql-server-2008-wait-events-with-xevents\/","title":{"rendered":"Investigating SQL Server 2008 Wait Events with XEVENTS"},"content":{"rendered":"
\n

Investigating perfomance bottlenecks in  SQL Server 2008 by looking at wait events using the XE trace system<\/h1>\n

Introduction.<\/h3>\n

In my previous articles  SQL Server Wait Events: Taking the Guesswork out of Performance Profiling<\/a>,  and Taking the Guesswork out of SQL Server Performance Profiling Part 2,<\/a> I introduced the concepts of performance analysis based on wait events.<\/p>\n

In short, the idea behind this concept is to take the response time of a SQL statement (or a batch or a user session) and split it up into CPU time and Wait time..<\/p>\n

Earlier versions of SQL Server only maintain wait time (aggregated) on the server level, or you can see the wait times and the wait reasons, and when they actually occur in views like sysprocesses<\/i><\/b> or sys.dm_os_waiting_tasks<\/i><\/b>. Starting with SQL Server 2005, the wait events are finally documented in the SQL Server BOL, and more and more background is provided in blogs, KB Articles, forums etc.<\/p>\n

A wait event ‘happens’ when the SQL Server scheduler (implemented in the SQLOS) decides to suspend a running task.<\/p>\n

This can be because a ‘long’ operation starts, such as disk,  network I\/O, or  lock. It can also happen when the allotted time quantum that a task can be active on the CPU ends. At this moment this seems to be a hard-coded 4 ms. This is the means by which that the SQL Server scheduler makes sure that every task in SQL Server gets its turn running on the CPU. By carefully looking at the way the response time is build up, one can make intelligent decisions on where to look for possible optimizations, or capacity planning: For instance, if on your SQL Server box 90% of the total used (response) time consists of I\/O waits and only 10% of the time is spend on the CPU, then adding CPU capacity or upgrading to faster CPUs is unlikely to have a very large impact on response times. The same is true for individual queries. If one query spends 90% of its time waiting for I\/O, then speeding up the CPU will only impact the other 10% of the response time picture.<\/p>\n

SQL Server 2008 introduces Extended Events (XE) a new event handling system. XE is a flexible and lightweight event trace system.<\/p>\n

The SQL Server engine is instrumented with tracing code in many locations. It is possible to trace ‘traditional’ events as existed in older SQL Trace versions, events like ‘RPC:Completed’<\/b>. ‘sp_completed’<\/b>, ‘lock timeout’<\/b> etc.<\/p>\n

An exciting new tracing feature, is the means by which one can trace information about SQL Server OS (SQLOS) wait events<\/p>\n

Each event contains a set of interesting columns that will be logged to a ‘target’. In this example, we have chosen a file. Next to the ‘default’ set of columns for an event, extra information can be logged as well. This is done by defining ‘actions’ on a traced event. Below is an example of standard columns that are logged for the event ‘wait_info’<\/b> in the package ‘sqlos<\/b>‘, and for the event, ‘sql_statement_completed’<\/b> in the sqlserver<\/b> package, which will also be used in the example:<\/p>\n

name                         column_id       object_name            \n--------------------         -----------     -----------------------              \nwait_type                    0                wait_info         \nopcode                       1                wait_info  \nduration                     2                wait_info  \nmax_duration                 3                wait_info  \ntotal_duration               4                wait_info  \nsignal_duration              5                wait_info  \ncompleted_count              6                wait_info\n...\nsource_database_id           0                sql_statement_completed\nobject_id                    1                sql_statement_completed\nobject_type                  2                sql_statement_completed\ncpu                          3                sql_statement_completed\nduration                     4                sql_statement_completed\nreads                        5                sql_statement_completed\nwrites                       6                sql_statement_completed\n<\/pre>\n
Next is an example on how to setup wait event tracing and collecting information from an ‘asynchronous file target’.  Only specific events are collected for session_id=53.<\/p>\n
First we create the ‘event session’, and start it.<\/p>\n
After this, we can run an example query from a session with session_id=53, a count(*) query was run on a 1 million row (unindexed) table.<\/p>\n
Example 1:<\/h3>\n
\ncreate event session test1\non server\nadd event sqlserver.sql_statement_starting\n(action \n            (sqlserver.session_id, package0.collect_system_time,\npackage0.collect_cpu_cycle_time,sqlserver.sql_text,\nsqlserver.plan_handle, sqlos.task_address, sqlos.worker_address)\n            where sqlserver.session_id = 53),\nadd event sqlserver.sql_statement_completed\n(action \n(sqlserver.session_id, package0.collect_system_time, package0.collect_cpu_cycle_time, sqlserver.sql_text,\nsqlserver.plan_handle, sqlos.task_address, sqlos.worker_address)\n      where sqlserver.session_id = 53),\nadd event sqlos.wait_info\n            (action \n(sqlserver.session_id,  package0.collect_system_time, package0.collect_cpu_cycle_time, sqlos.task_address, sqlos.worker_address)\n       where sqlserver.session_id = 53)\n--\n--          async file, read with: sys.fn_xe_file_target_read_file\n--\n ADD TARGET package0.asynchronous_file_target\n(SET filename = N'C:\\temp\\wait.etx', metadatafile = N'C:\\temp\\wait.mta',\n                        max_file_size = 50, max_rollover_files = 10) \n            WITH (max_dispatch_latency = 2 seconds)\ngo\nalter event session test1 on server state = start\ngo\n<\/pre>\n
Example 2:<\/h3>\n
The next example shows how to collect the trace information from the trace files for further processing. As you can see from the example, the files is read ‘through’ a virtual function, ‘sys.fn_xe_file_target_read_file’, and the rows are returned in XML form.<\/p>\n
The insert into the xTable counted 4938 rows. For the next summary I only collected the ‘wait_info’ ‘end’ events (1560 rows) and the ‘sql_statement_completed’ event (1 row):<\/p>\n
drop table xTable\nCREATE TABLE xTable \n    ( \n      xTable_ID INT IDENTITY \n                    PRIMARY KEY, \n      xCol XML \n    ) ; \n \nINSERT  INTO xTable ( xCol ) \nselect cast(event_data as xml) waitinfo from sys.fn_xe_file_target_read_file\n('c:\\temp\\wait_*.etx',\n'c:\\temp\\wait_*.mta',\nnull,null)\n<\/pre>\n
Now in order to extract the CPU and Wait information and match it with the total response time, we run the following queries:<\/p>\n
SELECT  \n-- for some reason wait type name is not logged with synch target. bug?\n(select map_value from sys.dm_xe_map_values \n    where name = 'wait_types' \n        and map_key = xCol.value('(event\/data\/value)[1]', 'int') \n)AS wtype,\n     xCol.value('(event\/data\/value)[3]', 'int')  --wait time\n                                    AS tottime,\n     xCol.value('(event\/data\/value)[6]', 'int') --sig wait time\n                                    AS sigtime\n     into #mywaits    \nFROM    xTable \nwhere xCol.value('(\/event\/@name)[1]', 'varchar(30)') = 'wait_info'      \n and xCol.value('(event\/data\/value)[2]', 'int') = 1 --opcode end          \n \nselect  wtype, \n        count(*) as wcount, \n        sum(tottime) as total_time, \n        sum(sigtime) as signal_time \n        from #mywaits group by wtype\ngo\n-- stmt completed:\n \nSELECT  \n                        xCol.value('(event\/data\/value)[4]', 'int')\n                                    AS cputime,\n                        xCol.value('(event\/data\/value)[5]', 'int')\n                                    AS duration,\n                        xCol.value('(event\/action\/value)[4]', 'varchar(MAX)')\n                                    AS sql_text\ninto #mysql\nFROM    [xTable] \nwhere xCol.value('(\/event\/@name)[1]', 'varchar(30)') = 'sql_statement_completed'     \nselect  sql_text, \n        count(*) as count, \n        SUM(cputime) as cputime, \n        SUM(duration) as duration from #mysql group by sql_text\ngo\ndrop table #mywaits\ndrop table #mysql\n<\/pre>\n
This is the result of the above queries:<\/p>\n
   wtype                       wcount         total_time    signal_time    --------------------------  -----------    -----------   -----------    \nPWAIT_SOS_SCHEDULER_YIELD   20             45            0              \nPWAIT_SLEEP_TASK            1              10            0              \nPWAIT_PAGEIOLATCH_SH        1539           59163         674            \n                                                                             \n (1 row(s) affected)                                                           \nsql_text                    count      cputime   duration       \n-------------------------   --------   --------  -----------    \nselect COUNT(*) from t1m    1          1892      61560364       \n                                                                              \n<\/pre>\n
So what we can see here is that the statement response time (duration) was 6156 ms (apparently, the  sqlserver.sql_statement_completed.duration<\/b> is measured in microseconds)<\/p>\n
The CPU time used was 1892 ms and the wait time for the three different wait events was 45+10+59163 ms = 59218 ms. Including the measured signal_time (the time between the end of the actual wait and the resumption of work) this nicely adds up to the total duration of the query.<\/p>\n
For more information on the specific wait events, search the SQL Server BOL for the sys.dm_os_wait_stats<\/b> view. All wait events are documented here.<\/p>\n
It is also possible to look at each individual wait event. This can be useful to detect skew in wait durations for example. If you detect that certain I\/O operations take longer than others, it might be interesting to add other XEvents to trace. Events like ‘file_read_completed’<\/b> will show which file was read and which offset within the file. The event ‘physical_page_read’<\/b>, can tell which page for which file. These events can help detecting if you might be reading from slow disks or doing random I\/O while you were expecting to do sequential I\/Os.<\/p>\n
-- first: sql_statement_starting\nSELECT  xTable_ID,\n                        xCol.value('(event\/action\/value)[1]', 'int')\n                                    AS session_id,\n                        xCol.value('(\/event\/@timestamp)[1]', 'varchar(24)')\n                                    AS EventTime,\n                        xCol.value('(\/event\/@name)[1]', 'varchar(30)')\n                                    AS EventType,\n                        xCol.value('(event\/action\/value)[2]', 'varchar(30)')\n                                    AS system_time,\n                        xCol.value('(event\/action\/value)[3]', 'varchar(30)')\n                                    AS cpu_cycle_time,\n                        xCol.value('(event\/data\/value)[5]', 'varchar(30)')\n                                    AS data1,\n                        xCol.value('(event\/data\/value)[6]', 'varchar(30)')\n                                    AS data2,\n                        xCol.value('(event\/action\/value)[4]', 'varchar(MAX)')\n                                    AS sql_text\nFROM    [xTable] \nwhere xCol.value('(\/event\/@name)[1]', 'varchar(30)') = 'sql_statement_starting'\nunion    --now collect: statement_completed                     \nSELECT  xTable_ID,\n                        xCol.value('(event\/action\/value)[1]', 'int')\n                                    AS session_id,\n                        xCol.value('(\/event\/@timestamp)[1]', 'varchar(24)')\n                                    AS EventTime,\n                        xCol.value('(\/event\/@name)[1]', 'varchar(30)')\n                                    AS EventType,\n                        xCol.value('(event\/action\/value)[2]', 'varchar(30)')\n                                    AS system_time,\n                        xCol.value('(event\/action\/value)[3]', 'varchar(30)')\n                                    AS cpu_cycle_time,\n                        xCol.value('(event\/data\/value)[4]', 'varchar(30)')\n                                    AS data1,\n                        xCol.value('(event\/data\/value)[5]', 'varchar(30)')\n                                    AS data2,\n                        xCol.value('(event\/action\/value)[4]', 'varchar(MAX)')\n                                    AS sql_text\nFROM    [xTable] \nwhere xCol.value('(\/event\/@name)[1]', 'varchar(30)') = 'sql_statement_completed'\nunion\nSELECT  xTable_ID,\n                        xCol.value('(event\/action\/value)[1]', 'int')\n                                    AS session_id,\n                        xCol.value('(\/event\/@timestamp)[1]', 'varchar(24)')\n                                    AS EventTime,\n-- for some reason wait type name is not logged with synch target. bug?\n                         (select map_value from sys.dm_xe_map_values \n                            where name = 'wait_types' \n                            and map_key =  xCol.value('(event\/data\/value)[1]', 'int') \n                          ) as Event_name,\n                        xCol.value('(event\/action\/value)[2]', 'varchar(30)')\n                                    AS system_time,\n                        xCol.value('(event\/action\/value)[3]', 'varchar(30)')\n                                    AS cpu_cycle_time,\nxCol.value('(event\/data\/value)[3]', 'varchar(30)')  --wait time\n                                    AS data1,\nxCol.value('(event\/data\/value)[6]', 'varchar(30)') --sig wait time\n                                    AS data2,\n                        ''\n                                    AS sql_text\n                        \nFROM    [xTable] \nwhere xCol.value('(\/event\/@name)[1]', 'varchar(30)') = 'wait_info'      \n and xCol.value('(event\/data\/value)[2]', 'int') = 1 -- opcode end         \n \n\n<\/pre>\n
This article, submitted in May, was originally scheduled for publication as part of Simple-Talk’s celebration of the launch of SQL Server 2008 next month, but has been brought forward in view of the current interest in the subject <\/p>\n<\/div>\n","protected":false},"excerpt":{"rendered":"
Some reasons for the slow-running of database applications aren’t obvious. Occasionally, even the profiler won’t tell you enough to remedy a problem, especially when a SQL Statement is being forced to wait.
\nNow, in SQL Server 2008, come XEvents, which allow you to look at those wait events that are slowing your SQL Statements.
\nMario Broodbakker continues his series about SQL Server Wait Events
\nSQL Server 2008 wait event based performance analysis using XEvents…<\/p>\n","protected":false},"author":129582,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[143529],"tags":[4168,4206,4150,4151],"coauthors":[],"class_list":["post-408","post","type-post","status-publish","format-standard","hentry","category-performance-sql-server","tag-database","tag-performance","tag-sql","tag-sql-server"],"acf":[],"_links":{"self":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/408","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/users\/129582"}],"replies":[{"embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/comments?post=408"}],"version-history":[{"count":6,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/408\/revisions"}],"predecessor-version":[{"id":91218,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/posts\/408\/revisions\/91218"}],"wp:attachment":[{"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/media?parent=408"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/categories?post=408"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/tags?post=408"},{"taxonomy":"author","embeddable":true,"href":"https:\/\/www.red-gate.com\/simple-talk\/wp-json\/wp\/v2\/coauthors?post=408"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}