Eu tenho tentado diagnosticar lentidão em um aplicativo. Para isso, registrei os eventos estendidos do SQL Server .

• Para esta pergunta, estou olhando para um procedimento armazenado específico.
• Mas há um conjunto básico de uma dúzia de procedimentos armazenados que igualmente podem ser usados ​​como uma investigação completa
• e sempre que executo manualmente um dos procedimentos armazenados, ele sempre é executado rapidamente
• e se um usuário tentar novamente: ele será executado rapidamente.

Os tempos de execução do procedimento armazenado variam muito. Muitas das execuções deste procedimento armazenado retornam em < 1s:

E para esse balde "rápido" , é muito menos que 1s. Na verdade, é em torno de 90 ms:

Mas há uma longa cauda de usuários que precisam esperar 2s, 3s, 4s segundos. Alguns têm que esperar 12s, 13s, 14s. Depois, há as almas realmente pobres que têm que esperar 22s, 23s, 24s.

E após 30s, o aplicativo cliente desiste, aborta a consulta e o usuário teve que esperar 30 segundos .

Correlação para encontrar a causa

Então tentei correlacionar:

• duração vs leituras lógicas
• duração vs leituras físicas
• duração vs tempo de CPU

E nenhum parece dar qualquer correlação; nenhum parece ser a causa

• duração vs leituras lógicas : seja um pouco ou muitas leituras lógicas, a duração ainda flutua muito :

  

• duração vs leituras físicas : mesmo que a consulta não tenha sido atendida pelo cache e muitas leituras físicas sejam necessárias, isso não afeta a duração:

  

• duração vs tempo de CPU : se a consulta levou 0s de tempo de CPU ou 2,5s completos de tempo de CPU, as durações têm a mesma variabilidade:

  

Bônus : notei que a duração v leituras físicas e duração v tempo de CPU são muito semelhantes. Isso é comprovado se eu tentar correlacionar o tempo de CPU com leituras físicas:

Acontece que muito uso da CPU vem de E/S. Quem sabia!

Então, se não há nada no ato de executar a consulta que possa explicar as diferenças no tempo de execução, isso significa que é algo não relacionado à CPU ou disco rígido?

Se a CPU ou o disco rígido fossem o gargalo; não seria o gargalo?

Se levantarmos a hipótese de que foi a CPU que foi o gargalo; que a CPU está com pouca energia para este servidor:

• então as execuções usando mais tempo de CPU não levariam mais tempo?
• uma vez que eles têm que completar com os outros usando a CPU sobrecarregada?

Da mesma forma para os discos rígidos. Se levantarmos a hipótese de que o disco rígido era um gargalo; que os discos rígidos não têm taxa de transferência aleatória suficiente para este servidor:

• então as execuções usando mais leituras físicas não levariam mais tempo?
• uma vez que eles têm que completar com outros usando a E/S sobrecarregada do disco rígido?

O procedimento armazenado em si não executa nem requer nenhuma gravação.

• Geralmente retorna 0 linhas (90%).
• Ocasionalmente, retornará 1 linha (7%).
• Raramente retornará 2 linhas (1,4%).
• E nos piores casos, ele retornou mais de 2 linhas (uma vez retornando 12 linhas)

Portanto, não é como se estivesse retornando um volume insano de dados.

Uso da CPU do servidor

A média de uso do processador do servidor é de cerca de 1,8%, com um pico ocasional de até 18% - portanto, não parece que a carga da CPU seja um problema:

Portanto, a CPU do servidor não parece sobrecarregada.

Mas o servidor é virtual...

Algo fora do universo?

A única coisa que posso imaginar é algo que existe fora do universo do servidor.

• se não for lógico lê
• e não são leituras físicas
• e não é uso de CPU
• e não é carga da CPU

E não é como se fossem os parâmetros do procedimento armazenado (porque emitindo a mesma consulta manualmente e não leva 27 segundos - leva ~ 0 segundos).

O que mais poderia explicar o servidor às vezes levando 30 segundos, em vez de 0 segundos, para executar o mesmo procedimento armazenado compilado.

• postos de controle?

É um servidor virtual

• o host sobrecarregado?
• outra VM no mesmo host?

Passando pelos eventos estendidos do servidor; não há mais nada acontecendo quando uma consulta de repente leva 20 segundos. Ele roda bem, então decide não rodar bem:

• 2 segundos
• 1 segundo
• 30 segundos
• 3 segundos
• 2 segundos

E não há outros itens particularmente extenuantes que eu possa encontrar. Não é durante o backup do log de transações a cada 2 horas.

O que mais poderia ser?

Existe algo que eu possa dizer além de: "o servidor" ?

Edit : Correlacione por hora do dia

Percebi que correlacionei as durações a tudo:

• leituras lógicas
• leituras físicas
• utilização do CPU

Mas a única coisa que eu não correlacionava era com a hora do dia . Talvez o backup do log de transações a cada 2 horas seja um problema.

Ou talvez as lentidão ocorram nos mandris durante os pontos de verificação?

Não:

Intel Xeon Gold Quad-core 6142.

Editar - As pessoas estão hipotetizando o plano de execução da consulta

As pessoas estão supondo que os planos de execução de consultas devem ser diferentes entre "rápido" e "lento". Eles não são.

E podemos ver isso imediatamente a partir da inspeção.

Sabemos que a duração mais longa da pergunta não se deve a um plano de execução "ruim":

• um que levou mais leituras lógicas
• um que consumiu mais CPU de mais junções e pesquisas de chave

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:

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.