Artigo SQL Magazine 12 - Profiler Parte II – Criando uma trace para análise de performance de um servidor SQL Server

Você precisa estar logado para dar um feedback. Clique aqui para efetuar o login
Para efetuar o download você precisa estar logado. Clique aqui para efetuar o login
Confirmar voto
0
 (0)  (0)

Artigo da Revista SQL Magazine - Edição 12.

Clique aqui para ler esse artigo em PDF.imagem_pdf.jpg

capaSQL12.JPG

Clique aqui para ler todos os artigos desta edição

 

Profiler Parte II – Criando uma trace para análise de performance de um servidor SQL Server

por Paulo Ribeiro

Leitura Obrigatória: SQL Magazine 7, artigo Indexed Views; SQL Magazine 9, artigo Estatísticas de Distribuição; SQL Magazine 11, artigo Profiler Parte I.

 

Como vimos na primeira parte dessa matéria na edição anterior, o Profiler é uma ferramenta de apoio ao gerenciamento e tuning de servidores SQL Server 2000. Iniciar uma trace é uma tarefa simples: basta executar o Profiler, conectar-se a um servidor, clicar em RUN e pronto! Mas, e agora? Os eventos selecionados servem para identificar a causa do problema de má performance em meu servidor? 

O objetivo dessa matéria será criar um guia, passo-a-passo, de como deve ser conduzido um processo para diagnóstico de performance utilizando o Profiler como ferramenta de apoio.

Análise preliminar: identificando stored procedures e batchs com baixa performance

Demora excessiva para conclusão de consultas, deadlocks em demasia e problemas com timeout nas aplicações - esse é o quadro de um servidor com sérios problemas de performance. Nosso objetivo inicial será efetuar um levantamento para determinar quais são os processos mais demorados, cronometrando a execução de batchs e stored procedures (sp´s) nesse servidor.

 

Nota

A denominação “batch” é utilizada para especificar um grupo de um ou mais comandos T-SQL enviados de uma só vez para o servidor SQL Server.

 

Iniciaremos o Profiler no menu do Microsoft SQL Server, escolhendo New Trace na opção File da barra de ferramentas. Na tela de propriedades da trace, confirme a seleção do template SQLProfilerStandard na guia General. Esse template captura a execução de batchs (TSQL\SQL: Batch Completed) e sp´s (Stored Procedures\ RPC: Completed). Os eventos Security Audit e Sessions não são necessários para essa análise, podendo ser removidos (selecione o evento e clique em <<Remove). A Figura 1 apresenta a relação final de eventos que devem estar selecionados.

 image001.png

Figura 1. Eventos que devem ser selecionados para monitorar execução de batchs e sp´s.

 

As colunas e ordem de apresentação dos eventos do template SQLProfilerStandard sofrerão duas alterações: na guia Data Columns ordenaremos as linhas capturadas segundo seu tempo de execução e eliminaremos algumas colunas desnecessárias nesse momento. Para ordenar as linhas do Profiler segundo a duração do comando executado, selecione Duration e clique em Up até que essa coluna fique logo abaixo de Groups. As colunas removidas foram: NTUserName, LoginName, CPU, Reads, Writes e ClientProcessId. O resultado final pode ser visualizado na Figura 2.

 

image004.jpg

Figura 2. Colunas selecionadas para visualização no Profiler.

 

Até esse momento, a trace irá capturar todos os batchs e sp´s executados nesse servidor. Seria interessante ligar um filtro de tempo de modo que só fossem captutados os processos com tempo de execução acima de um determinado limite. Para conseguir esse efeito, vamos ligar o filtro Duration na guia Filters, trabalhando com um limite de 2000 milisegundos (ver Figura 3).

 

image006.jpg

Figura 3. Filtrando comandos T-SQL cujo tempo de execução for superior a 2000 milisegundos (=2 segundos).

 

Agora inicie a trace clicando em . Para simular uma atividade no SGBD, abra uma sessão no Query Analyzer, digite as linhas da Listagem 1 e confirme o resultado na tela do Profiler (ver Figura 4).

 

