SQL Server

Pomyślałem, że napiszę krótki wpis o SQL Trace, czyli o mechanizmie, który powinien znaleźć się w arsenale każdego DBA pracującego z SQL Serverem.

Namierzyć Profilera

Zakładam, że każdy DBA prędzej czy później musi nauczyć się używać aplikacji SQL Server Profiler. Czasem jednak śledzenie przy użyciu Profilera nie jest mile widziane na serwerze produkcyjnym. Zwłaszcza, jeśli do tego dodać, że śledzenie może odbić się negatywnie na wydajność serwera. Niejednokrotnie zdarzało mi się, że przechwytując Profilerem za dużo zdarzeń (lub zbyt ciężkich zdarzeń – np. plany wykonania), obserwowałem “zamulanie” serwera.

Jak znaleźć trace’y otwarte z użyciem Profilera? Ano tak:

SELECT id, path, file_position, reader_spid
FROM sys.traces
WHERE is_rowset = 1;

Przykładowy wynik:

W zasadzie po dłuższych obserwacjach doszedłem do wniosku, że można też pytać o reader_spid o wartości innej niż NULL.

Kolumny, które wybrałem w powyższym zapytaniu są w moim odczuciu najbardziej przydatne:

• id – unikalny numer trace’a, dzięki niemu można dowiedzieć się więcej o danej sesji śledzenia (o tym za moment) lub po prostu zakończyć sesję śledzenia odpowiednimi wywołaniami procedury sp_trace_setstatus,
• path - jeśli zapisujemy do pliku .trc (najczęstszy scenariusz poza “zwykłym” śledzeniem za pomocą Profilera), ścieżkę do aktualnego pliku znajdziemy właśnie w tej kolumnie,
• file_position - rozmiar pliku, jeśli trace prowadzi zapis do takowego,
• reader_spid – jeśli Profiler czyta trace, tu znajdziemy identyfikator sesji otwartej przez aplikację (i można dzięki temu poleceniem KILL sprawnie zakończyć sesję Profilera).

Co właściwie śledzi trace?

Jednym z najbardziej niedocenianych źródeł informacji dla DBA jest default trace. Jest to systemowy trace uruchamiany domyślnie wraz ze startem instancji. W widoku katalogowym sys.traces zawsze ma id równe 1. Można go włączać / wyłączać zmieniając opcję ‘default trace’. Poniżej włączanie wspomnianej opcji:

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

Co śledzi taki domyślny trace? Przekonajmy się:

SELECT DISTINCT e.trace_event_id, e.name
FROM sys.traces AS t
CROSS APPLY sys.fn_trace_geteventinfo(t.id) AS i
INNER JOIN sys.trace_events AS e
ON i.eventid = e.trace_event_id
WHERE t.is_default = 1
ORDER BY e.trace_event_id;

Wynik:

trace_event_id name
-------------- ------------------------------
18             Audit Server Starts And Stops
20             Audit Login Failed
22             ErrorLog
46             Object:Created
47             Object:Deleted
55             Hash Warning
69             Sort Warnings
79             Missing Column Statistics
80             Missing Join Predicate
81             Server Memory Change
92             Data File Auto Grow
93             Log File Auto Grow
94             Data File Auto Shrink
95             Log File Auto Shrink
102            Audit Database Scope GDR Event
103            Audit Schema Object GDR Event
104            Audit Addlogin Event
105            Audit Login GDR Event
106            Audit Login Change Property Event
108            Audit Add Login to Server Role Event
109            Audit Add DB User Event
110            Audit Add Member to DB Role Event
111            Audit Add Role Event
115            Audit Backup/Restore Event
116            Audit DBCC Event
117            Audit Change Audit Event
152            Audit Change Database Owner
153            Audit Schema Object Take Ownership Event
155            FT:Crawl Started
156            FT:Crawl Stopped
157            FT:Crawl Aborted
164            Object:Altered
167            Database Mirroring State Change
175            Audit Server Alter Trace Event
218            Plan Guide Unsuccessful

Sporo, bo aż 35 rodzajów zdarzeń. Ale są to na ogół zdarzenia, które nie występują z dużą częstotliwością.

W podobny sposób, a używając jedynie innych funkcji i widoków katalogowych, można dowiedzieć się o tym, jakich kolumn dla każdego zdarzenia używa trace, oraz jakie są w nim ustawione filtry.

Default trace w użytku

Kilka przykładowych zastosowań default trace’a, niektóre podpatrzone w Management Studio ;-)

Zmiany w konfiguracji serwera

SELECT
  e.StartTime,
  e.SessionLoginName,
  e.TextData
FROM sys.traces AS t
CROSS APPLY sys.fn_trace_gettable(
  LEFT(t.path, LEN(t.path)-PATINDEX('%\%', REVERSE(t.path))) + '\log.trc',
  DEFAULT
) AS e
WHERE t.is_default = 1
AND (
  -- Error = 15457 - common sp_configure message
  (e.EventClass = 22 AND e.Error = 15457)
  OR
  -- DBCC event
  (e.EventClass = 116 AND e.TextData LIKE '%TRACEO%(%')
)
ORDER BY e.StartTime DESC;

Wynik:

