3

Two actual query plans were captured for two executions of one query:

Plan "Fast" took ~1s and occurs about 90% of the time.

Plan "Slow" took ~16s.

Since the graphical plans look identical to me, I dumped the XML versions and performed a diff to look at the text differences to be sure.

There are 2 "SpillToTempDb" warnings on the fast side and four on the slow side. Looking that the 2 extra on the slow side:

One SpillToTempDb warning on "Parallelism (Repartition Streams) Cost 1%":

    <SpillToTempDb SpillLevel="0" />

On SpillToTempDb warning on "Parallelism (Distribute Streams) Cost 1%":

    <SpillToTempDb SpillLevel="0" />

The cost is the same (1%) for both the slow and fast cases. Does that mean the warning can be ignored? Is there a way to show "actual" times or costs. That would be so much better! Actual row counts are the same for the operation with the spill.

Besides performing a manual text diff of xml execution plans to find the differences in warnings, how can I tell what the 1500% increase in runtime is actually due to?

Differences except "RunTimeCountersPerThread" lines:

Left file: C:\Users\chrisr\Desktop\fast.sqlplan     Right file: C:\Users\chrisr\Desktop\slow.sqlplan
10                    <ThreadStat Branches="10" UsedThreads="85">
     10               <ThreadStat Branches="10" UsedThreads="73">
------------------------------------------------------------------------
------------------------------------------------------------------------
19                    <MemoryGrantInfo SerialRequiredMemory="1536" SerialDesiredMemory="10816" RequiredMemory="124224" DesiredMemory="133536" RequestedMemory="133536" GrantWaitTime="0" GrantedMemory="133536" MaxUsedMemory="105440" />
     19               <MemoryGrantInfo SerialRequiredMemory="1536" SerialDesiredMemory="10816" RequiredMemory="124224" DesiredMemory="133536" RequestedMemory="133536" GrantWaitTime="0" GrantedMemory="133536" MaxUsedMemory="107840" />


------------------------------------------------------------------------
     276                                                    <Warnings>
     277                                                      <SpillToTempDb SpillLevel="0" />
     278                                                    </Warnings>
------------------------------------------------------------------------------------------------------------------------------------------------
     630                                                                <Warnings>
     631                                                                  <SpillToTempDb SpillLevel="0" />
     632                                                                </Warnings>
------------------------------------------------------------------------

For slow case, tempdb before/after (select * sys.fn_virtualfilestats(db_id('tempdb'),null)) ( only showing a few 100ms of latency ): TempDbBeforeAfter

Should I be looking at the differences in the RunTimeCountersPerThread lines? It appears it is just the order that is different between the Threads.

Possible hint (2013/04/26): The query performs multiple inner merge joins and I found this on Paul White's blog:

Exchange Spills

Posted by: Paul White NZ (view profile) Posted on: Monday, March 07, 2011 at 3:29 AM

...these are almost always caused by a sequence of exchanges operation in order-preserving mode, separated by one or more operators that require sorted input e.g. Merge Join, Stream Aggregate, Segment...

In SQL Server 2008 there is a Profiler event to show when this type of exchange 'deadlock' is resolved by spilling exchange packets to disk.

The primary workaround is to avoid these plan shapes (especially parallel Merge Join at high DOP, in my experience). It is sometimes enough to force a hash or loop join instead using a hint, but this is advanced tuning and really requires detailed knowledge of the data concerned.

1
  • 1
    Posting the plans would be the fastest route to a useful answer. Apr 27, 2013 at 1:31

1 Answer 1

6

The cost is the same (1%) for both the slow and fast cases. Does that mean the warning can be ignored? Is there a way to show "actual" times or costs. That would be so much better! Actual row counts are the same for the operation with the spill.

The cost shown is always the optimizer's estimated cost of the iterator, computed according to its internal model. This model does not reflect your server's particular performance characteristics; it is an abstraction that happens to produce reasonable plan shapes most of the time for most queries on most systems. There is no way to show 'actual' costs/execution times per iterator.

Besides performing a manual text diff of xml execution plans to find the differences in warnings, how can I tell what the 1500% increase in runtime is actually due to?

