Uneven query executions with parallelism

Published Jan 15 2019 02:56 PM 178 Views
Microsoft
First published on MSDN on Dec 21, 2012

We had a customer who was doing stress testing on a machine with 40 cores.   They designed a program that would launch multiple connections to execute the same query repeatedly based on their requirement to handle multiple concurrent executions.   The query was very CPU intensive and a parallel plan was generated.   As they increased concurrent connections to hundreds, the CPU would be pegged 100%.

What they noticed was that some connections executed the query far fewer times than others.  In other words, the same query didn’t result in same execution time.

On the one hand, driving up CPU to 100% in a sustained period not healthy and the query needed to be tuned.  On the other hand,  the customer was puzzled as why the same query executions result in a large variation in terms of execution time.  Some took much longer than others.   They needed us to find out root cause.

First thing we did was to verify if there were different query plans for the same query.  From looking at execution plans, they appeared to be the same.  That made us really puzzled.

As it turned out, the plans were the same.  But during execution phase, SQL Server decided how many threads to use for each execution of the query based on the load.  In customer’s situation, because the  CPU was pegged and very busy, SQL Server chose to execute some of the query serially.  In other words, the parallel plan didn’t get executed with multiple threads.  This created ‘uneven’ times because some were indeed  executed with multiple threads and others were serially executed.

It’s not easy to spot this problem though.  You will need to get “Showplan XML Statistics Profile” trace event.

Even after you get the trace event, it’s hard to spot the difference.   You will have to understand what specific operator is doing and determine actual parallelism has occurred.

In the following two screenshots (figures 1 and 2).    It’s the same plan.  In this hash match operation, both builds and probes sides are parallelized.   I am showing the scan for build input (scanning _dta_mv_45.dta_index_…).  If you look closely, there are differences between the two.   For figure 1, “number of executions” is 1.  But for figure 2, “number of executions” is 2.

What this means is that the second plan (figure 2) was truly parallelized.  But figure 1, it was a serial execution.

Figure 1

Figure 2

Another quick way to identify this is to open the .sqlplan file in a text editor and search for “RunTimeCountersPerThread “.  If all you are seeing is RunTimeCountersPerThread Thread="0", then the plan was never parallelized.  It executed serially.   Here is an example where parallel threads were used.


<RunTimeCountersPerThread Thread="2" ActualRows="63125" Batches="0" ActualExecutionMode="Row"  ActualEndOfScans="1" ActualExecutions="1" />
< RunTimeCountersPerThread Thread="1" ActualRows="75847" Batches="0" ActualExecutionMode="Row" ActualEndOfScans="1" ActualExecutions="1" />
< RunTimeCountersPerThread Thread="0" ActualRows="0" ActualEndOfScans="0" ActualExecutions="0" />

Note that:  In this post , we also talked about how to use RunTimeCountersPerThread to help solve another issue related to reindexing.

Summary

When your query is compiled with parallelism, there is no guarantee that it will be executed with multiple threads.  SQL Server can choose to execute the query with or without parallelism depending on current load of the system.   If the server is very busy, this can create some ‘uneven’ response time for the same query with multiple executions.  For highly concurrent system, you can reduce DOP to  even out this type of variations.   Or you can tune your query to reduce the need for parallelism and increase concurrency.