use NorthWind

go

 

create proc stp_teste

as

  select top 1 * from orders

  select top 1 * from [order details]

  waitfor delay '00:00:03'

  select top 1 * from customers

go

 

exec stp_teste

go

select count(*) from [order details] 

go

select top 10 * from orders

go

Listagem 1.

 

 image008.jpg

 Figura 4. Executando trace com o filtro Duration ativo.

 

Analisando a trace, verificamos que:

 

·         A única linha capturada foi a da execução de stp_Teste, pois o filtro com  Duration=2000 está ativo, inibindo a visualização dos dois últimos select´s ;

·         A execução da sp aparece sob o evento TSQL\SQL:BatchCompleted e não em Stored Procedures\RPC: Completed por dois motivos:

o        O Profiler considera quaisquer sequência de comandos executados no Query Analyzer como um batch;

o        O evento RPC:Completed irá aparecer somente quando a sp for executada numa aplicação que faça uso do mecanismo de RPC (Remote Procedure Call), e não pelo comando T-SQL execute.

 

Após deixar a trace ativa por um período, teremos capturado os processos com maior tempo de execução. O próximo passo será analisar os comandos T-SQL presentes nas sp´s e/ou batchs responsáveis pelos gargalos.

Análise específica: identificando comandos T-SQL com baixa performance

A trace gerada anteriormente forneceu a relação de batchs e sp´s que estão apresentando tempo de execução superior a 2 segundos. No caso da stored procedure stp_Teste, temos que identificar qual comando T-SQL está sendo responsável pela lentidão. Para conseguir esse efeito, criaremos uma trace para analisar somente a sp stp_Teste. Isto permitirá que visualizemos os tempos dos comandos T-SQL à medida em que são executados.

O ponto de partida é identificar o id do objeto que queremos selecionar. No Query Analyzer, digite:

 

select object_id (‘stp_Teste’)

----------------------------------------------------------------------------------------------------

743673697

 

(1 row(s) affected)

 

Crie agora uma nova trace no Profiler, selecionando os eventos presentes na Figura 5. SP:Completed irá gerar uma linha contendo a chamada para a procedure e SP:StmtCompleted irá gerar uma linha para cada comando T-SQL executado dentro da sp.

 

image010.jpg

Figura 5. Eventos que devem ser selecionados para visualizar a execução dos comandos T-SQL dentro das sp´s.

 

Na guia Data Columns, selecione os mesmos eventos assinalados na Figura 6.

 

image012.jpg

Figura 6. Selecionando colunas para analisar execução de sp.

 

Na guia Filters, siga até ObjectId e informe o id da procedure stp_Teste obtida anteriormete (Figura 7).

 

image014.jpg

Figura 7. Ligando o filtro ObjectId para filtrar os comandos T-SQL executados na procedure stp_Teste

 

Clique em , execute a procedure stp_Teste no Query Analyzer e em seguida pare a trace. O resultado encontra-se na Figura 8.

 

image016.jpg 

 

Figura 8. Visualização dos comandos executados na procedure stp_Teste.

Analisando a trace na Figura 8, nota-se que o comando ... waitfor delay ’00:00:03’ é o responsável pela lentidão na procedure stp_Teste. Perceba que a duração dele equivale a 3 segundos enquanto a duração dos outros é nula. A idéia agora é colar esses comandos individuais no Query Analyzer (1) e digitar + para avaliar o plano de execução gráfico. O comando ... waitfor delay ’00:00:03’ não necessita de maiores análises, pois denuncia explicitamente o gargalo. Na vida real, provavelmente seríamos apresentados a processos que denunciariam varreduras seqüenciais (=Table Scan ou Index Scan) em tabelas com milhares de linhas.

 

(1) Clique sobre a linha cujo comando deseja colar e, na parte inferior da tela do Profiler, execute + para capturar o comando, seguido de um + na tela do Query Analyzer.

 

Esse procedimento de análise deverá se repetir para todas as sp´s capturadas na trace inicial. Os batchs não necessitam da filtragem adicional por ObjectId; basta recortar o comando na trace e avaliar seu plano de execução no Query Analyzer.

