SQL
Microsoft SQL Server
11 February 2016

Что скрывает в себе DEFAULT TRACE?

Tutorial


Часто вспоминается первая работа… Средненький офис, моник 943N и обогреватель Pentium D под ногами. Как возникал из ниоткуда Борис (нет… не Борис «Бритва») с линейкой в руках и настойчиво просил не делать «больно» серверу.

Именно в те далекие времена я впервые познакомился с профайлером. Пользовательские трейсы оказались очень кстати при отладке приложений и поиске медленных запросов. Потом для себя я открыл DMV и XEvents… и профайлером стал пользоваться реже. Причина такого поступка проста – трейсы очень ресурсоемкие.

Однако, данную функциональность не стоит преждевременно придавать анафеме. Начиная с 2005 версии при установке SQL Server по умолчанию создается легковесный системный трейс, который хранит в себе много полезной информации.

Находится он в папке где установлен SQL Server и состоит из пяти файлов с расширением trc. При каждом старте сервера автоматически создается новый файл для трейса, а самый старый затирается. Запись новых событий всегда идет в самый последний файл, размер которого ограничен 20 Мб. При превышении размера автоматом создается новый файл. Поменять данное поведение нельзя.

Разрешается только отключать или включать данную функциональность:

EXEC sys.sp_configure 'show advanced options', 1
GO
RECONFIGURE WITH OVERRIDE
GO
EXEC sys.sp_configure 'default trace enabled', 0
GO
RECONFIGURE WITH OVERRIDE
GO

Проверить, что дефолтный трейс включен можно следующим запросом:

SELECT name, value
FROM sys.configurations
WHERE configuration_id = 1568

Путь к дефолтному трейсу:

SELECT [path], start_time, last_event_time, event_count
FROM sys.traces
WHERE is_default = 1

А теперь начинаем самое интересное… Посмотрим, что за события могут храниться в дефолтном трейсе:

SELECT e.trace_event_id, e.name, c.category_id, c.name
FROM sys.trace_categories c
JOIN sys.trace_events e ON c.category_id = e.category_id

trace_event_id name                       category_id name
-------------- -------------------------- ----------- -----------------------------------
196            CLR                        20          Assembly Load
92             Database                   2           Data File Auto Grow
93             Database                   2           Log File Auto Grow
94             Database                   2           Data File Auto Shrink
95             Database                   2           Log File Auto Shrink
79             Errors and Warnings        3           Missing Column Statistics
80             Errors and Warnings        3           Missing Join Predicate
67             Errors and Warnings        3           Execution Warnings
69             Errors and Warnings        3           Sort Warnings
55             Errors and Warnings        3           Hash Warning
21             Errors and Warnings        3           EventLog
22             Errors and Warnings        3           ErrorLog
213            Errors and Warnings        3           Database Suspect Data Page
214            Errors and Warnings        3           CPU threshold exceeded
46             Objects                    5           Object:Created
47             Objects                    5           Object:Deleted
164            Objects                    5           Object:Altered
...

И рассмотрим на небольших примерах практическую пользу от информации из дефолтного трейса.

1. Auto Grow Events

Надеюсь не секрет, что для выполнения любой транзакции требуется определенное место на диске. В файле данных или логе. Не будем конкретизировать… но общем случае, если места недостаточно, то происходит авто-увеличение файла. В этот момент файл блокируется и SQL Server будет ждать пока дисковая подсистема сделает необходимые операции по выделению места на диске.

По умолчанию, SQL Server инициализирует новое место на диске нулями. Для файлов данных такое поведение можно отключить за счет использования Instant File Initialization. Но для лог файлов инициализация все равно будет происходить и это однозначно медленно. Поэтому рекомендуется на постоянной основе отслеживать Auto Grow события:

SELECT
      StartTime
    , Duration = Duration / 1000
    , DatabaseName = DB_NAME(DatabaseID)
    , [FileName]
    , GrowType = CASE WHEN EventClass = 92 THEN 'DATA' ELSE 'LOG' END
FROM sys.traces i
CROSS APPLY sys.fn_trace_gettable([path], DEFAULT) t
WHERE t.EventClass IN (
            92, -- Data File Auto Grow
            93  -- Log File Auto Grow
        ) 
    AND i.is_default = 1