Typically, you can't. Spill warnings (sorts, hashes, exchanges) are new in execution plans for 2012, but they are just an indication of something you should investigate and look to eliminate if possible. The impact of a particular spill is something that needs to be measured - it is not possible to say that a spill of a particular type will always result in an x% performance drop for example.

For slow case, tempdb before/after (select * sys.fn_virtualfilestats(db_id('tempdb'),null)) (only showing a few 100ms of latency)

Spilling to tempdb and back is certainly undesirable, but the overall impact is hard to assess. For sort and hash spills, the impact is largely due to the I/O and access pattern, which may be small-block synchronous I/O e.g. for sort spills. With ~100ms of latency, you don't need too many synchronous I/Os to introduce a significant delay. The nature of the process and I/O patterns means tempdb spills can still be a problem on very low latency storage systems like fusion-io.

For exchange spills, there is an extra delay. The intra-query deadlock must be detected by the regular deadlock monitor, which by default only wakes up once every 5 seconds (more frequently if a deadlock has been found recently).

The resolver must then choose one or more victims, and spool exchange buffers to tempdb until the deadlock is resolved. The amount of spooling needed and the complexity of the deadlock will largely determine how long this takes.

Ultimately, preserved ordering is a Very Bad Thing for parallelism in general. Ideally, we want multiple concurrent threads operating on data streams with no inter-dependence. Preserving sort order introduces dependencies, so producer and consumer threads in different parallel branches can become deadlocked waiting for order-preserving iterators to receive rows to decide which input sorts next in sequence.

The precise nature of the deadlock depends on data distribution and per-thread sort order at runtime, so it is typically very hard to debug. Hence my recommendation to avoid order-preserving iterators in parallel plans, especially at high DOP. I do explain a very simplified example of an order-preserving parallel deadlock in some talks I do, but real examples are always more complex, though the underlying cause is the same.

In case the concepts are not familiar, it may help to follow the following example, reproduced from the (somewhat epic) 1993 paper Query Evaluation Techniques for Large Databases by Goetz Graefe:

Figure 37

If a different partitioning strategy than range-partitioning is used, sorting with subsequent partitioning is not guaranteed to be deadlock-free in all situations. Deadlock will occur if (i) multiple consumers feed multiple producers, and (ii) each producer produces a sorted stream and each consumer merges multiple sorted streams, and (iii) some key-based partitioning rule is used other than range partitioning, i.e., hash partitioning, and (iv) flow control is enabled, and (v) the data distribution is particularly unfortunate.

Figure 37 shows a scenario with two producer and two consumer processes, i.e., both the producer operators and the consumer operators are executed with a degree of parallelism of two. The circles in Figure 37 indicate processes, and the arrows indicate data paths. Presume that the left sort produces the stream 1, 3, 5, 7, ..., 999, 1002, 1004, 1006, 1008, ..., 2000 while the right sort produces 2, 4, 6, 8, ..., 1000, 1001, 1003, 1005, 1007, ..., 1999.

The merge operations in the consumer processes must receive the first item from each producer process before they can create their first output item and remove additional items from their input buffers. However, the producers will need to produce 500 items each (and insert them into one consumer’s input buffer, all 500 for one consumer) before they will send their first item to the other consumer. The data exchange buffer needs to hold 1000 items at one point of time, 500 on each side of Figure 37. If flow control is enabled and the exchange buffer (flow control slack) is less than 500 items, deadlock will occur.

The reason deadlock can occur in this situation is that the producer processes need to ship data in the order obtained from their input subplan (the sort in Figure 37) while the consumer processes need to receive data in sorted order as required by the merge. Thus, there are two sides which both require absolute control over the order in which data pass over the process boundary. If the two requirements are incompatible, an unbounded buffer is required to ensure freedom from deadlock.

1
  • Accepting this answer. For the record: No hints = ~4s, Merge hints = ~14s (with spills); merge hints with option recompile ~1.5s, hash hints 3s (with hash warning), hash hints with recompile: 1.3s (and pretty consistent). Note that the join order was bad. After improving the join order merge join with option recompile is 1.1s to 1.3s and hash hints with recompile are similar. It seems the recompile is very helpful. When it finds the row estimates are too far off does it try again (that's not how the docs read)? Robust Plan gave ~3s on average for hash.
    – crokusek
    Apr 29, 2013 at 18:37

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

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