[ Del 1 | Del 2 | Del 3 ]
I det første indlæg i denne serie viste jeg den analyse, jeg brugte til at bestemme, at standardsporingen ikke er for os. Mens jeg så på, hvilke oplysninger vi faktisk havde brug for at indsamle i stedet for (ændringer i filstørrelsen), og hvordan dette skulle eksponeres for brugere, overvejede jeg følgende punkter om standardsporingen:
- den fanger kun automatisk begivenheder;
- den fanger ikke den "skyldige" batch, der forårsagede hændelsen, medmindre du er så heldig, at den også blev fanget af en anden årsag (f.eks. DDL); og,
- den fanger begivenheder ved hjælp af lokal tid (vores servere er østlige og adlyder sommertid).
Til sit forsvar indfanger den en masse vigtig information om disse automatiske hændelser. Efter at vi har deaktiveret standardsporingen, vil vi muligvis stadig gennemgå begivenheder, der skete før ændringen og blev fanget i disse filer. Men når standardsporingen er deaktiveret, eksisterer rækken ikke længere i sys.traces
, så du kan ikke bestemme stien til .trc
filer derfra. Det er her, hvor ufleksibel standardsporingen faktisk giver en fordel:filerne er hardkodet til at ligge i samme mappe som SERVERPROPERTY(N'ErrorLogFileName')
. Så selvom standardsporingen er deaktiveret, kan vi stadig trække data fra filerne ved hjælp af følgende forespørgsel (med justeringer for at vise dataene i 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;
Prøveresultater fra én server, hvor der helt sikkert var nogle manuelle og automatiske hændelser, der skete (klik for at forstørre):
Skriv en erstatning
Den udvidede begivenhedssession, jeg formulerede til at erstatte dette, som også ville fange manuelle filstørrelsesændringer og forespørgselsteksten, der forårsagede automatiske begivenheder, er som følger:
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;
Mens det ligner username
og server_principal_name
kan være overflødig, fandt jeg faktisk tilfælde, hvor sidstnævnte var NULL
(og det ser ud til, at dette problem har eksisteret i et stykke tid).
Tjekker resultaterne
Jeg aktiverede den session den 22. februar, så den mangler de hændelser, som standardsporet fangede den 12., men den fangede mere end den enkelte autovækstbegivenhed fra den 23. Jeg kørte følgende forespørgsel for at få et resultat af samme form som ovenfor:
;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;
Resultaterne viser den ekstra sjov, jeg havde, inklusive (gisp!) at køre en "Shrink Database"-opgave fra brugergrænsefladen (klik for at forstørre):
Implementer det overalt
Med tillid til, at jeg nu kunne få et mere komplet billede af filstørrelsesændringer på enhver server, var det tid til at implementere. Jeg brugte et CMS-forespørgselsvindue til først at deaktivere standardsporingen overalt og indstille show advanced options
tilbage som jeg fandt det:
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
Derefter, for at oprette den udvidede begivenhedssession, skal jeg bruge dynamisk SQL, fordi nogle servere kan have forskellige stier til SERVERPROPERTY(N'ErrorLogFileName')
og det argument kan ikke parametreres.
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;
Beviset er i buddingen
Jeg oprettede en falsk arbejdsbelastning, der med vilje var tung med ting, der kunne logge hændelser til standardsporingen, og kørte den derefter flere gange med og uden standardsporingen aktiveret for at vise, at observatøreffekt kan have en indvirkning på arbejdsbyrden.
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
Gennemsnitlig kørselstid:
Standardsporing | Gennemsnitlig arbejdsbelastningstid |
---|---|
Aktiveret | 147,4s |
Deaktiveret | 131,6s |
En reduktion af kørselstid på 10-11 % er bestemt ikke enorm isoleret set, men det er en stor gevinst, hvis du tænker på den kumulative effekt på tværs af en hel flåde på 200+ servere.
Hvad er det næste?
Gør ikke dette endnu . Vi skal stadig tale om nogle bivirkninger ved at deaktivere standardsporingen og oprette visninger, så brugerne nemt kan forbruge sessionsdataene uden at blive XQuery-eksperter. Følg med!
[ Del 1 | Del 2 | Del 3 ]