How It Works: Extended Event (sqlos.wait_info*)

Published Jan 15 2019 01:16 PM 1,587 Views
Microsoft
First published on MSDN on Oct 20, 2010

I was posed a good question today about how the wait_info* event works in SQL Server 2008.   The easiest way for me to answer the question was to prove the behavior.  using WAITFOR DELAY it shows the behavior nicely.

From: Robert Dorr
Sent: Wednesday, October 20, 2010 2:07 PM
Subject: RE: Extended Events

The wait types are similar to those exposed in sys.dm_os_wait_stats.

The code shows me that:  completed_count = Number of times the action has been completed.   In this case of something like (NETWORK_IO) SQL checked and made sure lots have completed.   The wait time for many of these could have been 0 (already completed).

You can use the WAITFOR action to determine the behavior.    You can see below that I waited for 5 seconds and the outputs show the MS values.

select * from sys.dm_os_wait_stats

where wait_type = 'WAITFOR'

go

waitfor delay '00:00:05'

go

select * from sys.dm_os_wait_stats

where wait_type = 'WAITFOR'

go

create event session WaitTest on server

add event sqlos.wait_info

add target package0.asynchronous_file_target

(set filename=N'c:tempWait.xel')

with (max_dispatch_latency=1 seconds)

go

alter event session WaitTest on server state = start

alter event session WaitTest on server state = stop

select * from fn_xe_file_target_read_file('c:temp*.xel', 'c:temp*.xem', NULL, NULL)

where event_data like '%5000%'

go

<event name="wait_info" package="sqlos" id="48" version="1" timestamp="2010-10-20T19:02:31.797Z">

<data name="wait_type">

<value>189</value><text><![CDATA[WAITFOR]]></text></data>

<data name="opcode"><value>1</value>

<text><![CDATA[End]]></text></data>

<data name="duration"><value>5000</value><text></text></data>

<data name="max_duration"><value>5000</value><text></text></data>

<data name="total_duration"><value>20001</value><text></text></data>

<data name="signal_duration"><value>0</value><text></text></data>

<data name="completed_count"><value>4</value><text></text></data>

</event>

Bob Dorr - Principal SQL Server Escalation Engineer