И если их количество резко увеличивается:

StartTime            Duration    DatabaseName           FileName                   GrowType
-------------------- ----------- ---------------------- -------------------------- --------
2016-01-16 02:52:48  36          tempdb                 templog                    LOG
2016-01-16 02:52:49  50          tempdb                 tempdev                    DATA
2016-01-16 02:52:50  216         tempdb                 tempdev                    DATA
2016-01-16 02:52:51  43          tempdb                 tempdev                    DATA
2016-01-16 02:52:52  760         tempdb                 tempdev                    DATA
2016-01-16 02:52:54  270         tempdb                 tempdev                    DATA
2016-01-16 02:52:55  273         tempdb                 tempdev                    DATA
2016-01-16 02:52:56  286         tempdb                 tempdev                    DATA
2016-01-16 02:52:58  206         tempdb                 tempdev                    DATA
2016-01-16 02:52:59  513         tempdb                 tempdev                    DATA
2016-01-16 02:53:01  363         tempdb                 tempdev                    DATA
2016-01-16 02:53:03  300         tempdb                 tempdev                    DATA
2016-01-16 02:53:05  303         tempdb                 tempdev                    DATA
2016-01-16 02:53:08  200         tempdb                 tempdev                    DATA
2016-01-16 02:53:10  60          tempdb                 tempdev                    DATA
2016-01-16 02:53:12  350         tempdb                 tempdev                    DATA
2016-01-16 02:53:15  370         tempdb                 tempdev                    DATA
2016-01-16 02:53:17  243         tempdb                 tempdev                    DATA
2016-01-16 02:53:21  446         tempdb                 tempdev                    DATA
2016-01-16 02:53:25  163         tempdb                 tempdev                    DATA
2016-01-16 02:53:30  286         tempdb                 tempdev                    DATA
2016-01-16 02:53:36  426         tempdb                 tempdev                    DATA
2016-01-16 02:53:42  376         tempdb                 tempdev                    DATA
2016-01-16 02:53:49  120         tempdb                 tempdev                    DATA
2016-01-16 02:53:58  200         tempdb                 tempdev                    DATA
2016-01-16 02:54:06  186         tempdb                 tempdev                    DATA
2016-01-16 02:54:17  43          tempdb                 tempdev                    DATA
2016-01-16 02:54:27  6           tempdb                 tempdev                    DATA
2016-01-16 02:54:42  3           tempdb                 tempdev                    DATA
2016-01-16 02:55:04  30          tempdb                 tempdev                    DATA
2016-01-16 14:19:47  63          AdventureWorks2012     AdventureWorks2012_Log     LOG
2016-01-16 14:19:47  20          AdventureWorks2012     AdventureWorks2012_Log     LOG
2016-01-16 16:51:32  100         tempdb                 tempdev                    DATA
2016-02-16 17:31:02  66          tempdb                 templog                    LOG
...

То это может вызывать не только фрагментацию файла на диске, но и существенные задержки при выполнении запросов:

SELECT
      GrowType = CASE WHEN EventClass = 92 THEN 'DATA' ELSE 'LOG' END
    , GrowCount = COUNT(1)
    , Duration = SUM(Duration) / 1000
FROM sys.traces i
CROSS APPLY sys.fn_trace_gettable([path], DEFAULT) t
WHERE t.EventClass IN (92, 93) 
    AND i.is_default = 1
    AND t.DatabaseID = DB_ID('tempdb')
GROUP BY EventClass

GrowType GrowCount   Duration
-------- ----------- --------------------
DATA     36          7296
LOG      2           102

Посмотрим на настройки проблемной базы:

USE tempdb
GO

SELECT
      d.type_desc
    , d.name
    , d.physical_name
    , current_size_mb = ROUND(d.size * 8. / 1000, 0)
    , initial_size_mb = ROUND(m.size * 8. / 1000, 0) 
    , auto_grow =
        CASE WHEN d.is_percent_growth = 1
            THEN CAST(d.growth AS VARCHAR(10)) + '%'
            ELSE CAST(ROUND(d.growth * 8. / 1000, 0) AS VARCHAR(10)) + 'MB'
        END