Análise de outros objetos relacionados à performance

Como o leitor já deve ter percebido, o Profiler deixa à nossa disposição uma infinidade de combinações entre eventos, colunas e filtros. Os eventos que devemos selecionar na trace dependem do que exatamente estamos querendo analisar; os filtros informados também devem estar de acordo com a informação obtida em cada evento.

Um erro bastante comum ao criarmos traces advém do fato de ligarmos filtros em eventos que não tratam essa informação. Por exemplo, a filtragem da coluna DBUserName para o evento Locks/Lock:DeadLock não produziria o resultado esperado pois Locks/Lock:DeadLock não trabalha essa informação (ver Figura 9).  Para saber as colunas retornadas por cada evento, procure o Event Classes no BOL.

 

Figura 9. Colunas atualizadas para cada evento na classe Locks.

image017.png 

A seguir será apresentado um resumo dos principais eventos que devem ser analisados para solucionar problemas relacionados à performance.

Identificando cursores criados no servidor

Cursores oneram performance pois não conseguem desfrutar da grande vantagem dos SGBDs: trabalhar o dado orientado a bloco. A linguagem SQL foi criada com comandos que efetuam manipulações em lote: podemos selecionar, inserir e deletar vários registros com um único comando. Quando utilizamos cursores, estamos fazendo uma inversão nessa regra: selecionamos uma série de linhas para serem trabalhadas individualmente.

Existem situações onde a utilização de cursores se torna inevitável, quer pela complexidade do negócio ou mesmo quando a aplicação precisa apresentar um RecordSet para navegação na tela do cliente. Em ambos os casos, entretanto, existem algumas regras de boa conduta na utilização de cursores que devem ser observadas:

·         Procure transformar atualizações realizadas com cursores em processos que utilizem somente os comandos select, insert, update e delete. Trabalhar com cursores é uma opção tentadora que deve ser evitada. Vale a pena gastar alguns minutos a mais numa solução que utilize alguns select´s, crie uma tabela temporária e depois faça uma atualização em lote.

·         Utilize somente cursores do lado cliente nas aplicações. Manter cursores ativos no servidor é uma prática que deve ser evitada: cursores devem ser mantidos na aplicação cliente para não sobrecarregar a memória do servidor. Existem dois eventos que controlam a abertura e fechamento de cursores no servidor: Cursors:Cursor Open e  Cursors:Cursors Close. Se você se deparar com esses eventos, peça para o desenvolvedor mudar a localização do cursor para o cliente.

 

Na trace da Figura 10 podemos visualizar um cursor de servidor.

 

Figura 10. Trace capturando um cursor de servidor

image021.jpg 

Com uma pequena alteração em CursorLocation no código escrito em Visual Basic (ver Listagem 2)...

 

Dim con As New ADODB.Connection

       con.Open "Provider=SQLOLEDB.1;Integrated Security=SSPI;Persist Security Info=False;Initial Catalog=northwind;Data Source=srvteste"

 

       Dim rs As New ADODB.Recordset

       rs.CursorLocation = adUseServer … substituir por ... adUseClient

       rs.Open "select * from northwind.dbo.employees", con, adOpenStatic, adLockOptimistic

 

       End Sub

Listagem 2.

 

... obtemos o resultado apresentado na Figura 11. Perceba que os eventos CursorOpen e CursorClose não existem mais!

 

image023.jpg

Figura 11.

Rastreando processos envolvidos em Deadlocks

Deadlock é uma causa freqüente de má performance, pois requer que a conexão escolhida como vítima  - e cuja execução de comandos foi abortada - envie novamente o comando para execução. O Profiler possui dois eventos que nos ajudam a rastrear deadlocks: Lock:DeadLock informa a ocorrência do erro #1205 associado ao deadlock e Lock:DeadLockChain irá apontar o spid das conexões envolvidas no deadlock. A Figura 12 ilustra a ocorrência de um deadlock: note que as conexões envolvidas são as 62 e 66 (=Lock:DeadLock Chain); os comandos responsáveis pelo conflito de recursos que originou o deadlock são os dois últimos updates. A ação corretiva nesse caso seria eliminar a cláusula holdlock existente nos dois select´s iniciais da trace.

 

