Extended events and wait stats for specific session

  • Hi all

    I have a question about extended events. I wanted to demonstrate something about CXPACKET wait type. For the purpose of this demo I've created a query in AdventureWorks database that uses a parallel query plan, an extended events session that captured the wait statistics for a single session and a query that shows the extended event's data. I ran it and it worked fine. Then I dropped and recreated the event session (to clear the data), in a new window I wrote a transaction that updated the table fallowed by waitfor statement so the first query will be blocked for few seconds and ran the whole thing again. The select statement was blocked as expected (ran for 9 seconds instead on 1 second as it ran without the blocking), but the wait stats that I got were almost identical to the those that I got without blocking the query. Below is the code that I'm using. Can someone please tell me what am I missing?

    --Query that uses parallel query plan

    With MyCTE as (

    select top 50 * from Sales.SalesOrderHeader)

    select top 10000 * from Sales.SalesOrderHeader, MyCTE

    order by newid()

    -------------------------------------

    --The creation of the extended event session

    CREATE EVENT SESSION [CheckWaitStats] ON SERVER

    ADD EVENT sqlos.wait_info(

    ACTION(sqlserver.session_id)

    WHERE session_id = 177) --Change the session ID to the one that runs the select query

    ADD TARGET package0.ring_buffer

    GO

    ALTER EVENT SESSION CheckWaitStats ON SERVER STATE=START

    go

    -------------------------------------------------

    --Getting the data from the extended event session

    DECLARE @XML XML;

    SELECT @XML = CAST(target_data AS XML)

    FROM sys.dm_xe_sessions AS s

    JOIN sys.dm_xe_session_targets AS t

    ON t.event_session_address = s.address

    WHERE s.name = N'CheckWaitStats';

    --select @XML;

    WITH WaitTimes as (

    SELECT Tbl.XmlCol.value('(data/text)[1]','varchar(30)') as WaitTypeName,

    Tbl.XmlCol.value('(data [@name="duration"]/value)[1]','int') as Duration

    from @XML.nodes('RingBufferTarget/event') Tbl (XmlCol))

    SELECT WaitTypeName, SUM(Duration) as Duration

    FROM WaitTimes

    GROUP BY WaitTypeName

    ------------------------------------------------------------

    --The query that I used to create blocking (should be used in a different window)

    BEGIN TRAN

    UPDATE Sales.SalesOrderHeader

    SET OrderDate = OrderDate-1

    WHERE SalesOrderID = 51448

    WAITFOR DELAY '00:00:10'

    ROLLBACK

    Any help would be appreciated

    Adi

    --------------------------------------------------------------
    To know how to ask questions and increase the chances of getting asnwers:
    http://www.sqlservercentral.com/articles/Best+Practices/61537/

    For better answers on performance questions, click on the following...
    http://www.sqlservercentral.com/articles/SQLServerCentral/66909/

  • I know that answering my own question is a bit strange, but I found out the problem and it might help someone else so I'm writing it as an answer to my own question. It turns out that using the ring buffer as a target to an extended event is not such a good idea. In order to see the data in the ring buffer, SQL Server creates an XML document. The size of the XML document is limited and whenever the XML size will be to big because of the amount of data in the ring buffer, the server will ignore part of the data and will create the XML document that shows only part of the data. Unfortunately we will not get any error message or warning. In fact I'm not aware of any way of knowing that we see only part of the data. Jonathan Kehayias wrote about it in his blog – https://www.sqlskills.com/blogs/jonathan/why-i-hate-the-ring_buffer-target-in-extended-events/%5B/url%5D. Bellow is a small way to reproduce the problem.

    In one window of SSMS write this SQL Statement:

    With MyCTE as (

    select top 10 * from Sales.SalesOrderHeader)

    select top 1000 * from Sales.SalesOrderHeader, MyCTE

    order by newid();

    Check the SSMS's window's session id, and in a different window create the extended event, modify it so it will use the session id that is used for the first query and start it

    CREATE EVENT SESSION [CheckWaitStats] ON SERVER

    ADD EVENT sqlos.wait_info(

    ACTION(sqlserver.session_id)

    WHERE session_id = 0) --modify it to use the value of the session id of the window that has the select statement

    ADD TARGET package0.ring_buffer,

    ADD TARGET package0.event_file(SET filename=N'C:\Temp\CheckWaitStats.xel',max_file_size=(10240),max_rollover_files=(3))

    WITH (MAX_MEMORY=65536 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS);

    GO

    ALTER EVENT SESSION CheckWaitStats ON SERVER STATE=START;

    Run the select query and then compare the number of events that you got in the ring buffer to the number of results that you got in the file:

    --Get the results from Ring buffer

    DECLARE @XML XML;

    SELECT @XML = CAST(target_data AS XML)

    FROM sys.dm_xe_sessions AS s

    JOIN sys.dm_xe_session_targets AS t

    ON t.event_session_address = s.address

    WHERE s.name = N'CheckWaitStats' and t.target_name = 'ring_buffer';

    WITH WaitTimes as (

    SELECT Tbl.XmlCol.value('(data/text)[1]','varchar(30)') as WaitTypeName,

    Tbl.XmlCol.value('(data [@name="duration"]/value)[1]','int') as Duration

    from @XML.nodes('RingBufferTarget/event') Tbl (XmlCol))

    SELECT WaitTypeName,

    SUM(CASE WHEN Duration=0 THEN 0 ELSE 1 END) as TotalNonZeroDurationEvents,

    SUM(CASE WHEN Duration=0 THEN 1 ELSE 0 END) as TotalZeroDurationEvents

    FROM WaitTimes

    GROUP BY WaitTypeName;

    go

    --getting the results for the same session from the file

    WITH ParseXMLCTE AS

    (

    SELECT CAST(event_data AS XML) AS EventDataXML

    FROM sys.fn_xe_file_target_read_file('C:\Temp\CheckWaitStats*.xel', NULL, NULL, NULL)

    WHERE [object_name] = 'wait_info'

    ),

    DurationsCTE AS

    (

    SELECT

    EventDataXML.value('(event/data/text)[1]','varchar(30)') as WaitTypeName,

    EventDataXML.value('(event/data [@name="duration"]/value)[1]','int') as Duration

    FROM ParseXMLCTE

    )

    SELECT

    WaitTypeName,

    SUM(CASE WHEN Duration <> 0 THEN 1 ELSE 0 END) AS TotalNonZeroDurationEvents,

    SUM(CASE WHEN Duration = 0 THEN 1 ELSE 0 END) AS TotalZeroDurationEvents

    FROM DurationsCTE

    GROUP BY WaitTypeName;

    Hope that it will help someone.

    Adi

    --------------------------------------------------------------
    To know how to ask questions and increase the chances of getting asnwers:
    http://www.sqlservercentral.com/articles/Best+Practices/61537/

    For better answers on performance questions, click on the following...
    http://www.sqlservercentral.com/articles/SQLServerCentral/66909/

Viewing 2 posts - 1 through 1 (of 1 total)

You must be logged in to reply to this topic. Login to reply