Encontrando as querys mais demoradas do banco de dados

Encontrei um artigo interessante no iMasters e gostaria de compartilhar o mesmo no post.

Quem nunca quis 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?

Neste 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 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)
)	
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 em que ele 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:BatchCompletedtd>

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 STPCREATE_TRACE
AS
BEGIN
	DECLARE
		 @rc			int
		,@TraceID		int
		,@maxfilesize	bigint
		,@on			bit
		,@intfilter		bigint

	Set	 @on		  = 1
	Set  @maxfilesize = 50

	-- Criação do Trace
	EXEC @rc = SP_TRACE_CREATE @TraceID OUTPUT, 0, N'C:\Trace\Querys_Demoradas'

	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 @intfilter = 3000000 -- 3 segundos
	EXEC SP_TRACE_SETFILTER @TraceID, 13, 0, 4, @intfilter

	-- 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 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 você 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'

-- Interrompe o rastreamento especificado.
EXEC SP_TRACE_SETSTATUS @traceid = @Trace_Id, @status = 0 
--Fecha o rastreamento especificado e exclui sua definição do servidor.
EXEC SP_TRACE_SETSTATUS @traceid = @Trace_Id, @status = 2 

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:

Fonte: iMasters

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:

Fonte: iMasters

Step 3

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

EXEC STPCREATE_TRACE
[/sourcecoce]

No meu ambiente, esse <em>job</em> 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 <em>querys</em> mais demoradas.

No meu ambiente, identifico as <em>procedures</em> 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 <em>procedure </em>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.dbo.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:

Fonte: iMasters

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.

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, se você não possui uma rotina parecida com essa, tente implementá-la assim que possível.

Deixe uma Resposta

Preencha os seus detalhes abaixo ou clique num ícone para iniciar sessão:

Logótipo da WordPress.com

Está a comentar usando a sua conta WordPress.com Terminar Sessão / Alterar )

Imagem do Twitter

Está a comentar usando a sua conta Twitter Terminar Sessão / Alterar )

Facebook photo

Está a comentar usando a sua conta Facebook Terminar Sessão / Alterar )

Google+ photo

Está a comentar usando a sua conta Google+ Terminar Sessão / Alterar )

Connecting to %s