FROM sys.database_files d
JOIN sys.master_files m ON d.[file_id] = m.[file_id]
WHERE m.database_id = DB_ID('tempdb')

Изначальный размер базы данных 8 Мб для файла данных и 1 Мб для лога:

type  name       physical_name                  current_size_mb    initial_size_mb    auto_grow
----- ---------- ------------------------------ ------------------ ------------------ ---------
ROWS  tempdev    D:\SQL_2012\DATA\tempdb.mdf    258.000000         8.000000           10%
LOG   templog    D:\SQL_2012\DATA\templog.ldf   3.000000           1.000000           1MB

… чего явно недостаточно, если сравнивать с текущим размером. Более того, нужно помнить, что при каждом рестарте SQL Server tempdb пересоздается. В сухом остатке, при следующем старте мы опять получим файл в 9 Мб, задержки при выполнении запросов и новую порцию сообщений в дефолтном трейсе.

Какой выход из этой ситуации? Следить за размером файлов и резервировать свободное место для них:

SELECT
      s.[file_id]
    , s.name
    , size = CAST(s.size * 8. / 1024 AS DECIMAL(18,2))
    , space_used = CAST(t.space_used * 8. / 1024 AS DECIMAL(18,2))
    , free_space = CAST((s.size - t.space_used) * 8. / 1024 AS DECIMAL(18,2))
    , used_percent = CAST(t.space_used * 100. / s.size AS DECIMAL(18,2))
    , s.max_size
    , s.growth
    , s.is_percent_growth
FROM sys.database_files s
CROSS APPLY (
    SELECT space_used = FILEPROPERTY(s.name, 'SpaceUsed')
) t

2. Auto Shrink Events

Недавно я уже писал о том, что опция AUTO_CLOSE снижает производительность. Так вот AUTO_SHRINK поступает еще хуже… Каждые 30 минут SQL Server пытается сделать усечение свободного места в файлах базы данных. Данный процесс достаточно ресурсоемкий и может приводить к фрагментации файлов на диске. При усечении файлов возникает высокая фрагментация индексов, что увеличивает логические чтения и снижает производительность запросов.

Представим простую ситуацию… Удалили данные из таблицы – усечение файла. Вставили новые данные – не хватило места и SQL Server пришлось увеличивать размер файла. Удалили данные и опять все по-новому…

SELECT
      StartTime
    , EndTime
    , Duration = Duration / 1000
    , DatabaseName = DB_NAME(DatabaseID)
    , [FileName]
    , GrowType = CASE WHEN EventClass = 94 THEN 'DATA' ELSE 'LOG' END
    , NTDomainName
    , ApplicationName
    , LoginName
    , TextData
    , IsSystem
FROM sys.traces i
CROSS APPLY sys.fn_trace_gettable([path], DEFAULT) t
WHERE t.EventClass IN (
            94, -- Data File Auto Shrink
            95  -- Log File Auto Shrink
        ) 
    AND i.is_default = 1

StartTime           Duration    DatabaseName              FileName                 GrowType
------------------- ----------- ------------------------- ------------------------ --------
2016-02-10 11:57:54 116         AdventureWorks2012        AdventureWorks2012_Log   LOG
2016-02-10 14:58:21 113         AdventureWorks2012        AdventureWorks2012_Log   LOG
2016-02-10 19:30:02 113         AdventureWorks2012        AdventureWorks2012_Log   LOG
2016-02-10 21:00:26 16          AdventureWorks2012        AdventureWorks2012_Log   LOG

Однозначно советую данную опцию отключать:

SELECT 'ALTER DATABASE ' + QUOTENAME(name) + ' SET AUTO_SHRINK OFF WITH NO_WAIT;'
FROM sys.databases
WHERE is_auto_shrink_on = 1

3. DBCC Events

Еще одна полезность дефолтного трейса – возможность отслеживать кто и когда запускал DBCC команды. Ругать за DBCC CHECKDB обычно не стоит, но вот если кто-то на продакшене без ума выполняет:

DBCC SHRINKDATABASE
DBCC FREEPROCCACHE
DBCC DROPCLEANBUFFERS

то можно это легко отследить:

SELECT t.TextData, t.ApplicationName, t.LoginName, t.StartTime
FROM sys.traces i
CROSS APPLY sys.fn_trace_gettable([path], DEFAULT) t
WHERE i.is_default = 1
    AND t.EventClass = 116 -- Audit DBCC Event
    AND t.ApplicationName IS NOT NULL

и кое с кем провести профилактическую беседу о пользе стояния в углу на гречке:

TextData                ApplicationName     LoginName    StartTime               
----------------------- ------------------  -----------  ----------------------- 
DBCC SHRINKDATABASE(1)  SSMS - Query        PC\IgorS     2016-02-10 20:03:46.307 
DBCC FREEPROCCACHE      SSMS - Query        PC\IgorS     2016-02-10 20:03:43.430 
DBCC DROPCLEANBUFFERS   SSMS - Query        PC\IgorS     2016-02-10 20:03:44.767 

4. Errors and Warnings Events

В ситуации, когда SQL Server не имеет достаточного объёма свободной памяти, который требуется для выполнения запроса, обработка результатов некоторых операторов будет происходить в tempdb. Такое же поведение будет, когда оптимизатором была сделала неверная оценка ожидаемого количества строк.

Попробуем написать запрос, который вызовет spills в tempdb:

SELECT *
FROM Sales.SalesOrderHeader
WHERE DueDate > ShipDate
ORDER BY OrderDate DESC



Благодаря сообщению из дефолтного трейса мы можем отследить такие запросы:

SELECT TOP(10)
      EventName = e.name
    , t.TextData
    , t.ApplicationName
    , t.LoginName
    , t.StartTime
    , DatabaseName = DB_NAME(t.DatabaseID)
FROM sys.traces i
CROSS APPLY sys.fn_trace_gettable([path], DEFAULT) t
JOIN sys.trace_events e ON e.trace_event_id = t.EventClass
WHERE i.is_default = 1
    AND e.category_id = 3
ORDER BY t.StartTime DESC

EventName          ApplicationName   LoginName     StartTime               DatabaseName
------------------ ----------------- ------------- ----------------------- ---------------------
Sort Warnings      SSMS - Query      PC\SergeyS    2016-02-11 13:06:44.867 AdventureWorks2012

Найти их план выполнения и попытаться оптимизировать запрос:

USE AdventureWorks2012
GO
SELECT TOP(5)
      p.query_plan
    , e.[text]
    , qyery_cost = p.query_plan.value(
            '(/*:ShowPlanXML/*:BatchSequence/*:Batch/*:Statements/*:StmtSimple/@StatementSubTreeCost)[1]',
            'FLOAT'
        )
    , s.last_execution_time
    , last_exec_ms = s.last_worker_time / 1000
    , s.execution_count
FROM sys.dm_exec_query_stats s
CROSS APPLY sys.dm_exec_query_plan(s.plan_handle) p
CROSS APPLY sys.dm_exec_sql_text(s.plan_handle) e
WHERE e.[text] NOT LIKE '%sys%'
    AND s.last_execution_time >= DATEADD(MS, -2500, '2016-02-10 19:41:45.983')
    AND e.[dbid] = DB_ID()
ORDER BY s.last_execution_time

query_plan        text                             qyery_cost  execution_time      last_exec_ms  
----------------- -------------------------------- ----------- ------------------- --------------
<ShowPlanXML ...  SELECT * FROM Sales.SalesOrde... 1,10126     2016-02-11 13:06:44 1538          

К слову скажу, актуальные планы выполнения недоступны через DMV. Их можно получить только на этапе Post Query Execution Showplan, через соответствующий Trace event, или по команде SET STATISTICS XML ON. Начиная с SQL Server 2012 специально для таких целей добавили новый XEventpost_query_execution_showplan.

Меня лично радует, что отслеживать можно разного рода предупреждения:

SELECT DISTINCT d.SalesOrderID, d.UnitPrice, h.OrderDate
FROM Sales.SalesOrderHeader h
JOIN Sales.SalesOrderDetail d ON h.SalesOrderID = d.SalesOrderID
WHERE h.DueDate > h.ShipDate



