Премахване на следата по подразбиране

[ Част 1 | Част 2 | Част 3 ]

В първата публикация от тази серия показах анализа, който използвах, за да определя, че следата по подразбиране не е за нас. Докато разглеждах каква информация всъщност трябваше да съберем на нейно място (промени в размера на файла) и как това трябва да бъде изложено на потребителите, разгледах следните точки относно проследяването по подразбиране:

заснема само автоматично събития;
той не улавя партидата „виновник“, която е причинила събитието, освен ако нямате късмет, че е заснета и по друга причина (напр. DDL); и,
заснема събития, използвайки местно време (нашите сървъри са източни и се подчиняват на DST).

В своя защита той улавя много важна информация за тези автоматични събития. След като деактивираме проследяването по подразбиране, все пак може да искаме да прегледаме събития, които са се случили преди промяната и са били заснети в тези файлове. Но след като следата по подразбиране е деактивирана, редът вече не съществува в sys.traces , така че не можете да определите пътя към .trc файлове от там. Ето къде негъвкавостта на проследяването по подразбиране всъщност осигурява предимство:файловете са твърдо кодирани, за да се намират в същата папка като SERVERPROPERTY(N'ErrorLogFileName') . Така че, дори ако проследяването по подразбиране е деактивирано, ние все още можем да извлечем данни от файловете, като използваме следната заявка (с корекции за показване на данните в 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;

Примерни резултати от един сървър, където определено имаше някои ръчни и автоматични събития, които се случиха (щракнете, за да увеличите):

Написване на заместител

Сесията за разширени събития, която формулирах, за да заменя това, която също ще улови ръчни промени в размера на файла и текста на заявката, който е причинил автоматични събития, е както следва:

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;

Докато изглежда като username и server_principal_name може да е излишно, всъщност намерих случаи, в които последното беше NULL (и изглежда този проблем съществува от известно време).

Проверка на резултатите

Активирах тази сесия на 22 февруари, така че липсват събитията, които проследяването по подразбиране е заснело на 12-ти, но тя засне повече от единичното събитие за автоматично нарастване от 23-ти. Изпълних следната заявка, за да получа резултат със същата форма като по-горе:

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

Резултатите показват допълнителното забавление, което имах, включително (въздъхна!) стартиране на задача „Свиване на база данни“ от потребителския интерфейс (щракнете, за да увеличите):

Разгръщане навсякъде

Уверен, че сега мога да получа по-пълна картина на събитията за промяна на размера на файла на всеки сървър, беше време за внедряване. Използвах прозорец за заявка на CMS, за да деактивирам първо проследяването по подразбиране навсякъде и задам show advanced options обратно по начина, по който го намерих:

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

След това, за да създам сесията за разширено събитие, трябва да използвам динамичен SQL, тъй като някои сървъри може да имат различни пътища за SERVERPROPERTY(N'ErrorLogFileName') и този аргумент не може да бъде параметризиран.

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;

Доказателството е в пудинга

Създадох фалшиво работно натоварване, което умишлено беше натоварено с неща, които ще регистрират събития в проследяването по подразбиране, след което го стартирах няколко пъти със и без активирана проследяване по подразбиране, за да покажа, че ефектът на наблюдателя може да окаже влияние върху работното натоварване.

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

Средно време на изпълнение:

Проследяване по подразбиране	Средно време на натоварване
Активирано	147.4s
Деактивирано	131.6s

Намаляването на времето за изпълнение с 10-11% със сигурност не е огромно самостоятелно, но е голяма печалба, ако мислите за кумулативното въздействие върху цял флот от над 200 сървъра.

Какво следва?

Не правете това все още . Все още трябва да говорим за някои странични ефекти от деактивирането на проследяването по подразбиране и да създадем изгледи, така че потребителите да могат лесно да консумират данните за сесията, без да стават експерти по XQuery. Останете на линия!