Skip to main content
2 of 3
added tempdb stats screenshot
crokusek
  • 2.2k
  • 4
  • 26
  • 34

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

crokusek
  • 2.2k
  • 4
  • 26
  • 34