{"id":293,"date":"2010-06-05T09:33:02","date_gmt":"2010-06-05T12:33:02","guid":{"rendered":"http:\/\/fabriciodba.wordpress.com\/2010\/06\/05\/passo-a-passo-para-encontrar-as-querys-mais-demoradas-do-banco-de-dados-parte-1"},"modified":"2016-09-11T18:10:52","modified_gmt":"2016-09-11T21:10:52","slug":"passo-a-passo-para-encontrar-as-querys-mais-demoradas-do-banco-de-dados-parte-1","status":"publish","type":"post","link":"https:\/\/fabriciolima.net\/blog\/2010\/06\/05\/passo-a-passo-para-encontrar-as-querys-mais-demoradas-do-banco-de-dados-parte-1\/","title":{"rendered":"Passo a passo para encontrar as querys mais demoradas do Banco de Dados – Parte 1"},"content":{"rendered":"
\n

Fala Pessoal,<\/p>\n

Quem n\u00e3o quer saber quais s\u00e3o as querys<\/em> mais demoradas do seu ambiente de Banco de Dados? Em quais hor\u00e1rios essas querys<\/em> rodam? Quem est\u00e1 executando? De onde est\u00e1 sendo rodada? Quais os recursos que essas querys<\/em> consomem?<\/p>\n

Nesse artigo, demonstrarei como eu fa\u00e7o esse acompanhamento no meu ambiente de trabalho. Ele \u00e9 v\u00e1lido para as vers\u00f5es 2005 e 2008 do SQL Server. Para a vers\u00e3o do SQL Server 2000, algumas colunas do trace<\/em> devem ser alteradas pois n\u00e3o existem no SQL 2000.<\/p>\n

Primeiramente, deve ser criada uma tabela para armazenar o log<\/em> das querys<\/em> mais demoradas que rodam no nosso banco de dados. Deve-se escolher a database<\/em> adequada do seu ambiente para armazenar essa tabela. Tamb\u00e9m criei um \u00edndice nessa tabela para efetuar as buscas pela data em que a query<\/em> rodou.<\/p>\n

\r\nCREATE TABLE dbo.Traces (\r\n    [TextData] VARCHAR(MAX) NULL,\r\n    [NTUserName] VARCHAR(128) NULL,\r\n    [HostName] VARCHAR(128) NULL,\r\n    [ApplicationName] VARCHAR(128) NULL,\r\n    [LoginName] VARCHAR(128) NULL,\r\n    [SPID] INT NULL,\r\n    [Duration] NUMERIC(15, 2) NULL,\r\n    [StartTime] DATETIME NULL,\r\n    [EndTime] DATETIME NULL,\r\n    [Reads] INT,\r\n    [Writes] INT,\r\n    [CPU] INT,\r\n    [ServerName] VARCHAR(128) NULL,\r\n    [DataBaseName] VARCHAR(128),\r\n    [RowCounts] INT,\r\n    [SessionLoginName] VARCHAR(128)\r\n)\r\n\r\n-- Para realizar as querys de busca pela data que a query rodou.    \r\nCREATE CLUSTERED INDEX [SK01_Traces] ON [Traces]([StartTime]) WITH(FILLFACTOR = 95)\r\n<\/pre>\n
Em seguida, criaremos uma procedure<\/em> para criar o arquivo de trace<\/em> que ficar\u00e1 rodando em backgroud<\/em> no servidor.<\/p>\n
Nessa procedure<\/em> \u00e9 criado um trace<\/em> com a procedure sp_trace_create,<\/em> onde especificamos o caminho que esse trace<\/em> ser\u00e1 armazenado. No meu caso criei uma pasta chamada Trace<\/em> no C:<\/em> do meu servidor. Voc\u00ea deve criar esse diret\u00f3rio antes de rodar o procedimento. Caso queria armazenar em um caminho diferente basta mudar o caminho na procedure<\/em>.<\/p>\n
Com a procedure sp_trace_setevent<\/em>, n\u00f3s definimos quais os eventos que nosso trace<\/em> pegar\u00e1. Neste caso, armazenaremos os eventos:<\/p>\n\n\n\n\n\n
Event Number<\/strong><\/td>\nEvent Name<\/strong><\/td>\nDescription<\/strong><\/td>\n<\/tr>\n
10<\/td>\nRPC:Completed<\/td>\nOccurs when a remote procedure call (RPC) has completed.<\/td>\n<\/tr>\n
12<\/td>\nSQL:BatchCompleted<\/td>\nOccurs when a Transact-SQL batch has completed.<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n
Ap\u00f3s selecionarmos os eventos, devemos escolher as colunas que desejamos visualizar. As colunas que utilizo no meu ambiente s\u00e3o as seguintes:<\/p>\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n
Column Number<\/strong><\/td>\nColumn Name<\/strong><\/td>\nDescription<\/strong><\/td>\n<\/tr>\n
1<\/td>\nTextData<\/td>\nText value dependent on the event class that is captured in the trace.<\/td>\n<\/tr>\n
6<\/td>\nNTUserName<\/td>\nMicrosoft Windows user name.<\/td>\n<\/tr>\n
8<\/td>\nHostName<\/td>\nName of the client computer that originated the request.<\/td>\n<\/tr>\n
10<\/td>\nApplicationName<\/td>\nName 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.<\/td>\n<\/tr>\n
11<\/td>\nLoginName<\/td>\nSQL Server login name of the client.<\/td>\n<\/tr>\n
12<\/td>\nSPID<\/td>\nServer Process ID assigned by SQL Server to the process associated with the client.<\/td>\n<\/tr>\n
13<\/td>\nDuration<\/td>\nAmount of elapsed time (in milliseconds) taken by the event. This data column is not populated by the Hash Warning event.<\/td>\n<\/tr>\n
14<\/td>\nStartTime<\/td>\nTime at which the event started, when available.<\/td>\n<\/tr>\n
15<\/td>\nEndTime<\/td>\nTime 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.<\/td>\n<\/tr>\n
16<\/td>\nReads<\/td>\nNumber of logical disk reads performed by the server on behalf of the event. This column is not populated by the Lock:Released event.<\/td>\n<\/tr>\n
17<\/td>\nWrites<\/td>\nNumber of physical disk writes performed by the server on behalf of the event.<\/td>\n<\/tr>\n
18<\/td>\nCPU<\/td>\nAmount of CPU time (in milliseconds) used by the event.<\/td>\n<\/tr>\n
26<\/td>\nServerName<\/td>\nName of the instance of SQL Server (either servername or servername\\instancename) being traced.<\/td>\n<\/tr>\n
35<\/td>\nDatabaseName<\/td>\nName of the database specified in the USE database statement.<\/td>\n<\/tr>\n
40<\/td>\nDBUserName<\/td>\nSQL Server database username of the client.<\/td>\n<\/tr>\n
48<\/td>\nRowCounts<\/td>\nNumber of rows in the batch.<\/td>\n<\/tr>\n
64<\/td>\nSessionLoginName<\/td>\nThe 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.<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n
A lista completa com todos os eventos pode ser encontrada no books online<\/em> pesquisando pela procedure sp_trace_setevent<\/em>.<\/p>\n
Em seguida \u00e9 realizado o filtro na coluna 13(Duration<\/em>) para retornar apenas os valores maiores ou iguais a 3 segundos. Segue abaixo o script<\/em> dessa procedure.<\/p>\n
\r\nCREATE PROCEDURE [dbo].[stpCreate_Trace]\r\nAS\r\nBEGIN\r\n    DECLARE @rc INT, @TraceID INT, @maxfilesize BIGINT, @on BIT, @intfilter INT, @bigintfilter BIGINT\r\n    SELECT @on = 1, @maxfilesize = 50\r\n    \r\n    -- Cria\u00e7\u00e3o do trace\r\n    EXEC @rc = [dbo].[sp_trace_create] @TraceID OUTPUT, 0, N'C:\\Trace\\Querys_Demoradas', @maxfilesize, NULL\r\n    \r\n    IF (@rc != 0) GOTO error\r\n    \r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 1,  @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 6,  @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 8,  @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 10, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 11, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 12, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 13, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 14, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 15, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 16, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 17, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 18, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 26, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 35, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 40, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 48, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 10, 64, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 1,  @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 6,  @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 8,  @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 10, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 11, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 12, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 13, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 14, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 15, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 16, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 17, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 18, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 26, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 35, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 40, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 48, @on\r\n    EXEC [dbo].[sp_trace_setevent] @TraceID, 12, 64, @on\r\n    \r\n    SET @bigintfilter = 3000000 -- 3 segundos\r\n    \r\n    EXEC [dbo].[sp_trace_setfilter] @TraceID, 13, 0, 4, @bigintfilter\r\n    \r\n    -- Set the trace status to start\r\n    EXEC [dbo].[sp_trace_setstatus] @TraceID, 1\r\n    \r\n    GOTO finish\r\n    \r\n    error:\r\n\t\tSELECT ErrorCode = @rc\r\n    finish:\r\nEND\r\n<\/pre>\n
No meu principal servidor de produ\u00e7\u00e3o, utilizo 3 segundos para realizar o filtro, mas isso depende da realidade de cada ambiente. Por exemplo, antigamente eram logadas as querys<\/em> que demoravam mais de 10 segundos no meu ambiente, depois da migra\u00e7\u00e3o para o SQL Server 2005 e da aquisi\u00e7\u00e3o de um storage<\/em> baixamos para 5 segundos. H\u00e1 pouco tempo, depois de melhorar as querys<\/em> mais demoradas e as que mais consumiam recursos, ap\u00f3s a altera\u00e7\u00e3o, cria\u00e7\u00e3o e exclus\u00e3o de muitos indices (tudo isso com a ajuda das salvadoras dmvs<\/em> presentes a partir do SQL Server 2005), como s\u00f3 estavam sendo retornadas 30 querys<\/em> por hora em m\u00e9dia, baixei o trace<\/em> para 3 segundos para melhor identificar poss\u00edveis gargalos. O tuning<\/em> continua, para que eu tenha cada vez menos registros demorando mais de 3 segundos.<\/p>\n
Agora vamos rodar nossa procedure<\/em> para criar o trace<\/em>.<\/p>\n
\r\nEXEC [dbo].[stpCreate_Trace]\r\n<\/pre>\n
Para conferir o trace<\/em> criado, basta executar a query abaixo.<\/p>\n
\r\nSELECT *\r\nFROM :: fn_trace_getinfo(default)\r\nWHERE CAST([value] AS VARCHAR(50)) = 'C:\\Trace\\Querys_Demoradas.trc'\r\n<\/pre>\n
Depois de criado, vamos rodar algumas querys<\/em> para testar o nosso trace.<\/p>\n
\r\nWAITFOR DELAY '00:00:04'\r\n\r\nGO\r\nCREATE PROCEDURE [dbo].[stpTeste_Trace1]\r\nAS\r\nBEGIN\r\n    WAITFOR DELAY '00:00:04'\r\nEND\r\n\r\nGO\r\nEXEC [dbo].[stpTeste_Trace1]\r\n\r\n-- Conferindo todos os dados que foram armazenados no trace.\r\nSELECT\t[Textdata], [NTUserName], [HostName], [ApplicationName], [LoginName], [SPID], CAST([Duration] \/ 1000\/ 1000.00 AS NUMERIC(15, 2)) [Duration],\r\n\t\t[Starttime], [EndTime], [Reads],[writes], [CPU], [Servername], [DatabaseName], [rowcounts], [SessionLoginName]\r\nFROM :: fn_trace_gettable('C:\\Trace\\Querys_Demoradas.trc', default)\r\nWHERE [Duration] IS NOT NULL\r\nORDER BY [Starttime]\r\n<\/pre>\n
Segue abaixo o resultado da query<\/em> com os dados armazenados no trace<\/em>.<\/p>\n
\"Resultado<\/a><\/p>\n
A coluna TextData<\/em> retorna exatamente a query<\/em> que voc\u00ea rodou e demorou mais de 3 segundos. Esse tempo pode ser conferido na coluna Duration<\/em>, Starttime<\/em> e Endtime<\/em>. Outras 3 colunas que me ajudam muito s\u00e3o as colunas Reads<\/em>, Writes<\/em> e CPU<\/em> que mostram os recursos que uma determinada query<\/em> est\u00e1 consumindo.<\/p>\n
Este artigo continua em Passo a passo para encontrar as querys mais demoradas do Banco de Dados – Parte 2<\/a>.<\/p>\n
Gostou dessa dica?<\/b><\/p>\n
Cadastre seu e-mail para receber novos Posts e curta minha P\u00e1gina no Facebook<\/a> para receber Dicas de Leituras e Eventos sobre SQL Server.<\/p>\n
Aprenda a criar essa e outras rotinas para administrar melhor seu SQL Server no meu Treinamento de Tarefas do Dia a Dia de um DBA<\/a>.<\/p>\n
Abra\u00e7os,<\/p>\n
Fabr\u00edcio Lima<\/p>\n
MCITP \u2013 Database Administrator<\/p>\n
Consultor e Instrutor SQL Server<\/p>\n
Trabalha com SQL Server desde 2006\n<\/p><\/div>\n","protected":false},"excerpt":{"rendered":"
Fala Pessoal, Quem n\u00e3o quer saber quais s\u00e3o as querys mais demoradas do seu ambiente de Banco de Dados? Em quais hor\u00e1rios essas querys rodam? Quem est\u00e1 executando? De onde est\u00e1 sendo rodada? Quais os recursos que essas querys consomem? Nesse artigo, demonstrarei como eu fa\u00e7o esse acompanhamento no meu ambiente de trabalho. Ele \u00e9 […]<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_exactmetrics_skip_tracking":false,"_exactmetrics_sitenote_active":false,"_exactmetrics_sitenote_note":"","_exactmetrics_sitenote_category":0,"footnotes":""},"categories":[3,280],"tags":[18,23,26,65,63,48,66,31,64,49,33,50,34,35,67,40],"class_list":["post-293","post","type-post","status-publish","format-standard","hentry","category-administracao-de-bd","category-virtual-pass-br","tag-checklist","tag-dba","tag-excel","tag-lentidao","tag-performance","tag-planilha","tag-problema","tag-profile","tag-query-lenta","tag-sql","tag-sql-server","tag-sql-server-2005","tag-sql-server-2008","tag-sql-server-2008-r2","tag-sql-server-passo-a-passo","tag-tuning"],"post_mailing_queue_ids":[],"_links":{"self":[{"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/posts\/293","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/comments?post=293"}],"version-history":[{"count":0,"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/posts\/293\/revisions"}],"wp:attachment":[{"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/media?parent=293"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/categories?post=293"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/fabriciolima.net\/blog\/wp-json\/wp\/v2\/tags?post=293"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}