Odstranění výchozího trasování

[ Část 1 | Část 2 | Část 3 ]

V prvním příspěvku v této sérii jsem ukázal analýzu, kterou jsem použil k určení, že výchozí trasování není pro nás. Při zkoumání toho, jaké informace jsme vlastně potřebovali shromáždit na jejich místě (změna velikosti souboru) a jak by to mělo být vystaveno uživatelům, jsem zvážil následující body o výchozím trasování:

zaznamenává pouze automaticky Události;
nezachycuje dávku „viníka“, která událost způsobila, pokud nemáte to štěstí, že byla zachycena také z jiného důvodu (např. DDL); a,
zachycuje události pomocí místního času (naše servery jsou východní a poslouchají DST).

Na svou obranu zachycuje spoustu důležitých informací o těchto automatických událostech. Poté, co deaktivujeme výchozí trasování, můžeme stále chtít zkontrolovat události, které se staly před změnou a byly zachyceny v těchto souborech. Jakmile je však výchozí trasování zakázáno, řádek již v sys.traces neexistuje , takže nemůžete určit cestu k .trc soubory odtud. Zde je nepružnost výchozího trasování ve skutečnosti výhodou:soubory jsou pevně zakódovány tak, aby byly umístěny ve stejné složce jako SERVERPROPERTY(N'ErrorLogFileName') . Takže i když je výchozí trasování zakázáno, stále můžeme získávat data ze souborů pomocí následujícího dotazu (s úpravami pro zobrazení dat v 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;

Ukázkové výsledky z jednoho serveru, kde se určitě vyskytly nějaké manuální a automatické události (klikněte pro zvětšení):

Napsání náhrady

Relace Extended Events, kterou jsem vytvořil, abych to nahradila a která by také zachytila ruční změny velikosti souboru a text dotazu, který způsobil automatické události, je následující:

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;

I když to vypadá jako username a server_principal_name může být nadbytečné, ve skutečnosti jsem našel případy, kdy druhý byl NULL (a zdá se, že tento problém již nějakou dobu přetrvává).

Kontrola výsledků

Tuto relaci jsem povolil 22. února, takže chybí události, které výchozí trasování zachytilo 12. dne, ale zachytilo více než jediná událost automatického růstu z 23. Spustil jsem následující dotaz, abych získal výsledek stejného tvaru jako výše:

;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;

Výsledky ukazují další zábavu, kterou jsem si užil, včetně (zalapání po dechu!) spuštění úlohy „Shrink Database“ z uživatelského rozhraní (kliknutím zvětšíte):

Nasazení všude

S jistotou, že nyní mohu získat úplnější obrázek o událostech změny velikosti souborů na libovolném serveru, nastal čas nasazení. Použil jsem okno dotazu CMS, abych nejprve všude zakázal výchozí trasování a nastavil show advanced options zpět tak, jak jsem to našel:

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

Poté, abych vytvořil relaci Extended Event, musím použít dynamické SQL, protože některé servery mohou mít různé cesty pro SERVERPROPERTY(N'ErrorLogFileName') a tento argument nelze parametrizovat.

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;

Důkaz je v pudinku

Vytvořil jsem simulovanou pracovní zátěž, která byla záměrně obtížná věcmi, které by protokolovaly události do výchozího trasování, a pak jsem ji několikrát spustil s povoleným výchozím trasováním i bez něj, abych ukázal, že efekt pozorovatele může mít dopad na zátěž.

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

Průměrná doba běhu:

Výchozí trasování	Průměrná doba zátěže
Povoleno	147,4 s
Zakázáno	131,6 s

Snížení doby běhu o 10–11 % jistě není samo o sobě obrovské, ale je to velká výhra, pokud se zamyslíte nad kumulativním dopadem na celou flotilu více než 200 serverů.

Co bude dál?