Raport Schema Changes History i default trace w SQL Server

Szeroko pojęte operacje DDL (Data Definition Language) w SQL Server czyli wszelkiego rodzaju CREATE, DROP, ALTER powinny być używane z rozwagą szczególnie jeśli chodzi o serwery produkcyjne. Stwierdzenie to jest oczywiste dla niemal każdego, a ja przytoczyłem go ze względu na tematykę niniejszego artykułu, którym jest wbudowany w SSMS raport Schema Changes Hsitory pozwalający nam w przystępny sposób dostrzec co, gdzie i kiedy zostało wykonane na naszym serwerze. Przyjmy się nie tylko samemu raportowi ale również mechanizmowi na którym on bazuje.

Na samym wstępie powiedzmy sobie gdzie w ogóle wspomniany raport możemy znaleźć. Rzekłbym w standardowym miejscu tj. wystarczy kliknąć prawym przyciskiem myszy na serwer i tam z menu kontekstowego wybrać Reports -> Standard Reports -> Schema Changes History:

Po wykonaniu tej sekwencji kroków powinniśmy zobaczyć prosty raport przedstawiający szereg zmian wykonanych na obiektach znajdujących się na wskazanym przez nas serwerze. Zanim wyświetlimy sam raport wykonajmy kilka testowych zmian. Do tego celu przygotowałem prosty skrypt, który ma za zadanie wykonać następujące cztery czynności:

stworzyć bazę danych testSCH,
stworzyć pięć tabel testowych,
do każdego tabeli testowej dodać kolumnę name o typie nvarchar(20),
usunąć stworzone tabele.

Pomiędzy operacjami w pętli mamy dwie sekundy odstępu tak aby poszczególne operacje nie nachodziły na siebie czasowo (ogólnie zabieg ten zastosowałem w celach estetycznych aby na raporcie było widać wyraźną sekwencję kroków):

USE master
GO

DROP DATABASE IF EXISTS testSCH
GO

CREATE DATABASE testSCH
GO

USE testSCH
GO

DECLARE @Counter INT =1
DECLARE @Limit INT=3
DECLARE @SqlCreateStatement VARCHAR(255)='CREATE TABLE dbo.test'+CAST(@Counter AS CHAR(1)) +'( id int)'
DECLARE @SqlAlterStatement VARCHAR(255)='ALTER TABLE dbo.test'+CAST(@Counter AS CHAR(1)) +' ADD name nvarchar(20)'
DECLARE @SqlDropStatement VARCHAR(255)='DROP TABLE dbo.test'+CAST(@Counter AS CHAR(1))


WHILE @Counter<=@Limit
BEGIN

	EXEC(@SqlCreateStatement)
	EXEC(@SqlAlterStatement)
	EXEC(@SqlDropStatement)


	SET @Counter=@Counter+1;
	SET @SqlCreateStatement ='CREATE TABLE dbo.test'+CAST(@Counter AS CHAR(1)) +'( id int)'
	SET @SqlAlterStatement ='ALTER TABLE dbo.test'+CAST(@Counter AS CHAR(1)) +' ADD name nvarchar(20)'
	SET @SqlDropStatement ='DROP TABLE dbo.test'+CAST(@Counter AS CHAR(1))

	WAITFOR DELAY '00:00:02'
	
END

Skrypt ten powinien wygenerować tyle operacji, że powinniśmy mieć możliwość zaobserwowania tychże zmian na naszym raporcie i tak też w istocie jest:

Jak możecie zauważyć na powyższym zrzucie ekranowym raport przedstawia nam następujące informacje:

Database Name – nazwę bazy danych, której operacja dotyczy,
Object Name – nazwę obiektu w bazie, którego operacja dotyczy (chyba, że operacja dotyczy całej bazy wtedy to pole pozostanie puste),
Type – typ obiektu, którego operacja dotyczy
DDL Operation – rodzaj operacji czyli DROP/ALTER/CREATE,
Time – data i czas kiedy operacja została wykonana,
Login Name – nazwa użytkownika, który wykonał operację.

Nie są to bardzo szczegółowe operacje ale z całą pewnością w wielu przypadkach okażą się pomocne. Jeśli ktoś usunął jakiś obiekt to gdzie zacząć szukać? No właśnie ten raport jest dobrym kandydatem na punkt startowy naszych poszukiwań. W tym miejscu może się pojawić pytanie jak to wszystko działa i jaki mechanizm stoi za tym raportem? Odpowiedź nie powinna nikogo zaskoczyć i jest to nic innego jak tzw. Default trace. Jest to mechanizm będący w SQL Server od bardzo dawna i polega on na śledzeniu określonych wydarzeń i ich rejestracji. Oczywiście nie wszystko i nie na zawsze jest rejestrowane. Trace ten składa się z pięciu plików z limitem wielkości 20MB o czym możemy dowiedzieć się odpytując sys.traces:

Po osiągnięciu progu wielkości dane zapisywane są ponownie w najstarszym pliku, nadpisując tym samym najstarsze dane (kolumna is_rollover=1). Jeśli chcemy mieć pewność, że dane będą gdzieś zachowane do późniejszej analizy to możemy je odkładać w dedykowanym miejscu bądź też np. archiwizować fizyczne pliki, ale to jest temat na zupełnie inny artykuł. Wracając do tematu to jedyną kontrolę jaką mamy nad tym mechanizmem to możemy go włączyć lub wyłączyć używając poniższej komendy konfiguracyjnej:

EXEC sp_configure 'show advanced options', 1;
EXEC sp_configure 'default trace enabled', 1;
RECONFIGURE WITH OVERRIDE;

W default trace znajdują się nie tylko dane, które widzimy na omawianym raporcie. Oczywistym jest również fakt, że nie cała aktywność jest rejestrowana, a jedynie wybrane zdarzenia. Aby poznać całą listę rejestrowanych zdarzeń musimy wykonać poniższe zapytanie:

SELECT 
	 tcat.name AS EventCategory
    ,te.name AS EventDescription
    ,tc.name AS Column
FROM 
	fn_trace_geteventinfo(1) AS ftg
INNER JOIN 
	sys.trace_events AS te
	ON ftg.eventid = te.trace_event_id
INNER JOIN 
	sys.trace_columns AS tc
	ON ftg.columnid = tc.trace_column_id
INNER JOIN 
	sys.trace_categories AS tcat
	ON te.category_id = tcat.category_id
ORDER BY 1,2,3

W rezultacie otrzymamy ponad 34 różnego rodzaju zdarzenia podzielone na siedem grup:

Database:

Data File Auto Grow
Data File Auto Shrink
Database Mirroring State Change
Log File Auto Grow
Log File Auto Shrink

Errors and Warnings:

ErrorLog
Hash Warning
Missing Column Statistics
Missing Join Predicate
Sort Warnings

Full text:

FT:Crawl Started
Full text FT:Crawl Stopped

Objects:

Object:Altered
Object:Created
Object:Deleted

Performance:

Plan Guide Unsuccessful

Security Audit:

Audit Add DB User Event
Audit Add Login to Server Role Event
Audit Add Member to DB Role Event
Audit Add Role Event
Audit Addlogin Event
Audit Backup/Restore Event
Audit Change Audit Event
Audit Change Database Owner
Audit Database Scope GDR Event
Audit DBCC Event
Audit Login Change Property Event
Audit Login Failed
Audit Login GDR Event
Audit Schema Object GDR Event
Audit Schema Object Take Ownership Event
Audit Server Alter Trace Event
Audit Server Starts And Stops

Server:

Server Memory Change

Z każdym z tych zdarzeń powiązane są określone włąściwości jak np. czas czy nazwa użytkownika. Patrząc na tą listę możemy się domyślać, które zdarzenia są wyświetlane na raporcie Schema History Changes i są to zdarzenia z grupy Objects. Możemy to bardzo łatwo zweryfikować próbując wychwycić jakie zapytanie jest wykonywane gdy uruchomimy raport:

exec sp_executesql @stmt=N'begin try
declare @enable int
select top 1 @enable = convert(int,value_in_use) from sys.configurations where name = ''default trace enabled''
if @enable = 1 --default trace is enabled
begin 
        declare @d1 datetime;
        declare @diff int;
        declare @curr_tracefilename varchar(500); 
        declare @base_tracefilename varchar(500); 
        declare @indx int ;
        declare @temp_trace table (
                obj_name nvarchar(256) collate database_default
        ,       database_name nvarchar(256) collate database_default
        ,       start_time datetime
        ,       event_class int
        ,       event_subclass int
        ,       object_type int
        ,       server_name nvarchar(256) collate database_default
        ,       login_name nvarchar(256) collate database_default
        ,       application_name nvarchar(256) collate database_default
        ,       ddl_operation nvarchar(40) collate database_default 
        );
        
        select @curr_tracefilename = path from sys.traces where is_default = 1 ; 
        set @curr_tracefilename = reverse(@curr_tracefilename)
        select @indx  = PATINDEX(''%\%'', @curr_tracefilename) 
        set @curr_tracefilename = reverse(@curr_tracefilename)
        set @base_tracefilename = LEFT( @curr_tracefilename,len(@curr_tracefilename) - @indx) + ''\log.trc'';

        insert into @temp_trace 
        select ObjectName
        ,       DatabaseName
        ,       StartTime
        ,       EventClass
        ,       EventSubClass
        ,       ObjectType
        ,       ServerName
        ,       LoginName
        ,       ApplicationName
        ,       ''temp'' 
        from ::fn_trace_gettable( @base_tracefilename, default ) 
        where EventClass in (46,47,164) and EventSubclass = 0 and DatabaseID <> 2 

        update @temp_trace set ddl_operation = ''CREATE'' where event_class = 46
        update @temp_trace set ddl_operation = ''DROP'' where event_class = 47
        update @temp_trace set ddl_operation = ''ALTER'' where event_class = 164

        select @d1 = min(start_time) from @temp_trace
        set @diff= datediff(hh,@d1,getdate())
        set @diff=@diff/24; 

        select  @diff as difference
        ,       @d1 as date
        ,       object_type as obj_type_desc 
        ,       * 
        from @temp_trace where object_type not in (21587)
        order by start_time desc
end 
else 
begin 
        select top 0 1 as difference, 1 as date, 1 as obj_type_desc, 1 as obj_name, 1 as database_name, 1 as start_time, 1 as event_class, 1 as event_subclass, 1 as object_type, 1 as server_name, 1 as login_name, 1 as application_name, 1 as ddl_operation 
end
end try
begin catch
select -100 as difference
,       ERROR_NUMBER() as date
,       ERROR_SEVERITY() as obj_type_desc
,       ERROR_STATE() as obj_name
,       ERROR_MESSAGE() as database_name
,       1 as start_time, 1 as event_class, 1 as event_subclass, 1 as object_type, 1 as server_name, 1 as login_name, 1 as application_name, 1 as ddl_operation 
end catch',@params=N''

Kawał kodu ale możemy z niego wynieść informację o głównym warunku filtrującym czyli EventClass in (46,47,164). Same numery nie wiele nam mówią ale łatwo je odszyfrować gdyż w samym skrypcie znajduje się mapowanie dla tych wartości tj.

update @temp_trace set ddl_operation = ''CREATE'' where event_class = 46 
update @temp_trace set ddl_operation = ''DROP'' where event_class = 47 
update @temp_trace set ddl_operation = ''ALTER'' where event_class = 164

Wnikliwe oko dostrzeże również wykluczenie dla bazy danych o ID=2. Jak dobrze wiemy jest to baza tempdb tak więc raport nie będzie pokazywał obiektów tymczasowych pod postacią tabel lub zmiennych. Całkiem mądry warunek bez którego wyciągnięcie czegoś wartościowego z raportu byłoby niemal niemożliwe. Baza tempdb jest jedynym wykluczeniem jakie mamy na raporcie tak więc wszelkie zmiany w innych bazach systemowych zostaną oczywiście zarejestrowane (daje to ciekawe możliwości wyśledzenia kto stworzył omyłkowo obiekty w bazie master co zdarza się nader często).

Wszystko wydaje być się jasne i klarowne. Ciekawie rzeczy dzieją się w sytuacji gdy default trace jest wyłączony. Przetestujmy to zatem i zobaczmy co się stanie:

EXEC sp_configure 'show advanced options', 1;
EXEC sp_configure 'default trace enabled', 0;
RECONFIGURE WITH OVERRIDE;

Po uruchomieniu omawianego raportu wygląda on całkowicie inaczej:

Pomijając dużą część kodu zestawienie to opiera się na prostym przeszukaniu widoków systemowych:

from sys.all_objects o left outer join sys.schemas s
                                on (o.schema_id = s.schema_id)  where modify_date >  ( GETDATE() -7);'')

Co ciekawe przeszukiwana jest każda baza użytkownika, tak więc otrzymany rezultat rzeczywiście będzie odnosił się do serwera, a nie pojedynczej bazy. Całkiem dobre zachowanie – dobrze, że raport wyświetla jakieś dane, a nie jest w całości pusty. Brakuje mu jednak jednej zasadniczej informacji, a mianowicie tego kto określoną operację wykonał.

Jeśli chodzi o default trace to mechanizm ten ma jedną, zasadniczą wadę, a mianowicie to, że jest wycofywany i z całą pewnością w nowych projektach nie powinniśmy budować na nim żadnych rozwiązań. Zalecaną metodą związaną ze zbieraniem wszelkich informacji jest oczywiście charakteryzujący się lekkością Extended Events. Dlaczego zatem zawracać sobie głowę Schema Changes History i Default trace? A no dlatego, że domyślnie mechanizm ten jest włączony i w sytuacji “zastanego systemu” może być dobrym rozwiązaniem aby zbadać zmiany jakie zaszły (chyba, że ktoś wpadł na pomysł wyłączenia tego mechanizmu). W każdym bądź razie warto mieć w tyle głowy wiedzę, że coś takiego istnieje i jak z tego korzystać aby w razie potrzeby wiedzieć jak z tego skorzystać.