0

We have an SSRS report that is based on about 8 stored procedures which was running fine up until a few days ago. The report used to run in about 2 hours. Last Sunday (September 15 2019) it suddenly started timing out based on the SSRS timeout setting. We changed this to more time and found that it finishes after 6 hours. We're also seeing CPU contention when this report runs that we didn't see previously. What's strange is that I can't seem to find any apparent changes that would account for this:

The SP is using the same query plan it's used for weeks. So, in QueryStore you can see it completing in its usual 2 hours for days and suddenly spike 9/15. Even after a restart, the same plan was picked and it isn't being forced.

The underlying server is virtual, but we didn't change any resources until a few days later when we ended up adding more cores (which helped). Our VM guy isn't seeing any underlying hardware contention and from what I've seen, he's right.

The SSRS report itself wasn't changed. Same subscription, same configuration (other than the timeout setting being changed after the first night of bad performance). Statistics are set to update right before this report kicks off.

I'm pretty stumped here. I hate that for now we've had to settle with just throwing more resources at it. I tried searching for this issue online, but no one else seems to have posted about this specific scenario. Any suggestions? Below is the part of the code that takes up to 6 hours total.

EDIT: Link to Query plan: https://www.brentozar.com/pastetheplan/?id=SJ0XtSWwH

SELECT DISTINCT Object1.Column1
    , Function1(CASE 
            WHEN Object1.Column2 IN (?) AND LEFT(Object1.Column3,?) = ?
                THEN ?
            WHEN Object1.Column2 IN (?) AND LEFT(Object1.Column3,?) = ?
                THEN ?
            ELSE ?
            END) OVER (PARTITION BY Object1.Column1) AS Column4
    , Function1(CASE 
            WHEN Object1.Column2 IN (?) AND LEFT(Object1.Column3,?) = ?
                THEN Function2(Column5,Object2.Column6, Object3.Column7)
            WHEN Object1.Column2 IN (?) AND LEFT(Object1.Column3,?) = ?
                THEN Function2(Column5,Object2.Column6, Object3.Column7) * ?
            ELSE ?
            END) OVER (PARTITION BY Object1.Column1) AS Column8
    , Function1(CASE 
            WHEN Object1.Column2 IN (?) AND LEFT(Object1.Column3,?) = ?
                THEN Function2(Column5,Object2.Column6, Object3.Column7)
            WHEN Object1.Column2 IN (?) AND LEFT(Object1.Column3,?) = ?
                THEN Function2(Column5,Object2.Column6, Object3.Column7) * ?
            ELSE ?
            END) OVER (PARTITION BY Object1.Column1) 
            / NULLIF(Function1(CASE 
            WHEN Object1.Column2 IN (?) AND LEFT(Object1.Column3,?) = ?
                THEN ?
            WHEN Object1.Column2 IN (?) AND LEFT(Object1.Column3,?) = ?
                THEN ?
            ELSE ?
            END) OVER (PARTITION BY Object1.Column1), ?)
            / ? AS Column9
INTO Object4
FROM Object5 Object1 
JOIN Schema1.Object6 Object7 ON Object7.Column1 = Object1.Column1
LEFT JOIN Schema1.Object8 Object9 ON Object9.Column10 = Object1.Column10
    LEFT OUTER JOIN Object10 Object3 ON Object3.Column10 = Object9.Column10
                        AND Object3.Column11 = ?
    JOIN (SELECT Object11.Column10, Function3(Object11.Column12) AS Column13 
        FROM Object12 Object11 (NOLOCK)
        WHERE Object11.Column14 = ?
        GROUP BY Object11.Column10) Object13 ON Object9.Column10 = Object13.Column10

    JOIN Object12 Object2 (NOLOCK) ON Object2.Column10 = Object13.Column10
                        AND Object2.Column12 = Object13.Column13

    LEFT JOIN Database1.Schema1.Object14 Object15 ON Object2.Column15 = Object15.Column16 
                                  AND Object15.Column14 = ?
                              AND Object2.Column17 IN (?)
  • I've pasted a link to the query plan if that helps. I should note that this SP runs hundreds of times for this report. As mentioned, its still executing the same amount of times with the same plan so I just don't understand the degradation. – cmmrc Sep 19 at 19:20
  • 1
    Thanks LowlyDBA. I've encountered that link before, but I assume it isn't parameter sniffing because its using the same plan its been using for weeks. – cmmrc Sep 19 at 21:28
  • There are a lot of other answers in that question as well, have you looked into those? – LowlyDBA Sep 20 at 11:19
2

One possible cause for this sudden increase in duration is that there is another process blocking this query from making progress.

You mentioned that you have query store enabled. I would run a query like this, and look for the point where avg_duration jumps up from 2 hours to 6 hours (after 9/15):

SELECT 
    qsrs.first_execution_time,
    qsrs.avg_duration,
    qsrs.avg_cpu_time,
    qsrs.avg_logical_io_reads,
    qsrs.avg_logical_io_writes,
    qsrs.avg_dop,
    qsrs.avg_rowcount
FROM sys.query_store_runtime_stats qsrs 
WHERE qsrs.plan_id = @your_plan_id
ORDER BY qsrs.first_execution_time DESC;

If the problem is blocking, you should see all of the other values (CPU, reads, writes, etc) stay mostly the same. You should then be able to track this problem down by finding other queries running during this time period (either using Query Store, or running sp_WhoIsActive, or logging it to a table).

If other values in the runtime stats did change, then at least this will be a clue as far as where to look next. For instance, I included avg_dop because maybe the query has suddenly stopped being able to use parallelism as much because of a settings change you didn't know about.


Since you've determined that CPU increased with duration, but the other metrics stayed the same, I'm tempted to think that the VM is fighting to get CPU time on the host, possibly because it's oversubscribed and there are other CPU heavy workloads running on other guests.

Jonathan Kehayias has an interesting post that shows SOS_SCHEDULER_YIELD waits could result from this situation (CPU Ready Impact on SOS_SCHEDULER_YIELD). If you're logging wait stats, you might look to see if you can correlate the increase in duration with increases in this wait type. Or better yet, work with your VM admin to see if there's evidence on the host side:

  • Thank you Josh Darnell for the response. Running your query shows that while duration increased, so did CPU time while the other stats remained about the same. Same average DOP as well. I'm wondering if we need to revisit checking on the host this server is on. – cmmrc Sep 19 at 21:36
  • @cmm That's a good idea. I don't know what you meant exactly by "We're also seeing CPU contention when this report runs that we didn't see previously" but you might have host-level issues. I've updated my answer. – Josh Darnell Sep 20 at 18:33

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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