SQL Server – Como identificar uma query lenta ou “pesada” no seu banco de dados

Uma coisa que deve ficar bem clara, é que nem sempre o objetivo do performance/query tuning é simplesmente reduzir o tempo de execução de uma consulta que esteja demorando. Por muitas vezes, deve-se analisar o escopo geral da instância e identificar quais os principais problemas de performance apresentados e tratá-los de modo macro.

Um bom ponto de início para a nossa análise, é consultando a DMV sys.dm_os_wait_stats, com a query abaixo:

Resultado:

Essa consulta vai apresentar quais os eventos de waiting que mais demandaram tempo, ou seja, vai avaliar entre tudo o que foi executado na instância, o que mais fez essas consultas aguardarem recursos, seja disco, CPU, memória, rede, etc. Isso é muito útil para identificar onde está o nosso maior gargalo de processamento.

O grande Paul Randal disponibilizou uma versão dessa query, que traz algumas estatísticas sobre esses eventos de wait, como % de tempo de wait e um link para a explicação do que é esse evento de wait, e também filtra eventos que geralmente só apenas avisos e não problemas, facilitando a identificação do que realmente está atrapalhando a nossa instância.

Segue script:

Resultado: (bem mais “clean” né?”

Para facilitar a sua vida, vou listar abaixo alguns eventos comuns e sua possível causa:

• ASYNC_NETWORK_IO / NETWORKIO: Os eventos de wait networkio (SQL 2000) e async_network_io (SQL 2005+) podem apontar para problemas relacionados à rede (raramente), mas geralmente podem indicar que uma aplicação cliente não está processando os resultados do SQL Server rápido o bastante. Esse evento costuma aparecer em casos de RBAR (Row-By-Agonizing-Row)
• CXPACKET: Evento geralmente ligado à execução de consultas utilizando processamento paralelo, ele pode indicar que uma thread já concluiu o seu processamento e está aguardando a execução das outras threads do processo para concluir a execução. Caso esse evento esteja com wait_time muito alto, talvez seja interessante revisar as configurações de MAXDOP, avaliar se o hint OPTION(MAXDOP x) pode ser útil em algumas consultas, reavaliar os índices utilizados pelas consultas que mais consomem disco (provavelmente, essas que estão utilizando paralelismo) e tentar garantir que argumentos sargable estão sendo utilizados.
• DTC: Esse evento de wait não é local. Quando se utiliza o Microsoft Distributed Transaction Coordinator (MS-DTC), uma transação é aberta em vários sistemas ao mesmo tempo e a transação só é concluída quando ela é executada em todos esses sistemas.
• OLEDB: Esse evento de wait indica que o processo fez uma chamada para um provedor OLEDB e está aguardando que essa chamada processo no servidor de destino e retorne os dados. Esse evento é gerado também quando executamos comandos em outras instâncias utilizando Linked Servers (chamadas remotas), comandos BULK INSERT e consultas FULLTEXT-SEARCH. Não há nada o que se fazer na instância local, mas em casos de chamadas remotas a outras instâncias, você pode analisar a instância de destino e tentar identificar o motivo da demora no processamento e retorno dos dados.
• PAGEIOLATCH_*: Esse evento ocorre quando o SQL Server está aguardando para ler dados no disco/storage de páginas que não estão em memória, gerando contenção de disco. Para diminuir esse evento de I/O, você pode tentar aumentar a velocidade do disco (para reduzir esse tempo), adicionar mais memória (para alocar mais páginas) ou tentar identificar e tunar essas consultas que estão gerando esse evento de I/O.

  Uma causa muito comum que gera esse evento, é a falta de índices ótimos para essa determinada consulta, o que pode ser resolvido criando novos índices com a ajuda das DMV’s de Missing Index para evitar operações de Scan (Dê uma lida no post Entendendo o funcionamento dos índices no SQL Server para entender melhor sobre isso).

• PAGELATCH_*: As causas mais comuns para esse evento são contenção na tempdb em instâncias com muita sobrecarga. O wait PAGELATCH_UP geralmente ocorre quando múltiplas threads estão tentando acessar o mesmo bitmap, enquanto o evento PAGELATCH_EX ocorre quando threads estão tentando inserir dados na mesma página do disco, e o evento PAGELATCH_SH indica que alguma thread está tentando ler dados de uma página que está sendo modificada
• IO_COMPLETION: Esse evento de wait ocorre quando o SQL Server está aguardando operações de I/O para concluir o processamento, as quais não são leituras de índices os de dados no disco, e sim, leituras de alocações de bitmaps do disco (GAM, SGAM, PFS), transaction log, escritas de sort buffers no disco, leitura de cabeçalhos de VLF’s da transaction log, leitura/escrita de merge join/eager spools no disco, etc.

  Esse evento é normal acontecer, pois ele costuma aparece logo antes de se iniciar alguma operação que requisite I/O, mas pode ser um problema se o tempo de wait está muito alto e a sua lista de maiores waits inclui ASYNC_IO_COMPLETION, LOGMGR, WRITELOG ou PAGEIOLATCH_*.

  Quando existe um problema de I/O na instância, o log do SQL Server costuma apresentar mensagens de “I/O requests are taking longer than X seconds to complete”, o que pode acontecer se houver realmente uma lentidão nos discos ou estiverem processando operações que consomem muito I/O, como BACKUP, ALTER/CREATE DATABASE e eventos de AutoGrowth.

  Para investir esse problema, procure por consultas que esteja com tempos de leitura/escrita de disco muito altas, incluindo os contadores Disk avg. read time, Disk avg. write time, Avg. disk queue length, Buffer cache hit ratio, Buffer free pages, Buffer page life expectancy e Machine: memory used

• SOS_SCHEDULER_YIELD: Esse evento ocorre quando o SqlOS (SOS) está aguardando mais recursos de CPU para terminar o processamento, o que pode indicar que o servidor está com sobrecarga de CPU e não está conseguindo processar todas as tarefas que são requisitadas. Entretanto, nem sempre isso indica que é um problema geral da instância, pois pode indicar que uma query em específico que está precisando de mais CPU.

  Se a sua query possui alguns inibidores de paralelismo (Ex: HINT MAXDOP(1), funções UDF seriais, consultas a tabelas de sistemas, etc), ela pode fazer com que o processamento seja feito utilizando apenas 1 CPU Core, fazendo com que o evento SOS_SCHEDULER_YIELD possa ser gerado, mesmo que o servidor tenha vários cores disponíveis para processamento e com baixa utilização de CPU na instância.

  Para tentar identificar isso, tente localizar as consultas que estão mais consumindo CPU e/ou que o tempo de CPU seja menor que o tempo de execução (quando ocorre paralelismo, às vezes a consulta consome 10s de CPU e executa em 2s, o que significa que ela foi paralelizada em vários núcleos da CPU)

• WRITELOG: Quando uma transação está aguardando pelo evento WRITELOG, isso quer dizer que ela está aguardando que o SQL Server capture os dados do log cache e os grave em disco (na transaction log). Como essa operação envolve escrita em disco, que é uma operação geralmente muito mais lenta que um acesso à memória ou processamento na CPU, esse tipo de evento pode ser bem comum em instâncias que não tenham um disco muito rápido. Se você encontra muito esse evento, uma alternativa para reduzir esse wait é utilizar o recurso Delayed Durability, disponível a partir do SQL Server 2014
• LCK*: Evento muito comum e que não está diretamente relacionado à performance, esse evento ocorre quando uma transação está alterando um objeto e ela coloca um lock nesse objeto, para impedir que nenhuma outra transação possar modificar ou acessar os dados enquanto ela está processando. Com isso, caso outra transação tente acessar esse objeto, ela terá que ficar aguardando a remoção desse lock para continuar o processamento, gerando justamente esse evento de wait. Isso é muito confundido com problema de performance, porque a consulta vai realmente demorar o tempo que for necessário até que o lock seja liberado e ela possar processar seus dados, fazendo com o que o usuário tenha uma sensação de lentidão no ambiente, ainda mais se for uma consulta muito utilizada no sistema. Nesse caso, é cabível uma análise da sessão que está gerando o lock para avaliar porquê ela está demorando tanto para processar e liberar o objeto.

Para se aprofundar na análise de eventos de wait, recomendo a leitura dos posts abaixo:
– https://www.sqlskills.com/help/sql-server-performance-tuning-using-wait-statistics/
– https://www.sqlskills.com/blogs/erin/the-accidental-dba-day-25-of-30-wait-statistics-analysis/
– Wait statistics, or please tell me where it hurts
– List of common wait types
– Using Wait Stats to Find Why SQL Server is Slow
– What is the most worrying wait type?

Conforme eu já havia demonstrado no post SQL Server – Como identificar e coletar informações de consultas demoradas utilizando Extended Events (XE), utilizando um Extended Event (XE), podemos coletar todas as consultas que demorem mais que X segundos a processar na instância e depois analisar quais consultas são essas, nos permitindo ordenar os resultados por tempo de execução, consumo de disco (leitura ou escrita) e também consumo de CPU:

Desta forma, em conjunto com a análise de eventos de wait, podemos iniciar o trabalho de identificar possíveis agressores ao consumo de CPU, Disco ou tempo de execução.

Conforme eu já havia demonstrado no post SQL Server – Como identificar e coletar informações de consultas demoradas utilizando Trace (SQL Server Profiler), utilizando um trace simples, podemos coletar todas as consultas que demorem mais que X segundos a processar na instância e depois analisar quais consultas são essas, nos permitindo ordenar os resultados por tempo de execução, consumo de disco (leitura ou escrita) e também consumo de CPU:

Desta forma, em conjunto com a análise de eventos de wait, podemos iniciar o trabalho de identificar possíveis agressores ao consumo de CPU, Disco ou tempo de execução.

Como já havia citado no começo desse artigo, o conceito é “pesado” é relativo. Ele pode ser tempo de execução, consumo de disco para leitura, consumo de disco para escrita, tempo de CPU, etc..

Utilizando as estatísticas do banco e a DMV sys.dm_exec_query_stats, podemos consultar as queries que foram executadas na instância e aplicar os filtros e ordenação de tempo de execução, disco e CPU, permitindo inclusive, identificar a quantidade de vezes que essa consulta foi executada, tempo médio de execução e tempo da última execução, além de informar a query completa (text) que está sendo executada e também o trecho específico desse objeto/query (TSQL) dessas estatísticas coletadas e também o plano de execução dessa query.

Query utilizadada (Ordenando por tempo de execução):

Resultado:

Como vocês puderam observar, no exemplo acima eu filtrei os dados para me retornar as consultas que demora mais tempo para executar, mas você pode ordenar pela coluna que desejar, conseguindo refinar bem a sua consulta de acordo com seu ambiente e necessidade, junto à análise dos eventos de wait.

Vale lembrar que, como estamos consultando dados de estatísticas do banco, caso o serviço seja reiniciado, esses dados são perdidos. Por este motivo, sugiro criar uma rotina que colete esses dados de tempos em tempos e armazene em uma tabela física, para quando isso acontecer, você possa continuar sua análise de onde parou e não precise esperar por horas ou dias para ter dados para continuar analisando.

Stored Procedure para armazenar as consultas Ad-hoc de todos os databases:

Utilizando uma ideia e estrutura parecida com o exemplo anterior, o SQL Server nos disponibiliza a DMV sys.dm_exec_procedure_stats, onde podemos visualizar as estatísticas de execução agrupadas por objeto e plano de execução, onde um mesmo objeto pode retornar mais de 1 registro nessa DMV caso ele tenha mais de um plano de execução (Caso de parameter sniffing, por exemplo).

Query utilizada (Ordenação por quantidade de execuções):

Resultado:

Vale lembrar que, como estamos consultando dados de estatísticas do banco, caso o serviço seja reiniciado, esses dados são perdidos. Por este motivo, sugiro criar uma rotina que colete esses dados de tempos em tempos e armazene em uma tabela física, para quando isso acontecer, você possa continuar sua análise de onde parou e não precise esperar por horas ou dias para ter dados para continuar analisando. Caso o objeto seja alterado ou recompilado, será gerado um novo plano de execução para ele e os dados dessa view serão zerados, o que reforça a necessidade de ter esse histórico para identificar o efeito dessas mudanças de plano.

Stored Procedure para armazenar as estatísticas de SP’s de todos os databases:

Utilitário muito utilizado por DBA’s de todo o mundo, a sp_WhoIsActive é uma Stored Procedure que realiza diversas consultas em DMV’s do SQL Server, especialmente nas DMV’s sys.dm_exec_sessions e sys.dm_exec_requests para identificar as queries que estão em execução no momento e retornar suas estatísticas de execução, inclusive, até desenvolvi uma versão “lite” da sp_WhoIsActive e compartilhei aqui no blog, no post SQL Server – Query para retornar as consultas em execução (sp_WhoIsActive sem consumir TempDB).

Utilizando essa SP, podemos acompanhar as consultas em execução na instância e avaliar quais estão consumindo mais CPU, Disco, Memória e também, acompanhar os eventos de wait de cada query e se alguma sessão está causando locks na instância:

Por este motivo, eu acho muito interessante ter uma rotina que colete os dados dessa Stored Procedure/View a cada X minutos e armazene em uma tabela física por X dias, de modo que você consiga analisar o passado em caso de uma lentidão e você queira identificar exatamente o que estava sendo executado em determinado instante e como estava o consumo de recursos (CPU, disco, memória, eventos de wait, etc) de cada consulta dessas.

Ter esse nível de informação pode ser muito útil na investigação de problemas de performance (e até outros tipos de problemas também).

Essa Stored Procedure, desenvolvida pelo grande Brent Ozar, é um verdadeiro canivete suiço para identificar rapidamente problemas de performance. Ao ser executada, a sp_BlitzFirst realiza uma série de verificações gerais na instância e nos logs do SQL para tentar encontrar possíveis problemas de performance e te indicar o que é e como corrigir.

Já a sp_BlitzCache, realiza várias verificações nos planos de execução em cache na instância e procura por situações que normalmente levam à uma má performance durante a execução, como índices ausentes (Missing index), conversões implícitas, etc.

Exemplo de execução da sp_BlitzFirst (Visão geral da instância):

Exemplo de execução da sp_BlitzCache (Analisa os planos de execução em cache):

Veja como ela funciona na prática:

Download das SP’s neste link aqui.

Uma outra forma muito utilizada para identificar consultas que podem ser tunadas e possíveis problemas de performance na instância, é utilizando os relatórios do SQL Server Management Studio (SSMS) e o Activity Monitor:

E analisando seus resultados, onde ele já mostra algumas consultas que ele julga que consomem muitos recursos da instância:

O SSMS também nos oferece vários relatórios prontos, que vão desde medir espaço em disco utilizado por cada tabela, quanto a relatórios de performance (Index Usage Statistics, Index Physical Statistics e Object Execution Statistics):

Relatório Object Execution Statistics:

O SSMS possui até relatórios auxiliando a migração de objetos físicos (Tabelas e Stored procedures) para objetos em memória (In-Memory OLTP), através do relatório “Transaction Performance Analysis Overview”:

Outro importante aliado na identificação de potenciais problemas na instância SQL Server é o Perfmon (Monitor de Desempenho), utilitário que já vem instalado no Windows. Com ele, podemos adicionar uma série de contadores, de acordo com o que querendo analisar, e a ferramenta nos mostra graficamente e com números, como está o uso de CPU, a quantidade de leituras/segundo, quantidade de bytes gravados/segundo e uma série gigantesca de contadores e métricas que podemos utilizar para analisar a performance do servidor.

Acessando o Perfmon:

Visão gráfica:

Visão textual:

Tipos de contadores:

Vídeo do MVP Osanam Giordane sobre o Perfmon:

No artigo Contadores do Perfmon, do MCM Fabricio Catae, ele nos apresenta uma lista de contadores que costumam ser utilizados para monitorar instâncias SQL Server, que são:

Logical Disk

• Avg Disk Sec/Read
• Avg Disk Sec/Transfer
• Avg Disk Sec/Write
• Current Disk Queue Length
• Disk Bytes/sec
• Disk Read Bytes/sec
• Disk Write Bytes/sec
• Disk Reads/sec
• Disk Transfers/sec
• Disk Writes/sec

Memory

• %Committed Bytes In Use
• Available MB
• Committed Bytes
• Free System Page Table Entries
• Pool Nonpaged Bytes
• Pool Paged Bytes

Network Interfaces

• Bytes Received/sec
• Bytes Sent/sec
• Bytes Total/sec

Processor

• %Processor Time
• %Privileged Time

System

• Context Switches/sec
• Exception Dispatches/sec
• Processor Queue Length
• System Calls/sec

Adicionalmente, utilize esses contadores por instância do SQL:
Buffer Manager

• Database pages
• Free list stalls/sec
• Free pages
• Lazy writes/sec
• Page life expectancy
• Page lookups/sec
• Page reads/sec
• Readahead pages/sec
• Stolen pages
• Target pages
• Total pages

General Statistics

• Connection Reset/sec
• Logins/sec
• Logouts/sec
• User Connections

SQL Statistics

• Batch Requests/sec
• Safe Auto-Params/sec
• Forced Parametrizations/sec
• SQL Compilations/sec
• SQL Re-Compilations/sec

Para se aprofundar mais no monitoramento de instâncias SQL Server utilizando o Perfmon, não deixe de conferir os Posts de Perfmon do Ninja.

E por fim, uma forma muito prática e rápida de se identificar consultas “pesadas” é utilizando softwares de terceiros, geralmente pagos, para monitorar a performance da sua instância e assim, te dar uma visão gráfica e intuitiva de como está a sua instância SQL Server.

Para isso, separei algumas ferramentas que já utilizei e achei bem legais:

RedGate SQL Monitor (pago)

ApexSQL Monitor (pago)

https://www.youtube.com/watch?v=3Jdvmn3yazA

Quest Spotlight (pago)

SQLSentry SentryOne (pago)

SQL Performance Monitor (grátis)

Veja mais ferramentas acessando este link aqui.