Figura 12. Ocorrência de DeadLock rastreada pelo Profiler.

 

image025.jpg 

 

Evitando CacheMiss

Quando acionamos uma sp, seu plano de execução fica em memória. Nesse plano são armazenadas instruções de como a query deverá ser executada: que índices utilizar, o tipo de join selecionado, etc. Antes de criar um plano de execução novo, o otimizador faz uma busca na área de cache destinada a procedures procurando por um plano pré-existente. Se a busca for bem sucedida, o plano será aproveitado e a sp será executada de acordo com ele.

Existem algumas situações onde o otimizador é obrigado a fazer várias tentativas até encontrar o código pré-compilado. Cada uma dessas tentativas mal sucedidas dispara um evento conhecido por SP:CacheMiss, que pode ser evitado seguindo-se as dicas abaixo:

·         Não utilize o prefixo “sp_” para nomear suas sp´s. Quando o otimizador encontra uma stored-procedure com o prefixo sp, sua execução é desencadeada no banco de dados master. Como a sp não existe nesse banco de dados, seu plano de execução não é encontrado na primeira tentativa, disparando um evento SP:CacheMiss. O processo de execução prossegue procurando a sp no banco de dados local, onde o código compilado é encontrado e a sp executada.

·         Execute stored-procedures qualificando seu dono (owner). Lembre-se que você pode possuir objetos com o mesmo nome mas com owners diferentes. Portanto se você possui usuários que não possuem privilégio de dbo – e isso deve ser a regra –, especifique o owner da sp no momento da chamada. Troque exec stp_Teste por exec dbo.stp_Teste.

 

Agora um teste: abra o Profiler, mantendo o template padrão SQLServerProfilerStandard. Na guia Events, adicione o evento StoredProcedures/SP:CacheMiss. Crie uma nova sp de nome sp_Teste com o mesmo código de stp_Teste criada no início desse artigo; abra uma sessão no Query Analyzer com um usuário que não possua privilégios de db_owner(1) no banco – por exemplo UserSQLMag (ver Nota) – e execute o batch de comandos da Listagem 4. Confira o resultado na tela do Profiler na Figura 13.

 

set nocount ON

select system_user

go

select user_name() --não pode retornar dbo !!!

go

exec dbo.stp_Teste

go

exec stp_Teste

go

exec sp_teste

go

Listagem 4.

 

Nota

Usuários pertencentes ao role db_owner possuem permissão para executar qualquer tipo de operação em um banco de dados. Para verificar quais papéis estão atrelados a um usuário, execute o cmd  sp_HelpUser . O usuário UserSQLMag – que possui apenas permissão de leitura e escrita no database NorthWind - foi criado com a seqüência de comandos T-SQL abaixo:

use master

go

exec sp_addlogin  'UserSQLMag','UserSQLMag'

use NorthWind

go

exec sp_grantdbaccess 'UserSQLMag'

exec sp_addrolemember 'db_datareader', 'UserSQLMag'

exec sp_addrolemember 'db_datawriter', 'UserSQLMag'

 

Figura 13. Constatando a ocorrência do evento CacheMiss na execução de sp´s.

 image027.jpg

 

 

A Tabela 1 faz um breve comentário sobre as três modalidades de execução de stored procedures. 

Comando executado

CacheMiss?

Motivo

Exec dbo.stp_Teste

Não

A sp foi executada qualificando-se o owner dbo.

exec stp_Teste

Sim

Como o usuário não pertence ao grupo dbo, a sp é executada sem sucesso em exec UserSQLMag.stp_Teste, gerando um CacheMiss. Na segunda tentativa – com usuário dbo – ocorre o acerto (= exec dbo.stp_Teste)

exec sp_Teste

Sim

A sp foi procurada sem sucesso no banco de dados master para dbo (primeiro CacheMiss) e depois no banco NorthWind para UserSQLMag (segundo CacheMiss). Na última execução - no banco NorthWind para dbo -  ocorre o acerto.

