Что скрывает в себе DEFAULT TRACE?
Часто вспоминается первая работа… Средненький офис, моник 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 EndTime Duration DatabaseName FileName GrowType
------------------------ ------------------------ ----------- ---------------------- -------------------------- --------
2016-01-16 02:52:48.127 2016-01-16 02:52:48.163 36 tempdb templog LOG
2016-01-16 02:52:49.090 2016-01-16 02:52:49.140 50 tempdb tempdev DATA
2016-01-16 02:52:50.687 2016-01-16 02:52:50.903 216 tempdb tempdev DATA
2016-01-16 02:52:51.213 2016-01-16 02:52:51.257 43 tempdb tempdev DATA
2016-01-16 02:52:52.300 2016-01-16 02:52:53.060 760 tempdb tempdev DATA
2016-01-16 02:52:54.090 2016-01-16 02:52:54.360 270 tempdb tempdev DATA
2016-01-16 02:52:55.407 2016-01-16 02:52:55.680 273 tempdb tempdev DATA
2016-01-16 02:52:56.720 2016-01-16 02:52:57.007 286 tempdb tempdev DATA
2016-01-16 02:52:58.047 2016-01-16 02:52:58.253 206 tempdb tempdev DATA
2016-01-16 02:52:59.317 2016-01-16 02:52:59.830 513 tempdb tempdev DATA
2016-01-16 02:53:01.917 2016-01-16 02:53:02.280 363 tempdb tempdev DATA
2016-01-16 02:53:03.387 2016-01-16 02:53:03.687 300 tempdb tempdev DATA
2016-01-16 02:53:05.757 2016-01-16 02:53:06.060 303 tempdb tempdev DATA
2016-01-16 02:53:08.143 2016-01-16 02:53:08.343 200 tempdb tempdev DATA
2016-01-16 02:53:10.440 2016-01-16 02:53:10.500 60 tempdb tempdev DATA
2016-01-16 02:53:12.703 2016-01-16 02:53:13.053 350 tempdb tempdev DATA
2016-01-16 02:53:15.150 2016-01-16 02:53:15.520 370 tempdb tempdev DATA
2016-01-16 02:53:17.653 2016-01-16 02:53:17.897 243 tempdb tempdev DATA
2016-01-16 02:53:21.030 2016-01-16 02:53:21.477 446 tempdb tempdev DATA
2016-01-16 02:53:25.490 2016-01-16 02:53:25.653 163 tempdb tempdev DATA
2016-01-16 02:53:30.870 2016-01-16 02:53:31.157 286 tempdb tempdev DATA
2016-01-16 02:53:36.707 2016-01-16 02:53:37.133 426 tempdb tempdev DATA
2016-01-16 02:53:42.663 2016-01-16 02:53:43.040 376 tempdb tempdev DATA
2016-01-16 02:53:49.787 2016-01-16 02:53:49.907 120 tempdb tempdev DATA
2016-01-16 02:53:58.640 2016-01-16 02:53:58.840 200 tempdb tempdev DATA
2016-01-16 02:54:06.870 2016-01-16 02:54:07.057 186 tempdb tempdev DATA
2016-01-16 02:54:17.063 2016-01-16 02:54:17.107 43 tempdb tempdev DATA
2016-01-16 02:54:27.363 2016-01-16 02:54:27.370 6 tempdb tempdev DATA
2016-01-16 02:54:42.107 2016-01-16 02:54:42.110 3 tempdb tempdev DATA
2016-01-16 02:55:04.883 2016-01-16 02:55:04.913 30 tempdb tempdev DATA
2016-01-16 14:19:47.607 2016-01-16 14:19:47.670 63 AdventureWorks2012 AdventureWorks2012_Log LOG
2016-01-16 14:19:47.820 2016-01-16 14:19:47.840 20 AdventureWorks2012 AdventureWorks2012_Log LOG
2016-01-16 16:51:32.980 2016-01-16 16:51:33.080 100 tempdb tempdev DATA
2016-02-16 17:31:02.260 2016-02-16 17:31:02.327 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_desc 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 EndTime Duration DatabaseName FileName GrowType
----------------------- ----------------------- ----------- ------------------------- ------------------------ --------
2016-02-10 11:57:54.333 2016-02-10 11:57:54.450 116 AdventureWorks2012 AdventureWorks2012_Log LOG
2016-02-10 14:58:21.087 2016-02-10 14:58:21.200 113 AdventureWorks2012 AdventureWorks2012_Log LOG
2016-02-10 19:30:02.350 2016-02-10 19:30:02.463 113 AdventureWorks2012 AdventureWorks2012_Log LOG
2016-02-10 21:00:26.083 2016-02-10 21:00:26.100 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 last_execution_time last_exec_ms execution_count
----------------- ---------------------------------------- ----------- ----------------------- -------------- ----------------
К слову скажу, актуальные планы выполнения недоступны через DMV. Их можно получить только на этапе Post Query Execution Showplan, через соответствующий Trace event, или по команде SET STATISTICS XML ON. Начиная с SQL Server 2012 специально для таких целей добавили новый XEvent — post_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.507 AdventureWorks2012
или, когда на столбце по которому идет фильтрация отсутствует статистика:
SELECT DatabaseLogID
FROM dbo.DatabaseLog
WHERE PostTime = '2012-03-14 13:14:18.847'
EventName TextData .. LoginName StartTime DatabaseName
--------------------------- ------------------------------------------ .. ------------ ----------------------- --------------------
Missing Column Statistics NO STATS:([dbo].[DatabaseLog].[PostTime]) .. PC\SergeyS 2016-02-11 13:19:39.813 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 LoginName StartTime ObjectName ObjectType
---------------- -------------- -------------------- ------------- ----------------------- ------------- --------------
Object:Created test SSMS - Query PC\SergeyS 2016-02-11 13:36:46.727 NULL Database
Object:Created test SSMS - Query PC\SergeyS 2016-02-11 13:36:46.760 tbl Table
Object:Altered test SSMS - Query PC\SergeyS 2016-02-11 13:36:46.803 tbl Table
Object:Created test SSMS - Query PC\SergeyS 2016-02-11 13:36:46.837 ix Index
Object:Deleted test SSMS - Query PC\SergeyS 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).
Планы выполнения брал из dbForge Studio.
На правах рекламы. Все желающие из Харькова приходите 26 февраля на вторую встречу SQL Server юзер группы. Участие бесплатно. Если кто желает выступить как спикер — пишите в личку.
Всем спасибо за внимание.
