Analisando problemas de performance – Um estudo de caso (parte 3 de 4)
Até agora no nosso estudo de caso eu descrevi o cenário com o problema, coloquei algumas recomendações de contadores que poderiam ser utilizados e mostrei qual foi minha análise e recomendação para o cliente.
Parte 3: Procedimento com tempos diferenciados de execução
Durante o chamado de suporte, outra questão que me pediram para analisar é conhecida de muitos de muitos de vocês: em um momento um procedimento é executado em X minutos e depois é executado em X + Y minutos. E aí vem a pergunta... Qual o motivo deste comportamento?
No nosso caso, algumas vezes um determinado procedimento executava em 8 minutos e em outros momentos durava mais de 40 minutos.
Analisando o cenário
Sempre que temos uma pergunta desse tipo em mãos, é importante tentarmos comparar o que está acontecendo entre as execuções do procedimento e formular uma hipótese do problema. Se a hipótese estiver correta, quando o cliente executar a correção (que você vai sugerir), o problema não deve mais acontecer.
No nosso caso, eu parti para responder as seguintes perguntas:
1) Existe um padrão visível nas execuções que demoram mais tempo?
2) Existe algum problema de bloqueio durante a execução que demora mais tempo?
3) Inicialmente o problema foi descrito pelo cliente como sendo um gargalo em disco, como o disco de backup está no mesmo RAID group que os dados, será que existe alguma relação entre esses?
4) Os dados manipulados pelo procedimento têm uma distribuição muito diferente entre as execuções rápidas e lentas?
Para tentar responder as perguntas, eu utilizei o profiler para capturar os eventos de RPC:Starting/Completed e T-SQL:StmtStarting/StmtCompleted. Assim eu poderia entender o que está acontecendo durante a execução dos procedimentos. É claro que eu coloquei também um filtro na duração, pegando somente aquelas instruções que demoravam mais de 500 ms. Dessa forma eu não pegava toda e qualquer coisa que passava no SQL Server e sabia quando os procedimentos iniciavam, já que o filtro somente se aplica aos eventos de completed, pois não temos essa informação no starting.
Usei os mesmos counter sets do perfmon (que já havia configurado) para monitorar o que estava acontecendo durante o dia e, para completar, deixei rodando o blocker script para capturar informação dos bloqueios que estavam acontecendo durante o dia.
Após um dia de coleta, eu peguei o resultado das três ferramentas e comecei a responder as perguntas acima:
R1) Não existe um padrão visível durante as execuções que demoram mais tempo e nem previsibilidade de quando o problema acontece. Em um dia o problema acontece só de manhã, outro dia só de tarde, de vez em quando nos dois períodos ou em nenhum. O procedimento é executado diversas vezes ao dia e olhando o resultado do profiler, não foi encontrado nenhum padrão nas execuções, como a existência da procedureXYZ que é executada no mesmo horário sempre que temos uma lentidão.
A hipótese de haver em especial outro procedimento/instrução prejudicando a execução não é correta.
R2) Nenhum problema específico de bloqueio foi notado durante a execução do procedimento, onde veríamos o SPID da conexão esperando por algum recurso por um longo tempo. Dado R1, já era de imaginar que esse não seria o problema. Hipótese dois foi por água abaixo.
R3) Concorrência em disco poderia ser um dos problemas, mas temos um caso onde o backup está sendo executado concorrentemente com o procedimento, que acabava em 8 minutos. Vimos outros casos em que o procedimento levava 28 minutos para executar e nenhum backup era executado.
A hipótese três não é a explicação para o nosso problema, mas de qualquer forma ela pode ser um agravante e a recomendação para se separar os discos se mantém.
R4) Analisando por cima a lógica do procedimento e conversando com os especialistas do negócio, entendi que a SP fazia uma série de cálculos sobre um conjunto pré-definido de registros (processados nos últimos X minutos), varrendo os registros usando padrões de acesso conhecidos e realmente não havia nada que chamasse a atenção para gerar tempos de execução tão díspares.
Nessa hora você olha para o lado e pensa... E agora? Vamos analisar o que o perfmon nos trouxe e partir para a formulação de novas hipóteses. Mas para que os valores sejam significativos, eu preciso filtrar intervalos distintos, de quando o problema estava acontecendo e durante uma execução normal. Os dois intervalos filtrados são, um entre 16:19:58 e 16:28:07 (tempo de execução: 8 min) e outro entre 18:13:54 e 18:52:15 (tempo de execução: 38 min). Para encontrar o momento em que os procedimentos iniciaram, eu usei a saída do profiler.
O resumo em excel dos contadores que importam está em anexo a esse artigo (facilita a visualização), quem quiser tentar formular uma hipótese do que estava acontecendo, pare de ler o artigo e boa sorte! Para aqueles que continuam...
Contadores para execução de 08 minutos
_Total
C:
D:
G:
I:
L:
Avg. Disk sec/Read
0.016
0
0
0.017
0
0.003
Avg. Disk sec/Write
0.003
0
0
0.004
0
0
Current Disk Queue Length
1.281
0
0
1.25
0
0.031
Disk Bytes/sec
12324772.68
22839.74
79.285
10771098.03
0
1530755.622
(Physical Memory)
Available MBytes
764.281
HP Network Team _1
Bytes Total/sec
535744.388
Current Bandwidth
1000000000
_Total
% Privileged Time
1.435
% Processor Time
38.249
% User Time
36.816
Extent Deallocations/sec
49.998
Extents Allocated/sec
27.328
Forwarded Records/sec
187.139
FreeSpace Scans/sec
312.067
Full Scans/sec
455.149
Index Searches/sec
49577.99
Worktables Created/sec
48.16
Worktables From Cache Ratio
75.275
Buffer cache hit ratio
99.807
Checkpoint pages/sec
43.269
Database pages
197416.563
Lazy writes/sec
16.327
Page life expectancy
75.25
Page lookups/sec
207383.013
Page reads/sec
594.777
Page writes/sec
402.807
_Total
bancoX
tempdb
Transactions/sec
80.045
9.456
66.226
Batch Requests/sec
19.716
Contadores para execução de 38 minutos
|
_Total |
C: |
D: |
G: |
I: |
L: |
Avg. Disk sec/Read |
0.053 |
0 |
0 |
0.053 |
0.005 |
0.002 |
Avg. Disk sec/Write |
0.023 |
0.002 |
0 |
0.024 |
0 |
0.001 |
Current Disk Queue Length |
31.778 |
0.006 |
0 |
31.715 |
0.019 |
0.038 |
Disk Bytes/sec |
26271926.91 |
46556.351 |
143.269 |
25352753.63 |
238523.297 |
633950.361 |
|
|
|||||
|
(Physical Memory) |
|||||
Available Mbytes |
799.563 |
|||||
|
|
|||||
|
HP Network Team _1 |
|||||
Bytes Total/sec |
371224.371 |
|||||
Current Bandwidth |
1000000000 |
|||||
|
|
|||||
|
_Total |
|||||
% Privileged Time |
1.431 |
|||||
% Processor Time |
31.418 |
|||||
% User Time |
29.991 |
|||||
|
|
|||||
Extent Deallocations/sec |
19.822 |
|||||
Extents Allocated/sec |
11.391 |
|||||
Forwarded Records/sec |
74.163 |
|||||
FreeSpace Scans/sec |
509.628 |
|||||
Full Scans/sec |
398.785 |
|||||
Index Searches/sec |
37298.357 |
|||||
Worktables Created/sec |
27.78 |
|||||
Worktables From Cache Ratio |
77.015 |
|||||
|
|
|||||
Buffer cache hit ratio |
98.609 |
|||||
Checkpoint pages/sec |
14.945 |
|||||
Database pages |
199814.892 |
|||||
Lazy writes/sec |
85.864 |
|||||
Page life expectancy |
40.81 |
|||||
Page reads/sec |
2727.22 |
|||||
Page writes/sec |
243.661 |
|||||
|
|
|||||
|
_Total |
bancoX |
tempdb |
|||
Transactions/sec |
47.504 |
7.557 |
37.212 |
|||
|
|
|||||
Batch Requests/sec |
29.849 |
A nova hipótese!
Depois de olhar os contadores e dado a análise feita na parte 02 desta série. A conclusão que tirei para o nosso caso é a seguinte: a memória do servidor já está sobre constante pressão, e podemos ver isso na baixa expectativa de vida das páginas em cache, porém em alguns momentos o servidor passa a processar um número maior de procedimentos, fazendo com que um “ponto de máximo” seja extrapolado e o servidor gaste mais tempo em housekeeping que em execução de código. Essa idéia de ponto de máximo é um pouco abstrata, mas se aplica no nosso caso (eu gosto do termo tipping point).
Estamos em um cenário onde diversos procedimentos estão utilizando/disputando o uso de memória e o SQL Server deve gerenciar a inserção/retirada de páginas na memória. Imagine um caso onde um procedimento carregue 200MB para memória, se não houver espaço livre, o Lazy Writer entra e arranja espaço (retirando as páginas menos utilizadas). Agora imagine 30 procedimentos fazendo a mesma coisa simultaneamente em dados diferentes... 200 x 30 = 6000MB = 6GB. Se eu não tenho 6GB de memória, preciso que o SQL Server fique tirando/colocando as páginas que um procedimento está usando, mas se eu tenho uma troca constante de procedimentos (escalonamentos dos SPIDs), podemos ter, por exemplo, um fenômeno conhecido como cache trashing.
Outras observações que me ajudaram a chegar à conclusão acima foram:
Analisando os dois procedimentos podemos notar que existe um aumento de 50% no número de batch requests por segundo (10 requisições a mais) e o tempo de resposta dos discos está muito pior durante a execução de 38 minutos.
Se somarmos o tempo total de resposta dos discos por leitura e escrita, teremos um valor total de 21 milissegundos no primeiro caso e 77 segundos no pior caso. Somente aqui temos um tempo de resposta 3,7 vezes pior, enquanto o tempo total da segunda execução está 4,75 vezes pior (bem perto). Levando em conta que o segundo caso trafega entre a memória e o disco aproximadamente 15MB por segundo a mais que o primeiro, somente isso já explicaria um tempo elevado de execução no segundo caso.
Quando analisamos os contadores do SQL Server, vemos uma baixíssima expectativa de vida da página no primeiro caso (75 segundos) e uma pior ainda no outro (40 segundos), mostrando mais uma vez que a memória atual não é suficiente para a carga.
Um aspecto interessante que merece destaque é o volume de transações nos dois casos. No primeiro temos um número menor de requisições por segundo e ainda assim temos número maiores para o volume de transações, a quantidade de index searches, full scans, page allocations/deallocations, etc. Aqui notamos que o servidor deve está mais “parado” durante a execução demorada, diferente do primeiro caso, talvez esperando que as páginas sejam retiradas/postas na memória para continuar a execução.
Isso demonstra claramente que no segundo caso temos um gargalo sério no servidor. Esse gargalo não está dependente de um procedimento específico ou outro, o servidor vem trabalhando no limite de sua performance (aceitável) até que um volume um pouco maior de transações faz com que essa linha tênue seja alcançada. Isso faz com que o desempenho do servidor caia vertiginosamente, devido à acentuação dos gargalos existentes.
Últimos comentários
Quando me perguntaram se eu tinha certeza de que todas as observações que fiz estavam corretas, eu disse que a resposta é não. Eu juntei pistas que me indicam que esse provavelmente é o problema, usando um pouco de bom senso, conhecimento de computação/produto e experiência. Agora para descobrir se eu estou certo ou não, somente aplicando as recomendações que foram feitas (vide parte 2). Caso tenhamos conseguido criar uma hipótese correta, uma vez que o problema de pressão na memória seja corrigido, esperamos que essas disparidades entre as execuções não aconteçam mais, pois o tal limite de máximo não será atingido.
Muitos profissionais da nossa área não acreditam ou aceitam (outros não entendem) a hipótese que eu propus, por não existir uma comprovação formal do problema (como conseguimos com dumps de memória, em alguns casos). Infelizmente, existem cenários que são muito difíceis de reproduzir (nada é impossível, com dinheiro e tempo suficiente!) e algumas vezes precisamos fazer pequenas apostas, claro, se houver indícios para tal.
Para os curiosos, o comentário acima não foi o caso desse cliente, onde tivemos discussões ótimas, que colocamos hipóteses, sugestões, problemas, etc. Puro conhecimento que merecia até ter sido gravado.
Espero que vocês tenham gostado.
Até a próxima parte.
[]s
Luciano Caixeta Moreira
=============================================================
This posting is provided "AS IS" with no warranties, and confers no rights
=============================================================
20080107 - Analisando problemas de performance - Um estudo de caso (Parte 3 de 4).zip