[ Parte 1 | Parte 2 | Parte 3]
No primeiro post desta série, mostrei a análise que usei para determinar que o rastreamento padrão não é para nós. Ao analisar quais informações realmente precisávamos coletar em seu lugar (alterações no tamanho do arquivo) e como isso deveria ser exposto aos usuários, considerei os seguintes pontos sobre o rastreamento padrão:
- ele captura apenas automático eventos;
- não captura o lote "culpado" que causou o evento, a menos que você tenha a sorte de também ter sido capturado por outro motivo (por exemplo, DDL); e,
- ele captura eventos usando o horário local (nossos servidores são orientais e obedecem ao horário de verão).
Em sua defesa, ele captura muitas informações importantes sobre esses eventos automáticos. Depois de desabilitarmos o rastreamento padrão, ainda podemos querer revisar os eventos que aconteceram antes da alteração e foram capturados nesses arquivos. Mas uma vez que o rastreamento padrão é desabilitado, a linha não existe mais em
sys.traces
, então você não pode determinar o caminho para o .trc
arquivos de lá. Aqui é onde a inflexibilidade do rastreamento padrão realmente oferece um benefício:os arquivos são codificados para residir na mesma pasta que SERVERPROPERTY(N'ErrorLogFileName')
. Portanto, mesmo que o rastreamento padrão esteja desabilitado, ainda podemos extrair dados dos arquivos usando a seguinte consulta (com ajustes para mostrar os dados em UTC):;WITH dst AS ( SELECT s,e,d FROM (VALUES ('20190310','20191103',240),('20191103','20200308',300), ('20200308','20201101',240),('20201101','20210314',300), ('20210314','20211107',240)) AS dst(s,e,d) ), -- will add 2022, 2023, etc. later (if DST is still a thing then) p AS ( SELECT TracePath = REVERSE(SUBSTRING(p, CHARINDEX(N'\', p), 260)) + N'log.trc' FROM (SELECT REVERSE((CONVERT(nvarchar(max), SERVERPROPERTY(N'ErrorLogFileName'))))) AS s(p) ), trc AS ( SELECT src = 'trc', t.DatabaseName, t.[FileName], DurationSeconds = CONVERT(decimal(18,3),Duration/1000000.0), StartTimeUTC = DATEADD(MINUTE, COALESCE(st1.d,0), t.StartTime), EndTimeUTC = DATEADD(MINUTE, COALESCE(st2.d,0), t.EndTime), FileType = CASE t.EventClass WHEN 92 THEN 'Data' WHEN 93 THEN 'Log' END, Culprit = TextData, IsAutomatic = 'true', ChangeMB = CONVERT(bigint, IntegerData)*8/1024, Principal = t.LoginName, t.HostName, App = CASE WHEN ApplicationName LIKE N'%Management Studio%Query%' THEN N'SSMS - Query Window' WHEN ApplicationName LIKE N'%Management Studio%' THEN N'SSMS - GUI!' ELSE ApplicationName END FROM p CROSS APPLY sys.fn_trace_gettable(p.TracePath, DEFAULT) AS t LEFT OUTER JOIN dst AS st1 ON t.StartTime >= DATEADD(HOUR,2,st1.s) AND t.StartTime < DATEADD(HOUR,2,st1.e) LEFT OUTER JOIN dst AS st2 ON t.EndTime >= DATEADD(HOUR,2,st2.s) AND t.EndTime < DATEADD(HOUR,2,st2.e) WHERE t.EventClass IN (92,93) ) SELECT * FROM trc ORDER BY StartTimeUTC DESC;
Resultados da amostra de um servidor, onde definitivamente ocorreram alguns eventos manuais e automáticos (clique para ampliar):
Escrevendo uma substituição
A sessão Extended Events que formulei para substituir isso, que também capturaria as alterações manuais no tamanho do arquivo e o texto da consulta que causou eventos automáticos, é a seguinte:
CREATE EVENT SESSION FileSizeChanges ON SERVER ADD EVENT sqlserver.database_file_size_change ( ACTION ( sqlserver.sql_text, sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.username, sqlserver.server_principal_name ) ) ADD TARGET package0.event_file ( SET filename = N'W:\SomePath\FileSizeChanges.xel', MAX_FILE_SIZE = 100, -- MB MAX_ROLLOVER_FILES = 100 -- 100 MB x 100 = max 10 GB ) WITH ( MAX_MEMORY = 8192 KB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS, MAX_DISPATCH_LATENCY = 30 SECONDS, MAX_EVENT_SIZE = 0 KB, TRACK_CAUSALITY = OFF, STARTUP_STATE = ON ); ALTER EVENT SESSION FileSizeChanges ON SERVER STATE = START;
Embora pareça com
username
e server_principal_name
pode ser redundante, na verdade encontrei casos em que o último era NULL
(e parece que esse problema já existe há algum tempo). Verificando os resultados
Eu habilitei essa sessão em 22 de fevereiro, então está faltando os eventos que o rastreamento padrão capturou no dia 12, mas ele capturou mais do que o único evento de autogrowth do dia 23. Eu executei a seguinte consulta para obter um resultado da mesma forma acima:
;WITH FileInfo(XEPath) AS ( SELECT LEFT(BasePath,COALESCE(NULLIF(CHARINDEX(SessionName,BasePath)-1,-1),0)) + SessionName + N'*.xel' FROM ( SELECT xmlsrc.data.value(N'(@name)[1]', N'nvarchar(max)'), SessionName FROM ( SELECT CONVERT(xml,target_data), s.[name] FROM sys.dm_xe_session_targets AS t INNER JOIN sys.dm_xe_sessions AS s ON s.[address] = t.event_session_address WHERE s.[name] = N'FileSizeChanges' ) AS xefile (TargetData, SessionName) CROSS APPLY TargetData.nodes(N'//EventFileTarget/File') AS xmlsrc(data) ) AS InnerData(BasePath, SessionName) ), SessionData(EventData) AS ( SELECT CONVERT(xml, TargetData.event_data) FROM FileInfo CROSS APPLY sys.fn_xe_file_target_read_file(FileInfo.XEPath, NULL, NULL, NULL) AS TargetData ), src AS ( SELECT EndTimeUTC = x.d.value(N'(@timestamp)[1]', N'datetime2'), DatabaseID = x.d.value(N'(data [@name="database_id"]/value)[1]', N'int'), [FileName] = x.d.value(N'(data [@name="file_name"]/value)[1]', N'sysname'), Duration = x.d.value(N'(data [@name="duration"]/value)[1]', N'int'), FileType = x.d.value(N'(data [@name="file_type"]/text)[1]', N'varchar(4)'), Culprit = x.d.value(N'(action[@name="sql_text"]/value)[1]', N'nvarchar(max)'), IsAutomatic = x.d.value(N'(data [@name="is_automatic"]/value)[1]', N'varchar(5)'), ChangeKB = x.d.value(N'(data [@name="size_change_kb"]/value)[1]', N'bigint'), Principal = x.d.value(N'(action[@name="server_principal_name"]/value)[1]', N'sysname'), username = x.d.value(N'(action[@name="username"]/value)[1]', N'sysname'), AppName = x.d.value(N'(action[@name="client_app_name"]/value)[1]', N'sysname'), HostName = x.d.value(N'(action[@name="client_hostname"]/value)[1]', N'sysname') FROM SessionData CROSS APPLY EventData.nodes(N'/event') AS x(d) ) SELECT src = 'xe', DatabaseName = DB_NAME(DatabaseID), [FileName], DurationSeconds = CONVERT(decimal(18,3), Duration/1000000.0), StartTimeUTC = DATEADD(MICROSECOND, -Duration, EndTimeUTC), EndTimeUTC, FileType, Culprit, IsAutomatic, ChangeMB = CONVERT(decimal(18,3), ChangeKB / 1024.0), Principal = COALESCE([Principal], COALESCE(NULLIF(username,N''), N'?')), HostName, App = CASE WHEN AppName LIKE N'%Management Studio%Query%' THEN N'SSMS - Query Window' WHEN AppName LIKE N'%Management Studio%' THEN N'SSMS - GUI!' ELSE AppName END FROM src ORDER BY StartTimeUTC DESC;
Os resultados mostram a diversão adicional que tive, incluindo (suspiro!) executar uma tarefa "Encolher Banco de Dados" a partir da interface do usuário (clique para ampliar):
Implantando em todos os lugares
Confiante de que agora eu poderia obter uma visão mais completa dos eventos de alteração de tamanho de arquivo em qualquer servidor, era hora de implantar. Usei uma janela de consulta do CMS para primeiro desabilitar o rastreamento padrão em todos os lugares e definir as opções
show advanced options
de volta do jeito que eu encontrei:IF EXISTS ( SELECT 1 FROM sys.configurations WHERE name = N'default trace enabled' AND value_in_use = 1 ) BEGIN DECLARE @OriginalAdvancedOptions bit = ( SELECT CONVERT(bit, value_in_use) FROM sys.configurations WHERE name = N'show advanced options' ); IF @OriginalAdvancedOptions = 0 -- need to turn this on if it's not already BEGIN EXEC sys.sp_configure @configname = N'show advanced options', @configvalue = 1; RECONFIGURE WITH OVERRIDE; END EXEC sys.sp_configure @configname = N'default trace enabled', @configvalue = 0; IF @OriginalAdvancedOptions = 0 -- need to set it back (else leave it) BEGIN EXEC sys.sp_configure @configname = N'show advanced options', @configvalue = 0; END RECONFIGURE WITH OVERRIDE; END GO
Então, para criar a sessão Extended Event, preciso usar SQL dinâmico, pois alguns servidores podem ter caminhos diferentes para
SERVERPROPERTY(N'ErrorLogFileName')
e esse argumento não pode ser parametrizado. DECLARE @path nvarchar(max) = (SELECT REVERSE(SUBSTRING(p, CHARINDEX(N'\', p), 4000)) FROM (SELECT REVERSE((CONVERT(nvarchar(max), SERVERPROPERTY(N'ErrorLogFileName'))))) AS s(p)); IF EXISTS (SELECT 1 FROM sys.dm_xe_sessions WHERE name = N'FileSizeChanges') BEGIN EXEC sys.sp_executesql N'DROP EVENT SESSION FileSizeChanges ON SERVER;'; END DECLARE @sql nvarchar(max) = N' CREATE EVENT SESSION FileSizeChanges ON SERVER ADD EVENT sqlserver.database_file_size_change ( ACTION ( sqlserver.sql_text, sqlserver.client_app_name, sqlserver.client_hostname, sqlserver.username, sqlserver.server_principal_name ) ) ADD TARGET package0.event_file ( SET filename = ''' + @path + N'FileSizeChanges.xel'', MAX_FILE_SIZE = 100, -- MB MAX_ROLLOVER_FILES = 100 -- 100 MB x 100 = max 10 GB ) WITH ( MAX_MEMORY = 8192 KB, EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS, MAX_DISPATCH_LATENCY = 30 SECONDS, MAX_EVENT_SIZE = 0 KB, TRACK_CAUSALITY = OFF, STARTUP_STATE = ON ); ALTER EVENT SESSION FileSizeChanges ON SERVER STATE = START;'; EXEC sys.sp_executesql @sql;
A prova está no pudim
Criei uma carga de trabalho simulada que era intencionalmente pesada com coisas que registrariam eventos no rastreamento padrão e a executei várias vezes com e sem o rastreamento padrão habilitado, para mostrar que o efeito do observador pode ter um impacto na carga de trabalho.
SELECT [starting] = sysdatetime(); GO EXEC sys.sp_executesql N'CREATE OR ALTER PROCEDURE dbo.dostuff AS BEGIN SET NOCOUNT ON; SELECT DISTINCT TOP (1000) object_id, column_id INTO #blat FROM sys.all_columns; ALTER TABLE #blat ADD CONSTRAINT PK_wahoo PRIMARY KEY (object_id, column_id); ALTER TABLE #blat ADD CONSTRAINT DF_what DEFAULT(1) FOR object_id; CREATE INDEX IX_what ON #blat(column_id); DROP TABLE #blat; END'; EXEC dbo.dostuff; CREATE USER smidgen WITHOUT LOGIN; ALTER ROLE db_owner ADD MEMBER smidgen; DBCC TRACEON(2861) WITH NO_INFOMSGS; DBCC TRACEOFF(2861) WITH NO_INFOMSGS; DROP USER smidgen; GO 5000 SELECT [finished] = sysdatetime(); GO
Duração média:
Rastreamento padrão | Tempo médio de carga de trabalho |
---|---|
Ativado | 147,4s |
Desativado | 131,6s |
Uma redução de tempo de execução de 10 a 11% certamente não é enorme isoladamente, mas é uma grande vitória se você pensar no impacto cumulativo em uma frota inteira de mais de 200 servidores.
O que vem a seguir?
Não faça isso ainda . Ainda temos que falar sobre alguns efeitos colaterais de desabilitar o rastreamento padrão e criar visualizações para que os usuários possam consumir facilmente os dados da sessão sem se tornarem especialistas em XQuery. Fique atento!
[ Parte 1 | Parte 2 | Parte 3]