EventName        ApplicationName   LoginName     StartTime               DatabaseName
---------------- ----------------- ------------- ----------------------- ---------------------
Hash Warning     SSMS - Query      PC\SergeyS    2016-02-11 13:14:44.433 AdventureWorks2012

Например, когда по ошибке забыли указать поля по которым идет соединение:

SELECT *
FROM Sales.Currency c, Sales.CountryRegionCurrency r
--WHERE c.CurrencyCode = r.CurrencyCode



EventName               ApplicationName   LoginName     StartTime           DatabaseName
----------------------- ----------------- ------------- ------------------- ---------------------
Missing Join Predicate  SSMS - Query      PC\SergeyS    2016-02-11 13:18:20 AdventureWorks2012

или, когда на столбце по которому идет фильтрация отсутствует статистика:

SELECT DatabaseLogID
FROM dbo.DatabaseLog
WHERE PostTime = '2012-03-14 13:14:18.847'



EventName                   TextData                                   DatabaseName
--------------------------- ------------------------------------------ --------------------
Missing Column Statistics   NO STATS:([dbo].[DatabaseLog].[PostTime])  AdventureWorks2012

5. Object Events

В дефолтном трейсе можно отслеживать создание и удаление объектов:

USE [master]
GO
IF DB_ID('test') IS NOT NULL
    DROP DATABASE [test]
GO
CREATE DATABASE [test]
GO
USE [test]
GO
CREATE TABLE dbo.tbl (ID INT)
GO
ALTER TABLE dbo.tbl ADD Col VARCHAR(20)
GO
CREATE UNIQUE CLUSTERED INDEX ix ON dbo.tbl (ID)
GO
USE [master]
GO
IF DB_ID('test') IS NOT NULL
    DROP DATABASE [test]
GO

SELECT
      EventType = e.name
    , t.DatabaseName
    , t.ApplicationName
    , t.LoginName
    , t.StartTime
    , t.ObjectName
    , ObjectType =
        CASE t.ObjectType
            WHEN 8259 THEN 'Check Constraint'
            WHEN 8260 THEN 'Default Constraint'
            WHEN 8262 THEN 'Foreign Key'
            WHEN 8272 THEN 'Stored Procedure'
            WHEN 8274 THEN 'Rule'
            WHEN 8275 THEN 'System Table'
            WHEN 8276 THEN 'Server Trigger'
            WHEN 8277 THEN 'Table'
            WHEN 8278 THEN 'View'
            WHEN 8280 THEN 'Extended Stored Procedure'
            WHEN 16724 THEN 'CLR Trigger'
            WHEN 16964 THEN 'Database'
            WHEN 17222 THEN 'FullText Catalog'
            WHEN 17232 THEN 'CLR Stored Procedure'
            WHEN 17235 THEN 'Schema'
            WHEN 17985 THEN 'CLR Aggregate Function'
            WHEN 17993 THEN 'Inline Table-valued SQL Function'
            WHEN 18000 THEN 'Partition Function'
            WHEN 18004 THEN 'Table-valued SQL Function'
            WHEN 19280 THEN 'Primary Key'
            WHEN 19539 THEN 'SQL Login'
            WHEN 19543 THEN 'Windows Login'
            WHEN 20038 THEN 'Scalar SQL Function'
            WHEN 20051 THEN 'Synonym'
            WHEN 20821 THEN 'Unique Constraint'
            WHEN 21075 THEN 'Server'
            WHEN 21076 THEN 'Transact-SQL Trigger'
            WHEN 21313 THEN 'Assembly'
            WHEN 21318 THEN 'CLR Scalar Function'
            WHEN 21321 THEN 'Inline scalar SQL Function'
            WHEN 21328 THEN 'Partition Scheme'
            WHEN 21333 THEN 'User'
            WHEN 21572 THEN 'Database Trigger'
            WHEN 21574 THEN 'CLR Table-valued Function'
            WHEN 21587 THEN 'Statistics'
            WHEN 21825 THEN 'User'
            WHEN 21827 THEN 'User'
            WHEN 21831 THEN 'User'
            WHEN 21843 THEN 'User'
            WHEN 21847 THEN 'User'
            WHEN 22601 THEN 'Index'
            WHEN 22611 THEN 'XMLSchema'
            WHEN 22868 THEN 'Type'
        END