%3CLINGO-SUB%20id%3D%22lingo-sub-317495%22%20slang%3D%22en-US%22%3EUneven%20query%20executions%20with%20parallelism%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-317495%22%20slang%3D%22en-US%22%3E%0A%20%26lt%3Bmeta%20http-equiv%3D%22Content-Type%22%20content%3D%22text%2Fhtml%3B%20charset%3DUTF-8%22%20%2F%26gt%3B%3CSTRONG%3E%20First%20published%20on%20MSDN%20on%20Dec%2021%2C%202012%20%3C%2FSTRONG%3E%20%3CBR%20%2F%3E%3CP%3EWe%20had%20a%20customer%20who%20was%20doing%20stress%20testing%20on%20a%20machine%20with%2040%20cores.%26nbsp%3B%26nbsp%3B%20They%20designed%20a%20program%20that%20would%20launch%20multiple%20connections%20to%20execute%20the%20same%20query%20repeatedly%20based%20on%20their%20requirement%20to%20handle%20multiple%20concurrent%20executions.%26nbsp%3B%26nbsp%3B%20The%20query%20was%20very%20CPU%20intensive%20and%20a%20parallel%20plan%20was%20generated.%26nbsp%3B%26nbsp%3B%20As%20they%20increased%20concurrent%20connections%20to%20hundreds%2C%20the%20CPU%20would%20be%20pegged%20100%25.%3C%2FP%3E%0A%20%20%3CP%3EWhat%20they%20noticed%20was%20that%20some%20connections%20executed%20the%20query%20far%20fewer%20times%20than%20others.%26nbsp%3B%20In%20other%20words%2C%20the%20same%20query%20didn%E2%80%99t%20result%20in%20same%20execution%20time.%3C%2FP%3E%0A%20%20%3CP%3EOn%20the%20one%20hand%2C%20driving%20up%20CPU%20to%20100%25%20in%20a%20sustained%20period%20not%20healthy%20and%20the%20query%20needed%20to%20be%20tuned.%26nbsp%3B%20On%20the%20other%20hand%2C%26nbsp%3B%20the%20customer%20was%20puzzled%20as%20why%20the%20same%20query%20executions%20result%20in%20a%20large%20variation%20in%20terms%20of%20execution%20time.%26nbsp%3B%20Some%20took%20much%20longer%20than%20others.%26nbsp%3B%26nbsp%3B%20They%20needed%20us%20to%20find%20out%20root%20cause.%3C%2FP%3E%0A%20%20%3CP%3EFirst%20thing%20we%20did%20was%20to%20verify%20if%20there%20were%20different%20query%20plans%20for%20the%20same%20query.%26nbsp%3B%20From%20looking%20at%20execution%20plans%2C%20they%20appeared%20to%20be%20the%20same.%26nbsp%3B%20That%20made%20us%20really%20puzzled.%3C%2FP%3E%0A%20%20%3CP%3EAs%20it%20turned%20out%2C%20the%20plans%20were%20the%20same.%26nbsp%3B%20But%20during%20execution%20phase%2C%20SQL%20Server%20decided%20how%20many%20threads%20to%20use%20for%20each%20execution%20of%20the%20query%20based%20on%20the%20load.%26nbsp%3B%20In%20customer%E2%80%99s%20situation%2C%20because%20the%26nbsp%3B%20CPU%20was%20pegged%20and%20very%20busy%2C%20SQL%20Server%20chose%20to%20execute%20some%20of%20the%20query%20serially.%26nbsp%3B%20In%20other%20words%2C%20the%20parallel%20plan%20didn%E2%80%99t%20get%20executed%20with%20multiple%20threads.%26nbsp%3B%20This%20created%20%E2%80%98uneven%E2%80%99%20times%20because%20some%20were%20indeed%26nbsp%3B%20executed%20with%20multiple%20threads%20and%20others%20were%20serially%20executed.%3C%2FP%3E%0A%20%20%3CP%3EIt%E2%80%99s%20not%20easy%20to%20spot%20this%20problem%20though.%26nbsp%3B%20You%20will%20need%20to%20get%20%E2%80%9CShowplan%20XML%20Statistics%20Profile%E2%80%9D%20trace%20event.%3C%2FP%3E%0A%20%20%3CP%3EEven%20after%20you%20get%20the%20trace%20event%2C%20it%E2%80%99s%20hard%20to%20spot%20the%20difference.%26nbsp%3B%26nbsp%3B%20You%20will%20have%20to%20understand%20what%20specific%20operator%20is%20doing%20and%20determine%20actual%20parallelism%20has%20occurred.%3C%2FP%3E%0A%20%20%3CP%3EIn%20the%20following%20two%20screenshots%20(figures%201%20and%202).%26nbsp%3B%26nbsp%3B%26nbsp%3B%20It%E2%80%99s%20the%20same%20plan.%26nbsp%3B%20In%20this%20hash%20match%20operation%2C%20both%20builds%20and%20probes%20sides%20are%20parallelized.%26nbsp%3B%26nbsp%3B%20I%20am%20showing%20the%20scan%20for%20build%20input%20(scanning%20_dta_mv_45.dta_index_%E2%80%A6).%26nbsp%3B%20If%20you%20look%20closely%2C%20there%20are%20differences%20between%20the%20two.%26nbsp%3B%26nbsp%3B%20For%20figure%201%2C%20%E2%80%9Cnumber%20of%20executions%E2%80%9D%20is%201.%26nbsp%3B%20But%20for%20figure%202%2C%20%E2%80%9Cnumber%20of%20executions%E2%80%9D%20is%202.%3C%2FP%3E%0A%20%20%3CP%3EWhat%20this%20means%20is%20that%20the%20second%20plan%20(figure%202)%20was%20truly%20parallelized.%26nbsp%3B%20But%20figure%201%2C%20it%20was%20a%20serial%20execution.%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CSTRONG%3E%20Figure%201%20%3C%2FSTRONG%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CIMG%20src%3D%22https%3A%2F%2Ftechcommunity.microsoft.com%2Ft5%2Fimage%2Fserverpage%2Fimage-id%2F67460i7FF213C16619F95A%22%20%2F%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CSTRONG%3E%20Figure%202%20%3C%2FSTRONG%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CIMG%20src%3D%22https%3A%2F%2Ftechcommunity.microsoft.com%2Ft5%2Fimage%2Fserverpage%2Fimage-id%2F67462iC72A90AC28750208%22%20%2F%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3EAnother%20quick%20way%20to%20identify%20this%20is%20to%20open%20the%20.sqlplan%20file%20in%20a%20text%20editor%20and%20search%20for%20%E2%80%9CRunTimeCountersPerThread%20%E2%80%9C.%26nbsp%3B%20If%20all%20you%20are%20seeing%20is%20RunTimeCountersPerThread%20Thread%3D%220%22%2C%20then%20the%20plan%20was%20never%20parallelized.%26nbsp%3B%20It%20executed%20serially.%26nbsp%3B%26nbsp%3B%20Here%20is%20an%20example%20where%20parallel%20threads%20were%20used.%3C%2FP%3E%0A%20%20%3CP%3E%3CBR%20%2F%3E%20%3CSTRONG%3E%20%3CRUNTIMECOUNTERSPERTHREAD%20thread%3D%22%26quot%3B2%26quot%3B%22%20actualrows%3D%22%26quot%3B63125%26quot%3B%22%20batches%3D%22%26quot%3B0%26quot%3B%22%20actualexecutionmode%3D%22%26quot%3BRow%26quot%3B%26nbsp%3B%22%20actualendofscans%3D%22%26quot%3B1%26quot%3B%22%20actualexecutions%3D%22%26quot%3B1%26quot%3B%22%3E%3C%2FRUNTIMECOUNTERSPERTHREAD%3E%20%3CBR%20%2F%3E%20%26lt%3B%20RunTimeCountersPerThread%20Thread%3D%221%22%20ActualRows%3D%2275847%22%20Batches%3D%220%22%20ActualExecutionMode%3D%22Row%22%20ActualEndOfScans%3D%221%22%20ActualExecutions%3D%221%22%20%2F%26gt%3B%20%3CBR%20%2F%3E%20%26lt%3B%20RunTimeCountersPerThread%20Thread%3D%220%22%20ActualRows%3D%220%22%20ActualEndOfScans%3D%220%22%20ActualExecutions%3D%220%22%20%2F%26gt%3B%20%3CBR%20%2F%3E%20%3C%2FSTRONG%3E%3C%2FP%3E%0A%20%20%3CP%3ENote%20that%3A%26nbsp%3B%20In%20%3CA%20href%3D%22http%3A%2F%2Fblogs.msdn.com%2Fb%2Fpsssql%2Farchive%2F2009%2F03%2F18%2Fbe-aware-of-parallel-index-creation-performance-issues.aspx%22%20target%3D%22_blank%22%20rel%3D%22noopener%20noreferrer%22%3E%20this%20post%20%3C%2FA%3E%20%2C%20we%20also%20talked%20about%20how%20to%20use%20RunTimeCountersPerThread%20to%20help%20solve%20another%20issue%20related%20to%20reindexing.%3C%2FP%3E%0A%20%20%3CP%3E%3C%2FP%3E%0A%20%20%3CP%3E%3CSTRONG%3E%20Summary%20%3C%2FSTRONG%3E%3C%2FP%3E%0A%20%20%3CP%3EWhen%20your%20query%20is%20compiled%20with%20parallelism%2C%20there%20is%20no%20guarantee%20that%20it%20will%20be%20executed%20with%20multiple%20threads.%26nbsp%3B%20SQL%20Server%20can%20choose%20to%20execute%20the%20query%20with%20or%20without%20parallelism%20depending%20on%20current%20load%20of%20the%20system.%26nbsp%3B%26nbsp%3B%20If%20the%20server%20is%20very%20busy%2C%20this%20can%20create%20some%20%E2%80%98uneven%E2%80%99%20response%20time%20for%20the%20same%20query%20with%20multiple%20executions.%26nbsp%3B%20For%20highly%20concurrent%20system%2C%20you%20can%20reduce%20DOP%20to%26nbsp%3B%20even%20out%20this%20type%20of%20variations.%26nbsp%3B%26nbsp%3B%20Or%20you%20can%20tune%20your%20query%20to%20reduce%20the%20need%20for%20parallelism%20and%20increase%20concurrency.%3C%2FP%3E%0A%20%0A%3C%2FLINGO-BODY%3E%3CLINGO-TEASER%20id%3D%22lingo-teaser-317495%22%20slang%3D%22en-US%22%3EFirst%20published%20on%20MSDN%20on%20Dec%2021%2C%202012%20We%20had%20a%20customer%20who%20was%20doing%20stress%20testing%20on%20a%20machine%20with%2040%20cores.%3C%2FLINGO-TEASER%3E%3CLINGO-LABS%20id%3D%22lingo-labs-317495%22%20slang%3D%22en-US%22%3E%3CLINGO-LABEL%3EPerformance%3C%2FLINGO-LABEL%3E%3CLINGO-LABEL%3ESQL%20OS%3C%2FLINGO-LABEL%3E%3C%2FLINGO-LABS%3E
Version history
Last update:
‎Jan 15 2019 02:56 PM
Updated by: