Sql-server – Same Query plan, no new query competition, same hardware, but stored procedure runs slowly

performancequery-performancesql server

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 (?)

Best Answer

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:

Related Solutions

Sql-server – Stored procedure runs forever, but inner query runs fine

It is difficult to tell just from examining the code if it is running forever because of an infinite loop or blocking - my guess is the latter. But here is a slightly different approach that avoids some of the things that could be problematic:

CREATE PROCEDURE dbo.pr_BuscaLog
  @qtdDias INT
AS
BEGIN
  SET NOCOUNT ON;
  DECLARE @cmd NVARCHAR(MAX) = N'', @dataLimite DATETIME = CONVERT(SMALLDATETIME, 
      DATEADD(DAY, @qtdDias, GETDATE()));

  SELECT name INTO #tmp FROM sys.databases WHERE database_id > 4;

  -- delete the ones that don't have that view    
  SELECT @cmd += N'DELETE #tmp WHERE name = N''' + name 
      + ''' AND NOT EXISTS (SELECT 1 FROM ' + QUOTENAME(name) 
      + '.sys.views WHERE name = N''vwLogProjetos'');' FROM #tmp

  EXEC sys.sp_executesql @cmd;
  SET @cmd = N'';

  SELECT @cmd += N'INSERT PainelControle..tblLogProjetos(...columns...)  
    select ...columns... FROM ' + QUOTENAME(name) 
      + N'.dbo.vwLogProjetos as T1 with (nolock)  
          where DtTrabalho >= @dt and not exists
          (
            select 1 from PainelControle.dbo.tblLogProjetos T2 
             Where t2.BancoDados collate SQL_Latin1_General_CP1_CI_AS 
             = t1.BancoDados collate SQL_Latin1_General_CP1_CI_AS 
             and t2.codlog = t1.codlog
          );' FROM #tmp;

  BEGIN TRY
    EXEC sys.sp_executesql @cmd, N'@dt DATETIME', @dataLimite;
  END TRY
  BEGIN CATCH
    insert into dbo.tblLogProjetosErro (rotina, comando,Data) 
      values ('pr_BuscaLog', @cmd + ERROR_MESSAGE(), GETDATE());  
  END CATCH
END

Some things I've changed (or that you should):

No explicit loops. Contrary to popular belief, a while loop is not faster than a cursor (see this post), but neither is needed here.
Don't count when you don't have to - see this post.
I parameterized the date value instead of dealing with messy string concatenation (see this post and this post). This is harder to avoid with an entity, but should always be done with variables.
Please stop using lazy shorthand; e.g. use DATEDIFF(SECOND instead of DATEDIFF(s - see this post.
Use the schema prefix. Always.

Sql-server – SQL Server 2012 stored procedure runs very slow sometimes

First thing to check is if there's blocking happening. If the procedure / statement is blocked by another process then it's quite clear why it takes longer.

If that's not the case, you can try to check from plan cache if there's something that explains it. Here's one short example query to get some of the figure from there:

select top 100
SUBSTRING(t.text, (s.statement_start_offset/2)+1,
((CASE s.statement_end_offset
WHEN -1 THEN DATALENGTH(t.text)
ELSE s.statement_end_offset
END - s.statement_start_offset)/2) + 1) as statement_text,
t.text,
s.total_logical_reads, s.total_logical_reads / s.execution_count as avg_logical_reads,
s.total_worker_time, s.total_worker_time / s.execution_count as avg_worker_time,
s.execution_count
from sys.dm_exec_query_stats s
cross apply sys.dm_exec_sql_text (sql_handle) t
where t.text like '%name_of_proc%'
order by s.total_worker_time desc

There's also a lot of other columns, like max_elapsed_time, max_worker_time, max_logical_reads etc. That might give some insight.

Best Answer

Related Solutions

Sql-server – Stored procedure runs forever, but inner query runs fine

Sql-server – SQL Server 2012 stored procedure runs very slow sometimes

Related Question