Take the 2-minute tour ×
Database Administrators Stack Exchange is a question and answer site for database professionals who wish to improve their database skills and learn from others in the community. It's 100% free, no registration required.

Executing the query from here to pull the deadlock events out of the default extended events session

SELECT CAST (
    REPLACE (
        REPLACE (
            XEventData.XEvent.value ('(data/value)[1]', 'varchar(max)'),
            '<victim-list>', '<deadlock><victim-list>'),
        '<process-list>', '</victim-list><process-list>')
    AS XML) AS DeadlockGraph
FROM (SELECT CAST (target_data AS XML) AS TargetData
    FROM sys.dm_xe_session_targets st
    JOIN sys.dm_xe_sessions s ON s.address = st.event_session_address
    WHERE [name] = 'system_health') AS Data
CROSS APPLY TargetData.nodes ('//RingBufferTarget/event') AS XEventData (XEvent)
    WHERE XEventData.XEvent.value('@name', 'varchar(4000)') = 'xml_deadlock_report';

takes about 20 minutes to complete on my machine. The stats reported are

Table 'Worktable'. Scan count 0, logical reads 68121, physical reads 0, read-ahead reads 0, 
         lob logical reads 25674576, lob physical reads 0, lob read-ahead reads 4332386.

 SQL Server Execution Times:
   CPU time = 1241269 ms,  elapsed time = 1244082 ms.

Slow Plan XML

Parallel

If I remove the WHERE clause it completes in less than a second returning 3,782 rows.

Similarly if I add OPTION (MAXDOP 1) to the original query that speeds things up too with the stats now showing massively fewer lob reads.

Table 'Worktable'. Scan count 0, logical reads 15, physical reads 0, read-ahead reads 0,
                lob logical reads 6767, lob physical reads 0, lob read-ahead reads 6076.

 SQL Server Execution Times:
   CPU time = 639 ms,  elapsed time = 693 ms.

Faster Plan XML

Serial

So my question is

Can anyone explain what's going on? Why is the original plan so catastrophically worse and is there any reliable way of avoiding the problem?

Addition:

I've also found that changing the query to INNER HASH JOIN improves things to some extent (but it still takes > 3 mins) as the DMV results are so small I doubt that the Join type itself is responsible though and presume something else must have changed. Stats for that

Table 'Worktable'. Scan count 0, logical reads 30294, physical reads 0, read-ahead reads 0, 
          lob logical reads 10741863, lob physical reads 0, lob read-ahead reads 4361042.

 SQL Server Execution Times:
   CPU time = 200914 ms,  elapsed time = 203614 ms.

(And plan)

After filling up the extended events ring buffer (DATALENGTH of the XML was 4,880,045 bytes and it contained 1,448 events.) and testing a cut down version of the original query with and without the MAXDOP hint.

SELECT COUNT(*)
FROM   (SELECT CAST (target_data AS XML) AS TargetData
        FROM   sys.dm_xe_session_targets st
               JOIN sys.dm_xe_sessions s
                 ON s.address = st.event_session_address
        WHERE  [name] = 'system_health') AS Data
       CROSS APPLY TargetData.nodes ('//RingBufferTarget/event') AS XEventData (XEvent)
WHERE  XEventData.XEvent.value('@name', 'varchar(4000)') = 'xml_deadlock_report'

SELECT*
FROM   sys.dm_db_task_space_usage
WHERE  session_id = @@SPID 

Gave the following results

+-------------------------------------+------+----------+
|                                     | Fast |   Slow   |
+-------------------------------------+------+----------+
| internal_objects_alloc_page_count   |  616 |  1761272 |
| internal_objects_dealloc_page_count |  616 |  1761272 |
| elapsed time (ms)                   |  428 |   398481 |
| lob logical reads                   | 8390 | 12784196 |
+-------------------------------------+------+----------+

There is a clear difference in tempdb allocations with the faster one showing 616 pages were allocated and deallocated. This is the same amount of pages used when the XML is put into a variable too.

For the slow plan these page allocation counts are into the millions. Polling dm_db_task_space_usage whilst the query is running shows it seems to be constantly allocating and deallocating pages in tempdb with anywhere between 1,800 and 3,000 pages allocated at any one time.