Warte uwagi jest chyba tylko to, że pierwszy plik default trace’a ma nazwę log.trc. Ścieżkę da się odczytać z kolumny path widoku sys.traces. Reszta zapytania bez historii – wybrać dwa rodzaje zdarzeń (Errorlog oraz DBCC) dla trace’a, dla którego w kolumnie is_default w widoku sys.traces widnieje wartość 1.

DDL wykonywany na obiektach w bazach danych

SELECT
  e.StartTime,
  e.SessionLoginName,
  e.DatabaseName,
  e.ObjectName,
  v.subclass_name AS ObjectType,
  CASE e.EventClass
    WHEN 46 THEN 'CREATE'
    WHEN 47 THEN 'ALTER'
    WHEN 164 THEN 'DROP'
  END AS SchemaChange
FROM sys.traces AS t
CROSS APPLY sys.fn_trace_gettable(
  LEFT(t.path, LEN(t.path)-PATINDEX('%\%', REVERSE(t.path))) + '\log.trc',
  DEFAULT
) AS e
INNER JOIN sys.trace_subclass_values AS v
ON    v.trace_event_id = e.EventClass
  AND v.trace_column_id = 28
  AND v.subclass_value = e.ObjectType
WHERE t.is_default = 1
AND e.EventClass IN (46, 47, 164)
AND e.EventSubClass = 0 -- eliminate junk
AND e.DatabaseID <> 2 -- not tempdb
AND e.ObjectType <> 21587 -- not stats
ORDER BY e.StartTime DESC;

Wynik:

Problemem może być odczytanie schematu obiektu, jeśli obiekt skasowano. Komentarz “eliminate junk” dodałem obok filtra, który pozwolił na odfiltrowanie wierszy mówiących o operacjach na statystykach.

Notka: dwa powyższe przykłady wziąłem ze standardowych raportów dostępnych w Management Studio pod prawym przyciskiem na folderze Databases w oknie Object Explorer.

Automatyczne zmiany rozmiaru plików

SELECT
  e.StartTime,
  CASE e.EventClass
    WHEN 92 THEN 'Data File Auto Grow'
    WHEN 93 THEN 'Log File Auto Grow'
    WHEN 94 THEN 'Data File Auto Shrink'
    WHEN 95 THEN 'Log File Auto Shrink'
  END AS EventDesc,
  e.DatabaseName,
  e.FileName
FROM sys.traces AS t
CROSS APPLY sys.fn_trace_gettable(
  LEFT(t.path, LEN(t.path)-PATINDEX('%\%', REVERSE(t.path))) + '\log.trc',
  DEFAULT
) AS e
WHERE t.is_default = 1
AND e.EventClass IN (92, 93, 94, 95)
ORDER BY e.StartTime DESC;

Wynik:

Czarna skrzynka

SQL Server daje możliwość uruchomienia szybkiego w konfiguracji trace’a – tzw. BlackBox trace’a.

Kod do jego stworzenia i uruchomienia jest naprawdę krótki:

DECLARE @trace_id int;
EXEC sp_trace_create @trace_id OUT, 8;
EXEC sp_trace_setstatus @trace_id, 1;

Co śledzi taki trace?

SELECT DISTINCT e.trace_event_id, e.name
FROM sys.traces AS t
CROSS APPLY sys.fn_trace_geteventinfo(t.id) AS ei
CROSS APPLY sys.fn_trace_getinfo(t.id) AS i
INNER JOIN sys.trace_events AS e
ON ei.eventid = e.trace_event_id
WHERE i.property = 1 AND i.value = 8
ORDER BY e.trace_event_id;

Zapytanie zwraca raptem cztery rodzaje zdarzeń:

trace_event_id name
-------------- -----------------
11             RPC:Starting
13             SQL:BatchStarting
16             Attention
33             Exception

Do czego można użyć takiego śledzenia? Szybkie uruchomienie, dość zgrubne zdarzenia… Jeśli już, używałbym w sytuacji, gdy chciałbym dowiedzieć się, co stało się tuż przed “reprodukowalnym” problemem :-) Tak czy owak, jeśli ktoś kiedyś tego użył produkcyjnie, chętnie poczytam o innych zastosowaniach.

BlackBox trace’a znajdujemy w widoku sys.traces używając funkcji sys.fn_trace_getinfo (@options = 8). Swoje dane zapisuje on do dwóch plików o łącznym maksymalnym rozmiarze 10 MB (to mniej niż default trace, który zapisuje do 5 plików po maks. 20 MB każdy). Nowe zdarzenia w obu trace’ach – default i BlackBox – nadpisują stare zdarzenia, jeśli osiągnięty został maksymalny rozmiar ostatniego z dostępnych dla danego trace’a plików. Pliki obu trace’ów zapisywane są w folderze Log w ścieżce roboczej SQL Servera (a więc tam, gdzie ERRORLOG).

Podsumowanie

Sądzę, że warto poznać możliwości obu wymienionych trace’ów. Choćby po to, by pobawić się w wyciąganie metadanych trace’ów albo poznać lepiej procedury do ich obsługi. Nie polecam też wyłączania default trace’a, chyba, że polityka bezpieczeństwa firmy lub organizacji wyraźnie mówi o tym, że należy go wyłączyć.

Jeśli masz jakieś ciekawe przemyślenia na temat obu trace’ów albo znasz jakieś ciekawostki dotyczące trace’ów ogólnie, podziel się nimi (mogę je opublikować jako dodatek do tego wpisu).