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


luciano.moreira@microsoft.com


 


=============================================================


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

Comments (0)

Skip to main content