How to determine cause of runtime increase given two query plans with SpillToTempDb warning 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%":

    &lt;SpillToTempDb SpillLevel="0" /&gt;

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

    &lt;SpillToTempDb SpillLevel="0" /&gt;


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                    &lt;ThreadStat Branches="10" UsedThreads="85"&gt;
     10               &lt;ThreadStat Branches="10" UsedThreads="73"&gt;
------------------------------------------------------------------------
------------------------------------------------------------------------
19                    &lt;MemoryGrantInfo SerialRequiredMemory="1536" SerialDesiredMemory="10816" RequiredMemory="124224" DesiredMemory="133536" RequestedMemory="133536" GrantWaitTime="0" GrantedMemory="133536" MaxUsedMemory="105440" /&gt;
     19               &lt;MemoryGrantInfo SerialRequiredMemory="1536" SerialDesiredMemory="10816" RequiredMemory="124224" DesiredMemory="133536" RequestedMemory="133536" GrantWaitTime="0" GrantedMemory="133536" MaxUsedMemory="107840" /&gt;


------------------------------------------------------------------------
     276                                                    &lt;Warnings&gt;
     277                                                      &lt;SpillToTempDb SpillLevel="0" /&gt;
     278                                                    &lt;/Warnings&gt;
------------------------------------------------------------------------------------------------------------------------------------------------
     630                                                                &lt;Warnings&gt;
     631                                                                  &lt;SpillToTempDb SpillLevel="0" /&gt;
     632                                                                &lt;/Warnings&gt;
------------------------------------------------------------------------


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


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.
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:




  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.