SQL Server Performance

Long running query when using sp_executeSQL

Discussion in 'Performance Tuning for DBAs' started by fernando_toledo, Oct 26, 2004.

  1. fernando_toledo New Member

    I`m experiencing some problems when running a query called by sp_executeSQL. When this happens, the query runs for more than 1 hour (I never could wait till its end). But if I run the same query without being called by sp_executeSQL, it takes about 20s. This query runs only once a day, and looking in the syscacheobjects, I couldn`t find its cached exec plan.

    In my experiments I could observe that this can be fixed updating statistics, but I don`t understand why this is happening... Would someone help me out?


    exec sp_executesql N'select
    VW_1.Field_1,
    VW_1.Field_2,
    VW_1.Field_3,
    VW_1.Field_4,
    VW_1.Field_5,
    VW_1.Field_6,
    VW_1.Field_7,
    VW_1.Field_8,
    VW_1.Field_9,
    VW_1.Field_10,
    VW_1.Field_11,
    VW_1.Field_12,
    VW_1.Field_13,
    case
    when TB_1.Field_1 like ''%CDB%'' and VW_1.Field_5 = 1 then 1
    when TB_1.Field_1 like ''%CDI%'' and VW_1.Field_5 = 1 then 2
    end as TpoPapel
    from
    VW_1
    join
    (SELECT
    Field_1,
    Field_2
    FROM
    VW_2
    WHERE
    Field_3 = @P1 AND
    Field_4 = @P2
    GROUP BY
    Field_4,
    Field_2) AS InnerQry
    on
    VW_1.Field_1 = InnerQry.Field_2 and
    VW_1.Field_14 = InnerQry.Field_1
    join
    TB_1
    on
    VW_1.Field_15 = TB_1.Field_1
    where
    VW_1.Field_14 = @P3 and
    VW_1.Field_14 between VW_1.Field_2 and VW_1.Field_3 - 1 and
    VW_1.Field_6 <= 2 and
    (@P4 <= 0 or coalesce(VW_1.Field_1, -1) = @P5)
    ', N'@P1 int,@P2 datetime,@P3 datetime,@P4 int,@P5 int', 43, 'Oct 21 2004 12:00:00:000AM', 'Oct 21 2004 12:00:00:000AM', 0, 0
  2. satya Moderator

    In any case updating the statistics will fine tune the performance of the query by refreshing the execution plans.

    I suggest to refer Kalen Delaney's Inside SQL Server book which contains a very good explanation about caching execution plans.


    Satya SKJ
    Moderator
    http://www.SQL-Server-Performance.Com/forum
    This posting is provided “AS IS” with no rights for the sake of knowledge sharing.
  3. derrickleggett New Member

    Why are you calling it like this? You should be using a stored procedure for this and calling that.

    MeanOldDBA
    derrickleggett@hotmail.com

    When life gives you a lemon, fire the DBA.
  4. Adriaan New Member

    I'll hazard a guess about the nature of VW_1 and VW_2: are they views?

    Try querying the views individually, and see how long it takes for them to return all records on their own. You're using two, so AFAIK they must both finish (time1 + time2) before your query that is based on them can start creating the JOINs (time1 + time2 + time3).

    Like Derrick suggested, rewrite it as a stored procedure. Since you are using criteria that are applied to the (alleged) views, you might be better off by inserting the view definitions as derived tables and include the criteria in the derived tables: that will probably help with time1 and time2.

    I would also use a CASE WHEN VW_1.Field_1 IS NULL THEN -1 ELSE VW_1.Field_1 END instead of COALESCE(VW_1.Field_1, -1). That, or it is perhaps an unnecessary calculation that filters out NULLs (which won't equal any value of @P5 anyway, so no need to bother then).

    A final suggestion is of course to run the Index Tuning Wizard on the whole thing.
  5. fernando_toledo New Member

    Thanks everybody for your replies...

    The thing is a bit more complicated... The company I work for bought an application that dynamically designs this query, so, I can`t turn it to an sp without changing the application (and I cant do that)...

    About the exec plans, please tell me if i`m wrong but without these queries cached (they don`t appear in the syscacheobjects table), the exec plan should be the same using sp_executeSQL or not, once they`re based on the same statistics, right? All the times this problem occurred, I tried to exec both queries (with and without sp_executeSQL), and always without it, the exec time was about 20s or less...

    And yes, Adriaan, vw_1 and vw_2 are views...

    I`ll query these views individually and then I post the results...
  6. fernando_toledo New Member

    I just queried those views, and here goes the results:<br /><br />Vw_1 - Execution time: 2,5 min - Rows returned: 1319849<br /><pre><br />Server Trace:<br />TextEvent ClassDurationCPUReadsWrites<br />-----------------------------------------------------------------------------------------<br />SET STATISTICS PROFILE ON SQL<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted0000<br />select * from VW_1SQL<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted1761411892<br />SET STATISTICS PROFILE OFF SQL<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted0000<br /><br /><br />Statistics:<br />CounterValueAverage<br />-----------------------------------------------------------------------------<br />Application Profile Statistics<br /> Timer resolution (milliseconds)00<br /> Number of INSERT, UPDATE, DELETE statements00<br /> Rows effected by INSERT, UPDATE, DELETE statements00<br /> Number of SELECT statements22<br /> Rows effected by SELECT statements1,31986e+0061,31986e+006<br /> Number of user transactions55<br /> Average fetch time00<br /> Cumulative fetch time00<br /> Number of fetches00<br /> Number of open statement handles00<br /> Max number of opened statement handles00<br /> Cumulative number of statement handles00<br /> <br />Network Statistics<br /> Number of server roundtrips33<br /> Number of TDS packets sent33<br /> Number of TDS packets received5908759087<br /> Number of bytes sent212212<br /> Number of bytes received2,37776e+0082,37776e+008<br /> <br />Time Statistics<br /> Cumulative client processing time11<br /> Cumulative wait time on server replies9,82443e+0089,82443e+008<br /><br /><br /><br />Exec Plan:<br />Select (0%)<br /> |--Merge Join(Inner Join, MANY-TO-MANY MERGE) (0%)<br /> |--Merge Join(Inner Join, MANY-TO-MANY MERGE) (0%)<br /> | |--Clustered Index Scan (75%)<br /> | |--Clustered Index Scan (25%)<br /> |--Clustered Index Scan (29%)<br /><br /><br /><br /><br />Vw_2 - Execution time: 44 sec - Rows returned: 46182<br /><br />Server Trace:<br />TextEvent ClassDurationCPUReadsWrites<br />-----------------------------------------------------------------------------------------<br />SET STATISTICS PROFILE ON SQL<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted0000<br />select * from VW_2SQL<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted542272530<br />SET STATISTICS PROFILE OFF SQL<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted0000<br /><br /><br />Statistics:<br />CounterValueAverage<br />-----------------------------------------------------------------------------<br />Application Profile Statistics<br /> Timer resolution (milliseconds)00<br /> Number of INSERT, UPDATE, DELETE statements00<br /> Rows effected by INSERT, UPDATE, DELETE statements00<br /> Number of SELECT statements22<br /> Rows effected by SELECT statements46222683039<br /> Number of user transactions55<br /> Average fetch time00<br /> Cumulative fetch time00<br /> Number of fetches00<br /> Number of open statement handles00<br /> Max number of opened statement handles00<br /> Cumulative number of statement handles00<br /> <br />Network Statistics<br /> Number of server roundtrips33<br /> Number of TDS packets sent33<br /> Number of TDS packets received194330515<br /> Number of bytes sent208210<br /> Number of bytes received7,79322e+0061,22784e+008<br /> <br />Time Statistics<br /> Cumulative client processing time00,5<br /> Cumulative wait time on server replies503494,91247e+008<br /><br /><br />Exec Plan:<br />Select (0%)<br /> |--Concatenation<br /> |--Compute Scalar (0%)<br /> | |--Compute Scalar (0%)<br /> | |--Stream Aggregate(GROUP BY) (0%)<br /> | |--Sort(ORDER BY) (8%)<br /> | |--Compute Scalar (0%)<br /> | |--Hash Match(Inner Join) (0%)<br /> | |--Clustered Index Scan (11%)<br /> | |--Compute Scalar (0%)<br /> | |--Stream Aggregate(GROUP BY) (0%)<br /> | |--Index Scan (0%)<br /> |--Compute Scalar (0%)<br /> |--Filter(WHERE) (0%)<br /> |--Compute Scalar (0%)<br /> |--Stream Aggregate(GROUP BY) (0%)<br /> |--Sort(ORDER BY) (0%)<br /> |--Concatenation (0%)<br /> |--Stream Aggregate(GROUP BY) (0%)<br /> | |--Sort(ORDER BY) (0%)<br /> | |--Compute Scalar (0%)<br /> | |--Hash Match(Inner Join) (0%)<br /> | |--Clustered Index Scan (11%)<br /> | |--Clustered Index Scan (11%)<br /> |--Hash Match(Aggregate) (3%)<br /> |--Compute Scalar (0%)<br /> |--Hash Match(Inner Join) (0%)<br /> |--Clustered Index Scan (11%)<br /> |--Filter(WHERE) (0%)<br /> |--Hash Match(Right Outer Join) (0%)<br /> |--Clustered Index Scan (11%)<br /> |--Compute Scalar (0%)<br /> |--Merge Join(Inner Join) (0%)<br /> |--Clustered Index Scan (8%)<br /> |--Compute Scalar (0%)<br /> |--Stream Aggregate(GROUP BY) (5%)<br /> |--Sort(ORDER BY) (62%)<br /> |--Hash Match(Inner Join) (0%)<br /> |--Clustered Index Scan (8%)<br /> |--Index Seek (5%)<br /></pre>
  7. Adriaan New Member

    Nothing excessive in the views by themselves, I guess.

    The main thing with VW_2 in the query was that there's a GROUP BY involved, so could you run that part of the query by itself and see how much extra time is needed?

    Next step would be to query VW_1 joined to the "derived view" on VW_2 ...
    then also join TB_1, but without the criteria ...
    and repeat with the criteria ...
    then add some of the expressions from the original SELECT statements, but without the criteria ...
    and finally repeat with the criteria ...

    each time looking at the additional time required.
  8. fernando_toledo New Member

    Here goes the VW_2 subquery with GROUP BY:<br /><b>SELECT Field_1, Field_2 FROM VW_2 GROUP BY Field_4, Field_2</b><br /><br /><font face="Courier New"><br /><pre><br />Event ClassDurationCPUReadsWrites<br />SQL<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted197231660<br /><br /><br />CounterValueAverage<br /><br />Application Profile Statistics<br /> Timer resolution (milliseconds)00<br /> Number of INSERT, UPDATE, DELETE statements00<br /> Rows effected by INSERT, UPDATE, DELETE statements00<br /> Number of SELECT statements22<br /> Rows effected by SELECT statements3926839268<br /> Number of user transactions55<br /> Average fetch time00<br /> Cumulative fetch time00<br /> Number of fetches00<br /> Number of open statement handles00<br /> Max number of opened statement handles00<br /> Cumulative number of statement handles00<br /> <br />Network Statistics<br /> Number of server roundtrips33<br /> Number of TDS packets sent33<br /> Number of TDS packets received209209<br /> Number of bytes sent328328<br /> Number of bytes received770631770631<br /> <br />Time Statistics<br /> Cumulative client processing time116116<br /> Cumulative wait time on server replies1,14149e+0081,14149e+008<br /><br /><br />Exec Plan:<br /><br />Select (0%)<br /> |--Hash Match(Aggregate, HASH) (3%)<br /> |--Concatenation (0%)<br /> |--Hash Match(Aggregate, HASH) (8%)<br /> | |--Merge Join(Inner Join, MERGE) (0%)<br /> | |--Filter(WHERE) (0%)<br /> | | |--Bookmark Lookup (6%)<br /> | | |--Index Scan (11%)<br /> | |--Index Scan (0%)<br /> |--Filter(WHERE) (0%)<br /> |--Compute Scalar (0%)<br /> |--Stream Aggregate(GROUP BY) (0%)<br /> |--Sort(ORDER BY) (0%)<br /> |--Concatenation (0%)<br /> |--Stream Aggregate(GROUP BY) (0%)<br /> | |--Sort(ORDER BY) (0%) (0%)<br /> | |--Compute Scalar (0%)<br /> | |--Hash Match(Inner Join, HASH) (0%)<br /> | |--Clustered Index Scan (11%)<br /> | |--Clustered Index Scan (11%)<br /> |--Hash Match(Aggregate, HASH) (3%)<br /> |--Compute Scalar (0%)<br /> |--Hash Match(Inner Join, HASH) (0%)<br /> |--Clustered Index Scan (11%)<br /> |--Filter(WHERE) (0%)<br /> |--Hash Match(Right Outer Join, HASH) (0%)<br /> |--Clustered Index Scan (11%)<br /> |--Compute Scalar (0%)<br /> |--Merge Join(Inner Join, MERGE) (0%)<br /> |--Clustered Index Scan (8%)<br /> |--Compute Scalar (0%)<br /> |--Stream Aggregate(GROUP BY) (6%)<br /> |--Sort (64%)<br /> |--Hash Match(Inner Join, HASH) (0%)<br /> |--Clustered Index Scan (8%)<br /> |--Index Seek (6%)<br /></pre><br /></font id="Courier New"><br />
  9. Adriaan New Member

    Still nothing excessive, I guess.

    You didn't mention the execution time, but the Duration for the GROUP BY is 197 instead of 54 for the straight SELECT, so from 44 seconds it would translate to about 3 minutes?

    What happens once you add the JOINs and the criteria should tell us a lot more. Could you just report the timing? We can look into the other details if necessary.
  10. fernando_toledo New Member

    Actually not, Adriaan... the exec time was 36 sec...<br /><br /><br />Running the whole query with sp_executeSQL, here are the results:<br /><br />Exec time: 27s - Rows returned: 138<br /><font face="Courier New"><pre><br />Trace:<br />TextEvent ClassDurationCPUReadsWrites<br />select ...SP<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted1582422031<br />exec sp_executesql N'select...SQL<img src='/community/emoticons/emotion-7.gif' alt=':S' />tmtCompleted1582422031<br /><br /><br />Statistics:<br />Application Profile Statistics<br /> Timer resolution (milliseconds)00<br /> Number of INSERT, UPDATE, DELETE statements00<br /> Rows effected by INSERT, UPDATE, DELETE statements00<br /> Number of SELECT statements33<br /> Rows effected by SELECT statements6868<br /> Number of user transactions1010<br /> Average fetch time00<br /> Cumulative fetch time00<br /> Number of fetches00<br /> Number of open statement handles00<br /> Max number of opened statement handles00<br /> Cumulative number of statement handles00<br /> <br />Network Statistics<br /> Number of server roundtrips44<br /> Number of TDS packets sent44<br /> Number of TDS packets received3737<br /> Number of bytes sent43184318<br /> Number of bytes received130688130688<br /> <br />Time Statistics<br /> Cumulative client processing time3131<br /> Cumulative wait time on server replies2698126981<br /><br /><br />Exec Plan:<br />Select (0%)<br /> Compute Scalar (0%)<br /> |--Nested Loops(Inner Join, OUTER REFERENCES) (0%)<br /> |--Nested Loops(Inner Join, OUTER REFERENCES) (0%)<br /> | |--Nested Loops(Inner Join, OUTER REFERENCES) (0%)<br /> | | |--Nested Loops(Inner Join, OUTER REFERENCES) (0%)<br /> | | | |--Stream Aggregate(GROUP BY) (0%)<br /> | | | | |--Merge Join(Concatenation) (0%)<br /> | | | | |--Sort (0%)<br /> | | | | | |--Nested Loops(Inner Join) (0%)<br /> | | | | | |--Clustered Index Seek (0%)<br /> | | | | | |--Index Seek (10%)<br /> | | | | |--Filter(WHERE) (0%)<br /> | | | | |--Compute Scalar (0%)<br /> | | | | |--Stream Aggregate(GROUP BY) (0%)<br /> | | | | |--Sort(ORDER BY) (0%)<br /> | | | | |--Concatenation (0%)<br /> | | | | |--Compute Scalar (0%)<br /> | | | | | |--Nested Loops(Inner Join, WHERE) (0%)<br /> | | | | | |--Clustered Index Seek (10%)<br /> | | | | | |--Clustered Index Scan (13%)<br /> | | | | |--Compute Scalar (0%)<br /> | | | | |--Filter(WHERE) (0%)<br /> | | | | |--Nested Loops(Left Outer Join, OUTER REFERENCES) (0%)<br /> | | | | |--Nested Loops(Inner Join, WHERE) (0%)<br /> | | | | | |--Clustered Index Seek (10%)<br /> | | | | | |--Compute Scalar (0%)<br /> | | | | | |--Nested Loops(Inner Join, OUTER REFERENCES) (0%)<br /> | | | | | |--Compute Scalar (0%)<br /> | | | | | | |--Stream Aggregate(GROUP BY) (0%)<br /> | | | | | | |--Sort(ORDER BY) (74%)<br /> | | | | | | |--Nested Loops(Inner Join, WHERE) (0%)<br /> | | | | | | |--Clustered Index Seek (10%)<br /> | | | | | | |--Index Seek (6%)<br /> | | | | | |--Row Count Spool (0%)<br /> | | | | | |--Index Spool(SEEK) (16%)<br /> | | | | | |--Clustered Index Seek (10%)<br /> | | | | |--Clustered Index Seek (10%)<br /> | | | |--Clustered Index Seek (10%)<br /> | | |--Clustered Index Seek (10%)<br /> | |--Clustered Index Seek (10%)<br /> |--Clustered Index Seek (10%)<br /></pre></font id="Courier New">
  11. Adriaan New Member

    Okay, I shouldn't make so many guesses [<img src='/community/emoticons/emotion-1.gif' alt=':)' />]<br /><br />For this last test, the one that ended in 27 seconds, did you use the same parameters, and against the same data as for the session that you broke off after an hour?
  12. fernando_toledo New Member

    <font face="Tahoma"><br />No worries... all the guesses are welcome... [<img src='/community/emoticons/emotion-1.gif' alt=':)' />]<br /><br />For this last test, i've used the same parameters of the first topic...<br /><br />Something I can`t understand is how come the exec plans for this query can be different once it`s being compiled at execution time, based on the same statistics, just using the sp_executeSQL proc...<br /><br />Here is a plan of the same query above, just <b>without the sp_executeSQL</b>:<br /><pre><br />Select (0%)<br /> Compute Scalar (0%)<br /> |--Nested Loops(Inner Join, OUTER REFERENCES) (0%)<br /> |--Nested Loops(Inner Join, OUTER REFERENCES) (0%)<br /> | |--Hash Match(Inner Join, HASH) (14%)<br /> | | |--Stream Aggregate(GROUP BY) (0%)<br /> | | | |--Merge Join(Concatenation) (0%)<br /> | | | |--Sort(DISTINCT ORDER BY) (0%)<br /> | | | | |--Nested Loops(Inner Join) (0%)<br /> | | | | |--Clustered Index Seek (43%)<br /> | | | | |--Index Seek (43%)<br /> | | | |--Filter(WHERE) (0%)<br /> | | | |--Compute Scalar (0%)<br /> | | | |--Stream Aggregate(GROUP BY) (0%)<br /> | | | |--Sort(ORDER BY) (0%)<br /> | | | |--Concatenation (0%)<br /> | | | |--Compute Scalar (0%)<br /> | | | | |--Nested Loops(Inner Join, WHERE) (0%)<br /> | | | | |--Clustered Index Seek (43%)<br /> | | | | |--Clustered Index Scan (57%)<br /> | | | |--Compute Scalar (0%)<br /> | | | |--Filter(WHERE) (0%)<br /> | | | |--Hash Match(Right Outer Join, HASH) (0%)<br /> | | | |--Clustered Index Scan (57%)<br /> | | | |--Nested Loops(Inner Join, WHERE) (0%)<br /> | | | |--Clustered Index Seek (43%)<br /> | | | |--Compute Scalar (0%)<br /> | | | |--Nested Loops(Inner Join, WHERE) (0%)<br /> | | | |--Clustered Index Seek (43%)<br /> | | | |--Compute Scalar (0%)<br /> | | | |--Hash Match(Aggregate, HASH) (43%)<br /> | | | |--Nested Loops(Inner Join, WHERE) (0%)<br /> | | | |--Clustered Index Seek (43%)<br /> | | | |--Index Seek (29%)<br /> | | |--Hash Match(Inner Join, HASH) (0%)<br /> | | |--Clustered Index Scan (43%)<br /> | | |--Clustered Index Scan (114%)<br /> | |--Clustered Index Seek (14%)<br /> |--Clustered Index Seek (57%)<br /></pre></font id="Tahoma">
  13. fernando_toledo New Member

    Does anyone has gone thru this?
    sp_executeSQL exec plan worse than QA exec plan (both without cache)?

    Any thought are more than welcome...
  14. v1rtu0s1ty New Member

    Hi Frank,

    I'm no guru in this field. I have read in an article that when using sp_executesql, you should do fully qualified naming or else, it won't be reused.

    Question though, how were you able to produce that kind of result(the ones with percentages in every line)? Did you use QA? If so, how? I have a query that I would like to seek help regarding execution plan but it look different on my output,http://www.restricted.dyndns.org/target/executionplan.txt

    It's actually posted on the other thread.

    Thanks
  15. jdavis New Member

    Yes! I am interested in how you got your results and I am also interested in what you chose in Profiler and how you ran it. Kinda of a newbie with Profiler.

    Cheers,
    John Davis
  16. v1rtu0s1ty New Member

    Hi Fernando,

    How were you able to produce that tree?
  17. fernando_toledo New Member

    Hi y'all!

    v1rtu0s1ty, neither I am... but you`re right, if you don`t use the full qualified name, the cached plan will be reused just by the exactly same query, which isn`t the ideal... Also, I couldn`t see your exec plan output, my proxy server blocked the text file... but I suppose you got the same tree, just without the percentages, right?

    Actually that tree was produced by using SET SHOWPLAN_ALL ON but those percentages aren`t generated... You can calculate them using the "TotalSubtreeCost" col or get them at the exec plan...

    jdavis, it depends on what you want to trace, which are your needs...

Share This Page