12

I've been trying to diagnose slow-downs in an application. For this I've logged the SQL Server extended events.

  • For this question i'm looking at one particular stored procedure.
  • But there are a core set of a dozen stored procedures that equally can be used as an apples-to-apples investigation
  • and whenever i manually run one of the stored procedures, it always runs fast
  • and if a user tries again: it will run fast.

The execution times of the stored procedure vary wildly. A lot of the executions of this stored procedure return in < 1s:

enter image description here

And for that "fast" bucket, it's much less than 1s. It's actually around 90 ms:

enter image description here

But there is a long tail of users who have to wait 2s, 3s, 4s seconds. Some have to wait 12s, 13s, 14s. Then there's the really poor souls who have to wait 22s, 23s, 24s.

And after 30s, the client application gives up, aborts the query, and the user had to wait 30 seconds.

Correlation to find causation

So I tried to correlate:

  • duration vs logical reads
  • duration vs physical reads
  • duration vs cpu time

And none seem to give any correlation; none seem to be the cause

  • duration vs logical reads: whether a little, or a lot of logical reads, the duration still fluctuates wildly:

    enter image description here

  • duration vs physical reads: even if the query wasn't served from the cache, and a lot of physical reads were needed, it doesn't affect duration:

    enter image description here

  • duration vs cpu time: Whether the query took 0s of CPU time, or a full 2.5s of CPU time, the durations have the same variability:

    enter image description here

Bonus: I noticed that the Duration v Physical Reads and Duration v CPU time look very similar. This is proven out if i try to correlate CPU time with Physical Reads:

enter image description here

Turns out a lot of CPU usage comes from I/O. Who knew!

So if there's nothing about the act of executing the query that can account for the differences in execution time, does that imply that it's something unrelated to CPU or hard drive?

If the CPU or hard drive were the bottleneck; wouldn't it be the bottleneck?

If we hypothesize that it was the CPU that was the bottleneck; that the CPU is under-powered for this server:

  • then wouldn't executions using more CPU time take longer?
  • since they have to complete with others using the overloaded CPU?

Similarly for the hard-drives. If we hypothesize that the hard-drive was a bottleneck; that the hard-drives don't have enough random through-put for this server:

  • then wouldn't executions using more physical reads take longer?
  • since they have to complete with others using the overloaded hard-drive I/O?

The stored procedure itself neither performs, nor requires, any writes.

  • Usually it returns 0 rows (90%).
  • Occasionally it will return 1 row (7%).
  • Rarely it will return 2 rows (1.4%).
  • And in the worst cases it has returned more than 2 rows (one time returning 12 rows)

So it's not like it's returning an insane volume of data.

Server CPU Usage

The server's Processor Usage averages about 1.8%, with an occasional spike up to 18% - so it doesn't seem like the CPU load is an issue:

enter image description here

So the server CPU doesn't seem overloaded.

But the server is virtual...

Something outside the universe?

The only thing left i can imagine is something that exists outside the universe of the server.

  • if it's not logical reads
  • and it's not physical reads
  • and it's not cpu usage
  • and it's not CPU load

