Usuwanie domyślnego śladu

[ Część 1 | Część 2 | Część 3 ]

W pierwszym poście z tej serii pokazałem analizę, której użyłem do ustalenia, że domyślny ślad nie jest dla nas. Patrząc na to, jakie informacje faktycznie musieliśmy zebrać w jego miejscu (zmiany rozmiaru pliku) i jak należy to ujawnić użytkownikom, rozważyłem następujące punkty dotyczące domyślnego śledzenia:

przechwytuje tylko automatycznie wydarzenia;
nie przechwytuje partii „winowajcy”, która spowodowała zdarzenie, chyba że masz szczęście, że została ona przechwycona również z innego powodu (np. DDL); oraz,
przechwytuje zdarzenia w czasie lokalnym (nasze serwery są wschodnie i przestrzegają czasu letniego).

W swojej obronie przechwytuje wiele ważnych informacji o tych automatycznych zdarzeniach. Po wyłączeniu śledzenia domyślnego możemy nadal chcieć przejrzeć zdarzenia, które miały miejsce przed zmianą i zostały przechwycone w tych plikach. Ale po wyłączeniu domyślnego śledzenia wiersz nie istnieje już w sys.traces , więc nie możesz określić ścieżki do pliku .trc pliki stamtąd. W tym miejscu brak elastyczności domyślnego śledzenia faktycznie zapewnia korzyści:pliki są zakodowane na stałe w tym samym folderze, co SERVERPROPERTY(N'ErrorLogFileName') . Tak więc, nawet jeśli domyślne śledzenie jest wyłączone, nadal możemy pobierać dane z plików za pomocą następującego zapytania (z korektami, aby wyświetlić dane w 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;

Przykładowe wyniki z jednego serwera, na którym na pewno miały miejsce zdarzenia ręczne i automatyczne (kliknij, aby powiększyć):

Pisanie zamiennika

Sesja Extended Events, którą sformułowałem, aby to zastąpić, która obejmowałaby również ręczne zmiany rozmiaru pliku i tekst zapytania, który powodował automatyczne zdarzenia, jest następująca:

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;

Podczas gdy wygląda jak username i server_principal_name może być zbędne, faktycznie znalazłem przypadki, w których ten ostatni był NULL (i wygląda na to, że ten problem istnieje już od jakiegoś czasu).

Sprawdzanie wyników

Włączyłem tę sesję 22 lutego, więc brakuje w niej zdarzeń, które domyślny ślad przechwycił 12 lutego, ale przechwycił więcej niż jedno zdarzenie autowzrostu z 23 lutego. Uruchomiłem następujące zapytanie, aby uzyskać wynik o takim samym kształcie jak powyżej:

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

Wyniki pokazują dodatkową zabawę, jaką miałem, w tym (wzdycha!) uruchamiając zadanie „Shrink Database” z interfejsu użytkownika (kliknij, aby powiększyć):

Wdrażaj wszędzie

Przekonany, że mogę teraz uzyskać pełniejszy obraz zdarzeń zmiany rozmiaru plików na dowolnym serwerze, nadszedł czas na wdrożenie. Użyłem okna zapytania CMS, aby najpierw wyłączyć domyślny ślad wszędzie i ustawić show advanced options z powrotem tak, jak go znalazłem:

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

Następnie, aby utworzyć sesję Extended Event, muszę użyć dynamicznego SQL, ponieważ niektóre serwery mogą mieć różne ścieżki dla SERVERPROPERTY(N'ErrorLogFileName') a ten argument nie może być sparametryzowany.

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;

Dowód jest w budyniu

Stworzyłem symulowane obciążenie, które było celowo obciążone rzeczami, które rejestrowałyby zdarzenia w domyślnym śledzeniu, a następnie uruchomiłem go wiele razy z włączonym domyślnym śledzeniem i bez niego, aby pokazać, że efekt obserwatora może mieć wpływ na obciążenie.

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

Średni czas pracy:

Ślad domyślny	Średni czas obciążenia
Włączone	147,4s
Wyłączone	131,6s

Skrócenie czasu pracy o 10-11% z pewnością nie jest ogromne w izolacji, ale jest to duża wygrana, jeśli pomyślimy o skumulowanym wpływie na całą flotę ponad 200 serwerów.

Co dalej?

Jeszcze tego nie rób . Nadal musimy mówić o pewnych efektach ubocznych wyłączenia śledzenia domyślnego i tworzyć widoki, aby użytkownicy mogli łatwo korzystać z danych sesji bez zostania ekspertem XQuery. Bądź na bieżąco!