Tabela 1.

Evitando recompilações

Denomina-se compilação o processo utilizado pelo otimizador para gerar o plano de execução de uma sp. A compilação ocorre:

·         Quando a sp é executada pela primeira vez;

·         Quando o servidor SQL Server 2000 é reinicializado (stop/start no serviço);

·         Se utilizarmos a cláusula with recompile na criação da sp;

 

·         Quando intercalamos comandos de criação de objetos (=Data Definition Language ou DDL) com comandos de manipulação (=Data Manipulation Language ou DML). Como sabemos, um plano de execução é gerado ANTES de uma seqüência de comandos ser executada (no caso de uma procedure, o plano de execução é gerado antes da procedure ser disparada). Nesse plano, são determinados os meios de acesso às tabelas, baseados nos índices EXISTENTES. Ora, se no código de uma stored procedure ou batch criamos um índice na linha 10 e efetuamos um select nessa mesma tabela na linha 11, o índice criado não será considerado no processo de otimização, pois ele passará a existir somente quando a procedure for executada (o plano é gerado antes da execução da procedure). Pois bem, numa situação dessas o otimizador força uma compilação adicional da query APÓS a criação do indice, de modo que o select contido na linha 11 possa se beneficiar do índice recém-criado.

 

·         Quando alteramos o estado dos comandos ANSI_DEFAULTS, ANSI_NULLS, ANSI_WARNINGS e CONCAT_NULL_YIELDS_NULL, deixando-os em desacordo com a sessão responsável pela criação da sp. Executar uma mesma query com ANSI_NULLS ligado (=ON) e desligado (=OFF) pode acarretar em resultados diferentes (veja SQL Magazine 7). Quando o otimizador se depara com alteração dessas variáveis no decorrer da execução da sp, ele entente que o plano de execução deve ser reavaliado, solicitando uma nova compilação.

 

A compilação ocupa um tempo precioso quando realizada no momento da execução da sp. A Tabela 2 ilustra algumas sp´s que foram modificadas para inibir compilações.

 

Tabela 2. Alterações no código das sp´s que evitam recompilações

tabela2.JPG

O evento disparado quando acontece uma recompilação é SP:Recompile. A Figura 14 lista as execuções no Profiler antes e depois das alterações sugeridas na Tabela 2.

image029.png

Figura 14. Visualizando recompilações com o evento SP:Recompile.

 

 

Nota

Quando um índice é criado externamente a uma SP, para melhorar o desempenho de uma query contida na procedure, a geração de um novo plano não acontece de maneira automática – devemos “forçar” a recompilação com o comando sp_recompile . 

Confirmando TCP/IP como protocolo de conexão

Utilize Security Audit:Audit Login para confirmar se o TCP/IP é o protocolo padrão das conexões (ver Figura 15). Até a versão 2.6 do MDAC 2 , o protocolo default de conexão era o Named Pipes, que não possui performance tão boa quanto o TCP/IP. Portanto, se você localizar alguma sessão com protocolo Named Pipes, siga até a estação cliente e verifique o SQL Server Client Network Utility.

 

2 MDAC é o acrônimo de Microsoft Data Access Components; é o componente responsável pela  conexão do cliente com o servidor SQL Server.

 

Figura 15. Selecionando o evento Audit Login para confirmar o protocolo TCP/IP como padrão.

image032.jpg

Identificando erros

O Profiler possui uma classe chamada Errors and Warnings que possui dois eventos bastante interessantes: o primeiro – Exception – é indicado para capturar mensagens que aparecem nas aplicações cliente tais como violação de FK, violação de PK, divisão por zero, etc. O segundo – Missing Column Statistics  irá sinalizar colunas sem estatísticas de distribuição, que poderiam ser úteis para o otimizador no processamento da consulta que estiver sendo executada (Figura 16).

 

image034.jpg

Figura 16. Identificando erros e falta de estatísticas.

 