share|improve this question
    
You can move the WHERE clause into the XQuery expression; the logic doesn't have to be removed for it to go fast: TargetData.nodes ('RingBufferTarget[1]/event[@name = "xml_deadlock_report"]'). That said, I don't know XML internals well enough to answer the question you've posed. –  Jon Seigel Dec 21 '12 at 2:33
    
Paging @SQLPoolBoy for you Martin... he suggested to go through the comments here where he has more efficient suggestions (they're based on the source article for the code above). –  Aaron Bertrand Dec 21 '12 at 3:08
    
@AaronBertrand - Thanks! –  Martin Smith Dec 21 '12 at 11:17
add comment

2 Answers

up vote 12 down vote accepted
+100

The reason for the performance difference lies in how scalar expressions are handled in the execution engine. In this case, the expression of interest is:

[Expr1000] = CONVERT(xml,DM_XE_SESSION_TARGETS.[target_data],0)

This expression label is defined by a Compute Scalar operator (node 11 in the serial plan, node 13 in the parallel plan). Compute Scalar operators are different from other operators (SQL Server 2005 onward) in that the expression(s) they define are not necessarily evaluated at the position they appear in the visible execution plan; evaluation can be deferred until the result of the computation is required by a later operator.

In the present query, the target_data string is typically large, making the conversion from string to XML expensive. In slow plans, the string to XML conversion is performed every time a later operator that requires the result of Expr1000 is rebound.

Rebinding occurs on the inner side of a nested loops join when a correlated parameter (outer reference) changes. Expr1000 is an outer reference for most of the nested loops joins in this execution plan. The expression is referenced multiple times by several XML Readers, both Stream Aggregates, and by a start-up Filter. Depending on the size of the XML, the number of times the string is converted to XML can easily number in the millions.

The call stacks below show examples of the target_data string being converted to XML (ConvertStringToXMLForES - where ES is the Expression Service):

Start-up Filter

Start-up Filter call stack

XML Reader (TVF Stream internally)

TVF Stream call stack

Stream Aggregate

Stream Aggregate call stack

Converting the string to XML each time any of these operators rebind explains the performance difference observed with the nested loops plans. This is regardless of whether parallelism is used or not. It just so happens that the optimizer chooses a hash join when the MAXDOP 1 hint is specified. If MAXDOP 1, LOOP JOIN is specified, performance is poor just as with the default parallel plan (where the optimizer chooses nested loops).

How much performance increases with a hash join depends on whether Expr1000 appears on the build or probe side of the operator. The following query locates the expression on the probe side:

SELECT CAST (
    REPLACE (
        REPLACE (
            XEventData.XEvent.value ('(data/value)[1]', 'varchar(max)'),
            '<victim-list>', '<deadlock><victim-list>'),
        '<process-list>', '</victim-list><process-list>')
    AS XML) AS DeadlockGraph
FROM (SELECT CAST (target_data AS XML) AS TargetData
    FROM sys.dm_xe_sessions s
    INNER HASH JOIN sys.dm_xe_session_targets st ON s.address = st.event_session_address
    WHERE [name] = 'system_health') AS Data
CROSS APPLY TargetData.nodes ('//RingBufferTarget/event') AS XEventData (XEvent)
WHERE XEventData.XEvent.value('@name', 'varchar(4000)') = 'xml_deadlock_report';

I have reversed the written order of the joins from the version shown in the question, because join hints (INNER HASH JOIN above) also force the order for the whole query, just as if FORCE ORDER had been specified. The reversal is necessary to ensure Expr1000 appears on the probe side. The interesting part of the execution plan is:

hint 1

With the expression defined on the probe side, the value is cached:

Hash Cache

Evaluation of Expr1000 is still deferred until the first operator needs the value (the start-up filter in the stack trace above) but the computed value is cached (CValHashCachedSwitch) and reused for later calls by the XML Readers and Stream Aggregates. The stack trace below shows an example of the cached value being reused by an XML Reader.

Cache reuse

When the join order is forced such that the definition of Expr1000 occurs on the build side of the hash join, the situation is different:

SELECT CAST (
    REPLACE (
        REPLACE (
            XEventData.XEvent.value ('(data/value)[1]', 'varchar(max)'),
            '<victim-list>', '<deadlock><victim-list>'),
        '<process-list>', '</victim-list><process-list>')
    AS XML) AS DeadlockGraph
FROM (SELECT CAST (target_data AS XML) AS TargetData
    FROM sys.dm_xe_session_targets st 
    INNER HASH JOIN sys.dm_xe_sessions s ON s.address = st.event_session_address
    WHERE [name] = 'system_health') AS Data
CROSS APPLY TargetData.nodes ('//RingBufferTarget/event') AS XEventData (XEvent)
WHERE XEventData.XEvent.value('@name', 'varchar(4000)') = 'xml_deadlock_report'

Hash 2

A hash join reads its build input completely to construct a hash table before it starts probing for matches. As a result, we have to store all the values, not just the one per thread being worked on from the probe side of the plan. The hash join therefore uses a tempdb work table to store the XML data, and every access to the result of Expr1000 by later operators requires an expensive trip to tempdb:

Slow access

The following shows more details of the slow access path:

Slow details

If a merge join is forced the input rows are sorted (a blocking operation, just like the build input to a hash join) resulting in a similar arrangement where slow access via a tempdb sort-optimized worktable is required because of the size of the data.

Plans that manipulate large data items can be problematic for all sorts of reasons that are not apparent from the execution plan. Using a hash join (with the expression on the correct input) is not a good solution. It relies on undocumented internal behaviour with no guarantees it will work the same way next week, or on a slightly different query.

The message is that XML manipulation can be tricky things to optimize today. Writing the XML to a variable or temporary table before shredding is a much more solid workaround than anything shown above. One way to do this is:

DECLARE @data xml =
        CONVERT
        (
            xml,
            (
            SELECT TOP (1)
                dxst.target_data
            FROM sys.dm_xe_sessions AS dxs 
            JOIN sys.dm_xe_session_targets AS dxst ON
                dxst.event_session_address = dxs.[address]
            WHERE 
                dxs.name = N'system_health'
                AND dxst.target_name = N'ring_buffer'
            )
        )

SELECT XEventData.XEvent.value('(data/value)[1]', 'varchar(max)')
FROM @data.nodes ('./RingBufferTarget/event[@name eq "xml_deadlock_report"]') AS XEventData (XEvent)
WHERE XEventData.XEvent.value('@name', 'varchar(4000)') = 'xml_deadlock_report';

Finally, I just want to add Martin's very nice graphic from the comments below:

Martin's graphic

share|improve this answer
    
Great explanation, thank you. I had read your article on compute scalars too but not put two and two together here. –  Martin Smith Dec 22 '12 at 12:04
1  
I must have messed something up with my attempt at profiling yesterday (maybe muddled up slow and fast traces!). I've redone it today and of course it just shows what you already said. –  Martin Smith Dec 22 '12 at 16:27
    
@MartinSmith That's very cool Martin - how are you producing those traces? Visual Studio? Seems much nicer than my efforts with WinDbg! –  Paul White Dec 22 '12 at 21:22
    
Yes the screenshot is the Call Tree View report from the Visual Studio 2012 profiler. I think the method names look much clearer in your output though without mysterious strings such as @@IEAAXPEA_K appearing. –  Martin Smith Dec 22 '12 at 22:09
add comment

That is the code from my article originally posted here:

http://www.sqlservercentral.com/articles/deadlock/65658/

If you read the comments you will find a couple of alternatives that don't have the performance problems that you are experiencing, one using a modification of that original query, and the other using a variable to hold the XML before processing it which works out better. (see my comments on Page 2) XML from the DMV's can be slow to process, as can parsing XML from the DMF for the file target which often is better accomplished by reading the data into a temp table first and then processing it. XML in SQL is slow by comparison to using things like .NET or SQLCLR.

share|improve this answer
    
Thanks! That did the trick. The one without the variable taking 600ms and 6341 reads and with the variable 303 ms and 3249 lob reads. On 2012 I needed to also add and target_name='ring_buffer' to that version as looks like there are two targets now. I'm still trying to get a mental image of what exactly it is doing in the 20 minute version though. –  Martin Smith Dec 21 '12 at 11:16
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.