Na última semana, tivemos alguns problemas quanto a um estranho comportamento em um dos nossos servidores SQL Server 2005, ele estava apresentando uma grande lentidão.

 

 

No momento que tentamos realizar um logon na console do SSMS, recebemos a mensagem de "Request Timed out".

 

 

Geralmente este caso esta atrelado a um evento de situação de Lock/Deadlock em objetos do servidor ou escassez de memória no "connection pool", esta memória é dinâmica e pode ser alocada ou desalocada para uso em outras áreas como Procedure Cache, Buffer Pool e etc.

 

 

A primeira providência foi realizarmos uma conexão utilizando o DAC pelo SSMS, a partir desse busquei algumas informações nas dmv's para entender o que estava ocorrendo.

 

1 - Executei uma query na sys.dm_os_wait_stats - Verifiquei quais seriam os waits types mais comuns e com maior incidência de [wait_time_ms], lembrando que estes valores são cumulativos desde o start da instância SQL Server, porém caso um wait type comece a ocorrer com grande frequência, ele facilmente pode ser identificado na lista dos Top 10, ordenado DESC pelo [wait_time_ms], aqui já identifiquei o evento CMEMTHREAD aparecendo.

 

2 - Executei uma query na sys.dm_os_latch_stats - Verifiquei quais seriam os tipos de latch's mais comuns que estavam ocorrendo ordenando também pelo [wait_time_ms], existia alguns LATCHS internos na lista, porém um neste caso já chamou a atenção de primeira, BUFFER, este latch é exigido antes de ler ou modificar qualquer página no banco de dados, neste caso se o tempo de wait estiver alto demais, o que temos? Uma possível falta de memória ou alguém utilizando demais, o que talvez não deveria.

 

3 - Fiz uma query cruzando a sys.dm_exec_requests e sys.dm_exec_sessions, para identificar os processos em SUSPENDED e RUNNABLE, e com isso verificar qual o WAIT_TYPE destas sessões, com isso verifiquei que ocorria diversos CMEMTHREAD, com wait_time alto.

Select

   *

From

   sys.dm_exec_requests As r

inner

join

   sys.dm_exec_sessions As s

on

(r.session_id = s.session_id and r.[status] = 'SUSPENDED'

   Or r.[status] = 'RUNNABLE')

 

4 - Segundo este KB: http://support.microsoft.com/kb/822101/ este wait_type indica que o SPID está aguardando para acessar a thread-safe memory, isto pode ocorrer quando vários spid's estão tentando inserir ou desalocar um objeto na memória, no geral este wait está associado a RECOMPILAÇÃO.

 

5 - Neste passo devemos identificar qual a query por SPID está causando este problema com maior incidência, para isso executamos novamente a mesma query do passo 3, porém fazemos um CROSS APPLY com sys.dm_exec_sql_text:

 

   cross

apply sys.dm_exec_sql_text(r.[sql_handle])

6 - Após identificarmos qual a query, precisamos confirmar se realmente está ocorrendo a recompilação, como fazemos isso? Abrimos um SQL Profiler e coletamos o Evento de SP:Recompile.

7 - Podemos identificar se o plano está sendo re-utilizado com uma query na sys.dm_exec_cached_plans a partir do handle da query que resgatamos no passo 3 ou 5, com isso é possível verificarmos através da coluna [usecounts] se o plano está sendo re-utilizado com frequência e também o seu tamanho em [size_in_bytes], no meu caso havia um plano que estava grande com 270MB, desconfiei deste e parti para a solução.

8 - Com todos estes dados coletados, precisamos solucionar o problema. Muito bem iniciei investigando o [plano de execução X o plano em cache] eram os mesmos, também olhei se havia alguma coisa na query que estivesse causando a recompilação, não havia nada. Sim, a query não estava boa, porém não havia o que fazer naquele momento, apenas resolver este problema sem alterar nada.

Como resgatar o plano de execução em cache? faça um CROSS APPLY utilizando a sys.dm_exec_query_plan(plan_handle) que você terá acesso a partir da coluna [plan_handle] da sys.dm_exec_cached_plans. A saída será um XML, salve-o como .sqlplan e abra no SSMS.

9 - Foi onde tracei dois planos 1 - Forçar uma recompilação total na procedure com SP_RECOMPILE 'proc name', assim poderia retirá-la do cache e inserí-la novamente e verificar se este comportamento volta a acontecer. Ou então 2 - gerar um plano XML e forçar este ser mantido no cache. Pois bem não foi preciso executar o segundo plano, com o primeiro funcionou perfeitamente, o SQL retirou o plano do cache e colocou novamente na primeira execução da procedure, e a partir daí o evento não voltou a acontecer.

Causas prováveis:

- Estatísticas desatualizadas; (porém não foi preciso atualizá-las)

- Procedure migrada junto com o banco de dados em modo de compatibilidade 2000 (80), no momento da compilação causou alguma excessão.

- Plano foi marcado para ser removido do procedure cache em momento inadequado, pelo seu tamanho ou pelo fato do [usecounts] não estar incrementando.

Realmente a causa ficou complicada de identificarmos, ficamos de abrir um caso direto no time de desenvolvimento, porém o ideal seria coletarmos mais informações, coisa que não conseguimos, pelo fato de estar comprometendo o ambiente.

 

Bom espero que este artigo seja útil para todos.

Abraços e até a próxima!

 

Rodrigo Fernandes de Souza