FROM sys.traces i
CROSS APPLY sys.fn_trace_gettable([path], DEFAULT) t
JOIN sys.trace_events e ON t.EventClass = e.trace_event_id
WHERE e.name IN ('Object:Created', 'Object:Deleted', 'Object:Altered')
    AND t.ObjectType != 21587
    AND t.DatabaseID != 2
    AND i.is_default = 1
    AND t.EventSubClass = 1

EventType        DatabaseName   ApplicationName  StartTime               ObjectName    ObjectType
---------------- -------------- ---------------- ----------------------- ------------- ------------
Object:Created   test           SSMS - Query     2016-02-11 13:36:46.727 NULL          Database
Object:Created   test           SSMS - Query     2016-02-11 13:36:46.760 tbl           Table
Object:Altered   test           SSMS - Query     2016-02-11 13:36:46.803 tbl           Table
Object:Created   test           SSMS - Query     2016-02-11 13:36:46.837 ix            Index
Object:Deleted   test           SSMS - Query     2016-02-11 13:36:56.347 NULL          Database

6. Server Events

Также через дефолтный трейс существует возможность следить за тем, кто и когда делал бекапы и ресторил базы:

SELECT
    CASE WHEN t.EventSubClass = 1
        THEN 'BACKUP' 
        ELSE 'RESTORE'
    END, t.TextData, t.ApplicationName, t.LoginName, t.StartTime
FROM sys.traces i
CROSS APPLY sys.fn_trace_gettable([path], DEFAULT) t
WHERE i.is_default = 1
    AND t.EventClass = 115 -- Audit Backup/Restore Event

TextData             ApplicationName                 LoginName   StartTime
-------------------- ------------------------------- ----------- -------------------------
BACKUP DATABASE      SSMS - Query                    PC\SergeyS  2016-01-21 13:05:26.390
RESTORE DATABASE     dbForge Studio for SQL Server   PC\SergeyS  2016-01-22 12:46:45.717
BACKUP DATABASE      SQLCMD                          sa          2016-01-24 10:16:40.317

Или отслеживать потребление памяти SQL Server-ом:

SELECT
      t.StartTime
    , [Type] = CASE WHEN EventSubClass = 1 THEN 'UP' ELSE 'DOWN' END
    , t.IntegerData
FROM sys.traces i
CROSS APPLY sys.fn_trace_gettable([path], DEFAULT) t
WHERE t.EventClass = 81 -- Server Memory Change
    AND i.is_default = 1

StartTime                Type  IntegerData
------------------------ ----- -----------
2016-02-10 02:52:42.887  UP    191
2016-02-10 02:53:00.640  UP    371
2016-02-10 02:53:34.917  UP    734
2016-02-10 02:53:52.140  UP    916
2016-02-10 10:05:00.027  DOWN  736
2016-02-10 10:17:17.417  UP    921
2016-02-10 11:52:14.930  DOWN  735
2016-02-10 12:00:32.577  DOWN  553
2016-02-10 13:06:11.540  UP    751
2016-02-10 15:11:10.487  UP    936
2016-02-10 15:15:26.107  DOWN  714

Небольшое послесловие

Дефолтный трейс является достаточно мощным средством для отслеживания состояния сервера. Разумеется, он имеет много недостатков, например, упомянутое ограничение в 20Мб и заявление от Microsoft что данная функциональность начиная с SQL Server 2008 объявлена устаревшей. Но все же иногда дефолтный трейс бывает очень полезным на этапе первичной диагностики проблем с SQL Server. Надеюсь мои примеры выши смогли это наглядно показать.

Все тестировалось на Microsoft SQL Server 2012 (SP3) (KB3072779) — 11.0.6020.0 (X64).

Если хотите поделиться этой статьей с англоязычной аудиторией:
Hidden gems of DEFAULT TRACE in SQL Server

+10
12.6k 84
Comments 3