%3CLINGO-SUB%20id%3D%22lingo-sub-316224%22%20slang%3D%22en-US%22%3EHow%20It%20Works%3A%20Extended%20Event%20(sqlos.wait_info*)%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-316224%22%20slang%3D%22en-US%22%3E%0A%20%26lt%3Bmeta%20http-equiv%3D%22Content-Type%22%20content%3D%22text%2Fhtml%3B%20charset%3DUTF-8%22%20%2F%26gt%3B%3CSTRONG%3E%20First%20published%20on%20MSDN%20on%20Oct%2020%2C%202010%20%3C%2FSTRONG%3E%20%3CBR%20%2F%3E%3CP%3EI%20was%20posed%20a%20good%20question%20today%20about%20how%20the%20wait_info*%20event%20works%20in%20SQL%20Server%202008.%26nbsp%3B%26nbsp%3B%20The%20easiest%20way%20for%20me%20to%20answer%20the%20question%20was%20to%20prove%20the%20behavior.%26nbsp%3B%20using%20WAITFOR%20DELAY%20it%20shows%20the%20behavior%20nicely.%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CA%3E%3CB%3EFrom%3A%20%3C%2FB%3E%20%3C%2FA%3E%20Robert%20Dorr%20%3CBR%20%2F%3E%20%3CB%3E%20Sent%3A%20%3C%2FB%3E%20Wednesday%2C%20October%2020%2C%202010%202%3A07%20PM%20%3CBR%20%2F%3E%20%3CB%3E%20Subject%3A%20%3C%2FB%3E%20RE%3A%20Extended%20Events%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3EThe%20wait%20types%20are%20similar%20to%20those%20exposed%20in%20sys.dm_os_wait_stats.%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3EThe%20code%20shows%20me%20that%3A%26nbsp%3B%20completed_count%20%3D%20Number%20of%20times%20the%20action%20has%20been%20completed.%26nbsp%3B%26nbsp%3B%20In%20this%20case%20of%20something%20like%20(NETWORK_IO)%20SQL%20checked%20and%20made%20sure%20lots%20have%20completed.%26nbsp%3B%26nbsp%3B%20The%20wait%20time%20for%20many%20of%20these%20could%20have%20been%200%20(already%20completed).%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3EYou%20can%20use%20the%20WAITFOR%20action%20to%20determine%20the%20behavior.%26nbsp%3B%26nbsp%3B%26nbsp%3B%20You%20can%20see%20below%20that%20I%20waited%20for%205%20seconds%20and%20the%20outputs%20show%20the%20MS%20values.%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Eselect%20*%20from%20sys.dm_os_wait_stats%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ewhere%20wait_type%20%3D%20'WAITFOR'%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ego%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ewaitfor%20delay%20'00%3A00%3A05'%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ego%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Eselect%20*%20from%20sys.dm_os_wait_stats%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ewhere%20wait_type%20%3D%20'WAITFOR'%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ego%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ecreate%20event%20session%20WaitTest%20on%20server%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Eadd%20event%20sqlos.wait_info%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Eadd%20target%20package0.asynchronous_file_target%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E(set%20filename%3DN'c%3AtempWait.xel')%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ewith%20(max_dispatch_latency%3D1%20seconds)%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ego%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ealter%20event%20session%20WaitTest%20on%20server%20state%20%3D%20start%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ealter%20event%20session%20WaitTest%20on%20server%20state%20%3D%20stop%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Eselect%20*%20from%20fn_xe_file_target_read_file('c%3Atemp*.xel'%2C%20'c%3Atemp*.xem'%2C%20NULL%2C%20NULL)%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ewhere%20event_data%20like%20'%255000%25'%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3Ego%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CEVENT%20name%3D%22%26quot%3Bwait_info%26quot%3B%22%20package%3D%22%26quot%3Bsqlos%26quot%3B%22%20id%3D%22%26quot%3B48%26quot%3B%22%20version%3D%22%26quot%3B1%26quot%3B%22%20timestamp%3D%22%26quot%3B2010-10-20T19%3A02%3A31.797Z%26quot%3B%22%3E%3C%2FEVENT%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CDATA%20name%3D%22%26quot%3Bwait_type%26quot%3B%22%3E%3C%2FDATA%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CVALUE%3E189%3C%2FVALUE%3E%3CTEXT%3EWAITFOR%3C%2FTEXT%3E%3C%2FP%3E%3C%2FLINGO-BODY%3E%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CDATA%20name%3D%22%26quot%3Bopcode%26quot%3B%22%3E%3CVALUE%3E1%3C%2FVALUE%3E%3C%2FDATA%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CTEXT%3EEnd%3C%2FTEXT%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CDATA%20name%3D%22%26quot%3Bduration%26quot%3B%22%3E%3CVALUE%3E5000%3C%2FVALUE%3E%3CTEXT%3E%3C%2FTEXT%3E%3C%2FDATA%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CDATA%20name%3D%22%26quot%3Bmax_duration%26quot%3B%22%3E%3CVALUE%3E5000%3C%2FVALUE%3E%3CTEXT%3E%3C%2FTEXT%3E%3C%2FDATA%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CDATA%20name%3D%22%26quot%3Btotal_duration%26quot%3B%22%3E%3CVALUE%3E20001%3C%2FVALUE%3E%3CTEXT%3E%3C%2FTEXT%3E%3C%2FDATA%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CDATA%20name%3D%22%26quot%3Bsignal_duration%26quot%3B%22%3E%3CVALUE%3E0%3C%2FVALUE%3E%3CTEXT%3E%3C%2FTEXT%3E%3C%2FDATA%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CDATA%20name%3D%22%26quot%3Bcompleted_count%26quot%3B%22%3E%3CVALUE%3E4%3C%2FVALUE%3E%3CTEXT%3E%3C%2FTEXT%3E%3C%2FDATA%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3EBob%20Dorr%20-%20Principal%20SQL%20Server%20Escalation%20Engineer%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%3CBR%20%2F%3E%3CLINGO-TEASER%20id%3D%22lingo-teaser-316224%22%20slang%3D%22en-US%22%3EFirst%20published%20on%20MSDN%20on%20Oct%2020%2C%202010%20I%20was%20posed%20a%20good%20question%20today%20about%20how%20the%20wait_info*%20event%20works%20in%20SQL%20Server%202008.%3C%2FLINGO-TEASER%3E%3CLINGO-LABS%20id%3D%22lingo-labs-316224%22%20slang%3D%22en-US%22%3E%3CLINGO-LABEL%3ETroubleshooting%3C%2FLINGO-LABEL%3E%3CLINGO-LABEL%3EUtilities%3C%2FLINGO-LABEL%3E%3C%2FLINGO-LABS%3E
Version history
Last update:
‎Jan 15 2019 01:16 PM
Updated by: