Passo a passo para encontrar as querys mais demoradas do Banco de Dados

Quem não quer saber quais são as querys mais demoradas do seu ambiente de Banco de Dados? Em quais horários essas querys rodam? Quem está executando? De onde está sendo rodada? Quais os recursos que essas querys consomem? Nesse artigo, demonstrarei como eu faço esse acompanhamento no meu ambiente de trabalho.

por Fabrício França Lima

Fala Pessoal,

Quem não quer saber quais são as querys mais demoradas do seu ambiente de Banco de Dados? Em quais horários essas querys rodam? Quem está executando? De onde está sendo rodada? Quais os recursos que essas querys consomem?

Nesse artigo, demonstrarei como eu faço esse acompanhamento no meu ambiente de trabalho. Ele é válido para as versões 2005 e 2008 do SQL Server. Para a versão do SQL Server 2000, algumas colunas do trace devem ser alteradas pois não existem no SQL 2000.

Primeiramente, deve ser criada uma tabela para armazenar o log das querys mais demoradas que rodam no nosso banco de dados. Deve-se escolher a database adequada do seu ambiente para armazenar essa tabela. Também criei um índice nessa tabela para efetuar as buscas pela data em que a query rodou.

CREATE TABLE dbo.Traces(   

    TextData VARCHAR(MAX) NULL,

    NTUserName VARCHAR(128) NULL,

    HostName VARCHAR(128) NULL,

    ApplicationName VARCHAR(128) NULL,

    LoginName VARCHAR(128) NULL,

    SPID INT NULL,

    Duration NUMERIC(15, 2) NULL,

    StartTime DATETIME NULL,

    EndTime DATETIME NULL,

    Reads INT,

    Writes INT,

    CPU INT,

    ServerName VARCHAR(128) NULL,

    DataBaseName VARCHAR(128),

    RowCounts INT,

    SessionLoginName VARCHAR(128))

   

-- Para realizar as querys de busca pela data que a query rodou.   

CREATE CLUSTERED INDEX SK01_Traces on Traces(StartTime) with(FILLFACTOR=95)

Em seguida, criaremos uma procedure para criar o arquivo de trace que ficará rodando em backgroud no servidor.

Nessa procedure é criado um trace com a procedure sp_trace_create, onde especificamos o caminho que esse trace será armazenado. No meu caso criei uma pasta chamada Trace no C: do meu servidor. Você deve criar esse diretório antes de rodar o procedimento. Caso queria armazenar em um caminho diferente basta mudar o caminho na procedure.

Com a procedure sp_trace_setevent, nós definimos quais os eventos que nosso trace pegará. Neste caso, armazenaremos os eventos:

Event Number	Event Name	Description
10	RPC:Completed	Occurs when a remote procedure call (RPC) has completed.
12	SQL:BatchCompleted	Occurs when a Transact-SQL batch has completed.

Após selecionarmos os eventos, devemos escolher as colunas que desejamos visualizar. As colunas que utilizo no meu ambiente são as seguintes:

Column Number	Column Name	Description
1	TextData	Text value dependent on the event class that is captured in the trace.
6	NTUserName	Microsoft Windows user name.
8	HostName	Name of the client computer that originated the request.
10	ApplicationName	Name of the client application that created the connection to an instance of SQL Server. This column is populated with the values passed by the application rather than the displayed name of the program.
11	LoginName	SQL Server login name of the client.
12	SPID	Server Process ID assigned by SQL Server to the process associated with the client.
13	Duration	Amount of elapsed time (in milliseconds) taken by the event. This data column is not populated by the Hash Warning event.
14	StartTime	Time at which the event started, when available.
15	EndTime	Time at which the event ended. This column is not populated for starting event classes, such as SQL:BatchStarting or SP:Starting. It is also not populated by the Hash Warning event.
16	Reads	Number of logical disk reads performed by the server on behalf of the event. This column is not populated by the Lock:Released event.
17	Writes	Number of physical disk writes performed by the server on behalf of the event.
18	CPU	Amount of CPU time (in milliseconds) used by the event.
26	ServerName	Name of the instance of SQL Server (either servername or servername\instancename) being traced.
35	DatabaseName	Name of the database specified in the USE database statement.
40	DBUserName	SQL Server database username of the client.
48	RowCounts	Number of rows in the batch.
64	SessionLoginName	The login name of the user who originated the session. For example, if you connect to SQL Server using Login1 and execute a statement as Login2, SessionLoginName displays Login1, while LoginName displays Login2. This data column displays both SQL Server and Windows logins.

A lista completa com todos os eventos pode ser encontrada no books online pesquisando pela procedure sp_trace_setevent.

Em seguida é realizado o filtro na coluna 13(Duration) para retornar apenas os valores maiores ou iguais a 3 segundos. Segue abaixo o script dessa procedure.

CREATE PROCEDURE [dbo].[stpCreate_Trace]

AS

BEGIN

    declare @rc int, @TraceID int, @maxfilesize bigint, @on bit, @intfilter int, @bigintfilter bigint

    select @on = 1, @maxfilesize = 50

    -- Criação do trace

    exec @rc = sp_trace_create @TraceID output, 0, N"C:\Trace\Querys_Demoradas", @maxfilesize, NULL

    if (@rc != 0) goto error

    exec sp_trace_setevent @TraceID, 10, 1, @on 

    exec sp_trace_setevent @TraceID, 10, 6, @on 

    exec sp_trace_setevent @TraceID, 10, 8, @on 

    exec sp_trace_setevent @TraceID, 10, 10, @on

    exec sp_trace_setevent @TraceID, 10, 11, @on

    exec sp_trace_setevent @TraceID, 10, 12, @on

    exec sp_trace_setevent @TraceID, 10, 13, @on

    exec sp_trace_setevent @TraceID, 10, 14, @on

    exec sp_trace_setevent @TraceID, 10, 15, @on

    exec sp_trace_setevent @TraceID, 10, 16, @on

    exec sp_trace_setevent @TraceID, 10, 17, @on

    exec sp_trace_setevent @TraceID, 10, 18, @on

    exec sp_trace_setevent @TraceID, 10, 26, @on

    exec sp_trace_setevent @TraceID, 10, 35, @on

    exec sp_trace_setevent @TraceID, 10, 40, @on

    exec sp_trace_setevent @TraceID, 10, 48, @on

    exec sp_trace_setevent @TraceID, 10, 64, @on

    exec sp_trace_setevent @TraceID, 12, 1,  @on

    exec sp_trace_setevent @TraceID, 12, 6,  @on

    exec sp_trace_setevent @TraceID, 12, 8,  @on

    exec sp_trace_setevent @TraceID, 12, 10, @on

    exec sp_trace_setevent @TraceID, 12, 11, @on

    exec sp_trace_setevent @TraceID, 12, 12, @on

    exec sp_trace_setevent @TraceID, 12, 13, @on

    exec sp_trace_setevent @TraceID, 12, 14, @on

    exec sp_trace_setevent @TraceID, 12, 15, @on

    exec sp_trace_setevent @TraceID, 12, 16, @on

    exec sp_trace_setevent @TraceID, 12, 17, @on

    exec sp_trace_setevent @TraceID, 12, 18, @on

    exec sp_trace_setevent @TraceID, 12, 26, @on

    exec sp_trace_setevent @TraceID, 12, 35, @on

    exec sp_trace_setevent @TraceID, 12, 40, @on

    exec sp_trace_setevent @TraceID, 12, 48, @on

    exec sp_trace_setevent @TraceID, 12, 64, @on

    set @bigintfilter = 3000000 -- 3 segundos

    exec sp_trace_setfilter @TraceID, 13, 0, 4, @bigintfilter

    -- Set the trace status to start

    exec sp_trace_setstatus @TraceID, 1

    goto finish

    error:

    select ErrorCode=@rc

    finish:

END

No meu principal servidor de produção, utilizo 3 segundos para realizar o filtro, mas isso depende da realidade de cada ambiente. Por exemplo, antigamente eram logadas as querys que demoravam mais de 10 segundos no meu ambiente, depois da migração para o SQL Server 2005 e da aquisição de um storage baixamos para 5 segundos. Há pouco tempo, depois de melhorar as querys mais demoradas e as que mais consumiam recursos, após a alteração, criação e exclusão de muitos indices (tudo isso com a ajuda das salvadoras dmvs presentes a partir do SQL Server 2005), como só estavam sendo retornadas 30 querys por hora em média, baixei o trace para 3 segundos para melhor identificar possíveis gargalos. O tuning continua, para que eu tenha cada vez menos registros demorando mais de 3 segundos.

Agora vamos rodar nossa procedure para criar o trace.

exec dbo.stpCreate_Trace

Para conferir o trace criado, basta executar a query abaixo.

SELECT *

FROM :: fn_trace_getinfo(default)

where cast(value as varchar(50)) = "C:\Trace\Querys_Demoradas.trc"

Depois de criado, vamos rodar algumas querys para testar o nosso trace.

waitfor delay "00:00:04"

GO

create procedure stpTeste_Trace1

AS

BEGIN

    waitfor delay "00:00:04"

END

GO

exec stpTeste_Trace1

-- Conferindo todos os dados que foram armazenados no trace.

Select Textdata, NTUserName, HostName, ApplicationName, LoginName, SPID, cast(Duration /1000/1000.00 as numeric(15,2)) Duration, Starttime,

    EndTime, Reads,writes, CPU, Servername, DatabaseName, rowcounts, SessionLoginName

FROM :: fn_trace_gettable("C:\Trace\Querys_Demoradas.trc", default)

where Duration is not null

order by Starttime

Segue abaixo o resultado da query com os dados armazenados no trace.

A coluna TextData retorna exatamente a query que você rodou e demorou mais de 3 segundos. Esse tempo pode ser conferido na coluna Duration, Starttime e Endtime. Outras 3 colunas que me ajudam muito são as colunas Reads, Writes e CPU que mostram os recursos que uma determinada query está consumindo.

Agora que o trace já foi testado e vimos que ele realmente funciona, criaremos um job para enviar o trace para a tabela de log e automatizar todo o processo.

Você deve criar um Job no Management Studio com o nome “DBA - Trace Querys Demoradas” e esse job deve possuir 3 steps.

STEP 1- No primeiro Step devemos parar o trace momentaneamente para enviar todo o seu resultado para a tabela de log. Nesse step, você deve selecionar a database em que vc criou a tabela que armazenará o trace e incluir a query abaixo no step.

Declare @Trace_Id int

SELECT @Trace_Id = TraceId

FROM fn_trace_getinfo(0)

where cast(value as varchar(50)) = "C:\Trace\Querys_Demoradas.trc"

exec sp_trace_setstatus  @traceid = @Trace_Id,  @status = 0 -- Interrompe o rastreamento especificado.

exec sp_trace_setstatus  @traceid = @Trace_Id,  @status = 2 --Fecha o rastreamento especificado e exclui sua definição do servidor.

Insert Into Traces(Textdata, NTUserName, HostName, ApplicationName, LoginName, SPID, Duration, Starttime,

    EndTime, Reads,writes, CPU, Servername, DatabaseName, rowcounts, SessionLoginName)

Select Textdata, NTUserName, HostName, ApplicationName, LoginName, SPID, cast(Duration /1000/1000.00 as numeric(15,2)) Duration, Starttime,

    EndTime, Reads,writes, CPU, Servername, DatabaseName, rowcounts, SessionLoginName

FROM :: fn_trace_gettable("C:\Trace\Querys_Demoradas.trc", default)

where Duration is not null

order by Starttime

Segue abaixo a figura de como fica esse step:

STEP 2 - Agora que os dados do trace já foram armazenados na tabela, deve-se excluir o arquivo de trace para que um novo seja criado. Isso pode ser realizado executando o comando “del C:\Trace\Querys_Demoradas.trc /Q” como pode ser visto na figura abaixo:

STEP 3 - Esse passo deve apenas recriar o trace. Similar ao step 1, você deve selecionar a database em que vc criou a procedure e rodar a query abaixo:

exec dbo.stpCreate_Trace

No meu ambiente, esse job roda de hora em hora no meu principal servidor de produção, mas isso depende da sua necessidade. Eu também excluo os registros com mais de 60 dias, para que a tabela de log não fique muito grande, ja que não analiso esses registros mais antigos.

Agora que nosso procedimento ja está em produção, é possivel atacar as querys mais demoradas.

No meu ambiente, identifico as procedures que mais retornam no trace e realizo um agrupamento, como feito abaixo, para facilitar minha visualização diária. Para um exemplo, vou criar mais uma procedure de teste e executá-las algumas vezes.

CREATE PROCEDURE stpTeste_Trace2

AS

BEGIN

    waitfor delay "00:00:04"

END

GO

exec stpTeste_Trace1 -- Procedure ja criada

GO

exec stpTeste_Trace1

GO

exec stpTeste_Trace2

GO

exec stpTeste_Trace2

GO

exec stpTeste_Trace2

GO

exec stpTeste_Trace2

GO

Depois de executadas, rodarei o Job para importar o arquivo de trace para a tabela de log.

EXEC msdb..sp_start_job @job_name = "DBA - Trace Querys Demoradas"

Com a query abaixo, podemos visualizar os dados armazenados no trace agrupados por procedure.

declare @Dt_Inicial datetime, @Dt_Final datetime

select @Dt_Inicial = cast(floor(cast(getdate() as float)) as datetime), @Dt_Final = cast(floor(cast(getdate()+1 as float)) as datetime)

select case    when TextData like "%stpTeste_Trace1%" then "stpTeste_Trace1"   

        when TextData like "%stpTeste_Trace2%" then "stpTeste_Trace2"

    else "Outros" end Nm_Objeto,

    count(*) QTD, sum(Duration) Total, avg(Duration) Media, min(Duration) Menor, Max(Duration) Maior,

    sum(Reads) Reads, sum(writes) Writes, sum(cpu) CPU

from Traces (nolock)

where Starttime >= @Dt_Inicial and Starttime < @Dt_Final -- Periodo a ser analizado

group by case    when TextData like "%stpTeste_Trace1%" then "stpTeste_Trace1"   

        when TextData like "%stpTeste_Trace2%" then "stpTeste_Trace2"

    else "Outros" end

order by Total desc

Essa query retorna o seguinte resultado:

Onde QTD é a quantidade de vezes que a procedure demorou mais de 3 segundos, Total é o tempo total dessas execuções, Media é o tempo médio dessas execuções, Menor e Maior são os menores e maiores tempos respectivamente, e Reads, Writes e CPU é a soma dos recursos que as execuções dessas procedures gastaram.

Para quem viu o primeiro artigo que escrevi Criando um CheckList Automático do Banco de Dados , eu recebo essa informação em minha planilha de CheckList diário com um filtro para pegar o trace de 08:00am as 18:00pm do dia anterior. Desta forma, analiso quais são as procedures que mais demoram no meu ambiente para melhorá-las.

Como já disse anteriormente, tenho esse procedimento implantado no meu principal servidor de produção e ele não consome muitos recursos do servidor. Logo vale apena implementá-lo levando em conta que a informação que você tem é muito valiosa. É possível identificar por exemplo, a partir de qual horário os procedimentos do seu ambiente começaram a apresentar uma lentidão ou que tem alguém da sua equipe de desenvolvimento rodando alguma query pesada no seu servidor de produção no meio do dia ou ainda que no momento que executam a procedure A, ela faz com que muitas outras procedures fiquem lentas. Dentre outros benefícios.

Sugiro fortemente que quem não possui uma rotina parecida com essa, tente implementá-la assim que possível.