And it's not like it's the parameters to the stored procedure (because issuing the same query manually and it doesn't take 27 seconds - it takes ~0 seconds).

What else could account for the server sometimes taking 30 seconds, rather than 0 seconds, to run the same compiled stored procedure.

  • checkpoints?

It is a virtual server

  • the host overloaded?
  • another VM on the same host?

Going through the server's extended events; there's nothing else particularly happening when a query suddenly takes 20 seconds. It runs fine, then decides to not run fine:

  • 2 seconds
  • 1 second
  • 30 seconds
  • 3 seconds
  • 2 seconds

And there's no other particuarly strenuous items i can find. It's not during the every 2-hour transaction log backup.

What else could it be?

Is there anything i can say besides: "the server"?

Edit: Correlate by time of day

I realized i've correlated the durations to everything:

  • logical reads
  • physical reads
  • cpu usage

But the one thing i didn't correlate it to was the time of day. Perhaps the every-2-hour transaction log backup is a problem.

Or perhaps the slowdowns do occur in chucks during checkpoints?

Nope:

enter image description here

Intel Xeon Gold Quad-core 6142.

Edit - People are hypothizing the query execution plan

People are hypothesizing the query execution plans must be different between "fast" and "slow". They are not.

And we can see this immediately from inspection.

We know the longer question duration is not because of a "poor" execution plan:

  • one that took more logical reads
  • one that consumed more CPU from more joins and key lookups

Because if an increase in reads, or increase in CPU, was a cause of increased query duration, then we would have already seen that above. There is no correlation.

But lets try to correlate duration against the CPU-reads area product metric:

enter image description here

There becomes even less of a correlation - which is a paradox.

Edit: Updated the scatter diagrams to workaround a bug in Excel scatter plots with large numbers of values.

Next Steps

My next steps will be to get someone to have to server generate events for blocked queries - after 5 seconds:

EXEC sp_configure 'blocked process threshold', '5';
RECONFIGURE

It won't explain if queries are blocked for 4 seconds. But perhaps anything that's blocking a query for 5 seconds also blocks some for 4 seconds.

The slowplans

Here's the slowplan of the two stored procedures being executed:

  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04:00:00.000', @EndDate = '20190726 04:00:00.000'
  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04:00:00.000', @EndDate = '20190726 04:00:00.000'

The same stored procedure, with the same parameters, run back to back:

| Duration (us) | CPU time (us) | Logical reads | Physical reads | 
|---------------|---------------|---------------|----------------|
|    13,984,446 |        47,000 |         5,110 |            771 |
|     4,603,566 |        47,000 |         5,126 |            740 |

Call 1:

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Call 2

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

It makes sense for the plans to be identical; it's executing the same stored procedure, with the same parameters.

Improve this question
14
  • 2
    Can you post the query plans - good run vs bad run ?
    – Kin Shah
    Jul 29, 2019 at 19:06
  • 4
    My first guess from here would be blocking...
    – Tibor Karaszi
    Jul 29, 2019 at 19:10
  • 3
    Who downvoted this? It's a very detailled, thoroughly researched question even though it's lacking the query plans! +1 from me!
    – Vérace
    Jul 29, 2019 at 19:56
  • 4
    How have you come to the conclusion that the query plans are "identical"? Do you just mean they have the same shape? Post them somewhere so we can compare too. Just telling us they're identical does not mean they are identical.
    – Aaron Bertrand
    Jul 29, 2019 at 22:07
  • 3
    Adding the acutal execution plans using PasteThePlan could give us an idea what the query was waiting on.
    – Randi Vertongen
    Jul 30, 2019 at 8:15

1 Answer 1

Reset to default
2

Have a look at the wait_stats and it will show what the biggest bottlenecks are on your SQL server.

I recently experienced a problem where an external application was intermittently slow. Running stored procedures on the server itself was always fast though.

Performance monitoring showed nothing to be concerned about at all with SQL Caches or the RAM usage and IO on the server.

What helped narrow down the investigation was querying the wait stats that are collected by SQL in sys.dm_os_wait_stats

The excellent script on the SQLSkills website will show you the ones you are experiencing most. You can then narrow your search to identify the causes.

Once you know what waits are the big issues this script will help narrow down what session/database is experiencing the waits:

SELECT OSW.session_id,
       OSW.wait_duration_ms,
       OSW.wait_type,
       DB_NAME(EXR.database_id) AS DatabaseName
FROM sys.dm_os_waiting_tasks OSW
INNER JOIN sys.dm_exec_sessions EXS ON OSW.session_id = EXS.session_id
INNER JOIN sys.dm_exec_requests EXR ON EXR.session_id = OSW.session_id
OPTION(Recompile);

The above query and further detail is from the MSSQLTips website.

The sp_BlitzFirst script from Brent Ozar's website will also show you what's causing slowdowns.

Improve this answer

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

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