Estatísticas desatualizadas acarretam em planos de execução ineficientes, portanto devemos proceder à sua atualização. Apenas recordando o que foi visto na edição 9, o comando para criação de estatísticas para a coluna Freight na tabela Orders é o seguinte: 

CREATE STATISTICS st_Orders_Freight on Orders (Freight) with FullScan

Como agendar uma trace

Como você faria para gerar a trace de um processo com problemas de performance que roda somente nas madrugadas de domingo? Gere um script da trace, agende sua utilização no SQL Server 2000 e fim!

 

NOTA

Agendamentos de processos no SQL Server 2000 são efetuados através da criação de jobs. Para criar um job no Enterprise Manager, siga o procedimento definido na figura 16B. A criação e manipulação de jobs serão abordados em matéria específica.

 

Figura 16B . Criando um job a partir do Enterprise Manager

 

image035.png 

 

 Para gerar o script de uma trace siga até a opção File do Profiler, selecione Script Trace ... For SQL Server 2000 (ver Figura 17).


image038.jpg

Figura 17. Gerando o script dos comandos T-SQL necessários para gerar uma trace.


O código gerado pode ser visualizado na Listagem 5.

 

Listagem 5. Script gerado pelo Profiler para criação de uma trace.

/*****************************/

/* Created by: SQL Profiler            */

/* Date: 28/01/2004  13:45:07         */

/*****************************/

 

-- Create a Queue

declare @rc int

declare @TraceID int

declare @maxfilesize bigint

declare @DateTime datetime

 

set @DateTime = '2004-01-28 14:15:00.000'  horário previsto para término da trace

set @maxfilesize = 5  tamanho máximo do arquivo-texto da trace

 

exec @rc = sp_trace_create @TraceID output, 0, N'c:\temp\Trace_SQLMAG', @maxfilesize, @Datetime

if (@rc != 0) goto error                                                    

                                            nome do arquivo-texto que irá armazenar a trace  

declare @on bit

set @on = 1

exec sp_trace_setevent @TraceID, 10, 1, @on

.

...                                             seleção  dos eventos e colunas que aparecem na trace

……                                                                             

exec sp_trace_setevent @TraceID, 17, 18, @on

 

declare @intfilter int

declare @bigintfilter bigint

 

exec sp_trace_setfilter @TraceID, 10, 0, 7, N'SQL Profiler' os filtros que você definiu aparecem aqui

 

exec sp_trace_setstatus @TraceID, 1  esse comando irá iniciar a trace

 

select TraceID=@TraceID  o id gerado para essa trace é mostrado no final do processo

goto finish

 

error:

select ErrorCode=@rc

 

finish:

go


A Tabela 3 faz um resumo dos principais comandos utilizados na manipulação de traces.


tabela3.JPG

Tabela 3.

Nota

Funções internas no SQL Server 2000 que possuem o prefixo “fn_” precisam ser chamadas com a adição de “::” (duas vezes o sinal de pontuação dois pontos) . Um exemplo de execução da função fn_trace_getinfo encontra-se abaixo:

 

Select * from ::fn_trace_getinfo(default)

----------------------------------------------------------------------------------------------------------------------------------------------------------

TraceId

Property

Value

1

1

0

1

2

c:\temp\Trace_SQLMag

1

3

5

1

4

2004-01-28 14:15:00.000

1

5

1

O resultado da query pode ser assim interpretado:

TraceId

Identificação da trace

Property

1 – Interno;

2 – Nome do arquivo de saída;

3 – Tamanho máximo do arquivo de saída;

4 – Horário para término de execução;

5 – Status atual da trace, a saber:

      1 – Trace está ativa;

      0 – Trace foi encerrada.

Conclusão

O Profiler é uma ferramenta pouco explorada nos livros sobre SQL Server 2000, mas sua utilização é indispensável no dia-a-dia de um DBA. O objetivo dessa matéria foi introduzir os principais eventos relacionados à performance que podem ser monitorados com a ajuda do Profiler. Agora é com vocês, até a próxima!

 
Você precisa estar logado para dar um feedback. Clique aqui para efetuar o login
Receba nossas novidades
Ficou com alguma dúvida?