Часто мне вспоминается первая работа. Средненький офис, моник 943N и обогреватель Pentium D под ногами. Как возникал из ниоткуда Борис (нет… не Борис-бритва) с линейкой в руках и настойчиво просил не делать «больно» SQL Server.
Именно в те далекие времена я впервые познакомился с профайлером. Пользовательские трейсы оказались очень кстати при отладке приложений и поиске медленных запросов. Потом для себя я открыл 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) Microsoft SQL Server Management Studio PC\IgorS 2016-02-10 20:03:46.307 DBCC FREEPROCCACHE Microsoft SQL Server Management Studio PC\IgorS 2016-02-10 20:03:43.430 DBCC DROPCLEANBUFFERS Microsoft SQL Server Management Studio PC\IgorS 2016-02-10 20:03:44.767 4. Errors and Warnings Events
В ситуации, когда SQL Server не имеет достаточного объёма свободной памяти, который требуется для выполнения запроса, обработка результатов некоторых операторов будет происходить в 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 TextData ApplicationName LoginName StartTime DatabaseName ------------------ ----------- ---------------------------------------------------- ------------- ----------------------- --------------------- Sort Warnings NULL Microsoft SQL Server Management Studio - 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 ------------------------------------ ----------------------------------------- ----------- ----------------------- -------------- ---------------- <ShowPlanXML xmlns="http://schem... SELECT * FROM Sales.SalesOrderHeader... 1,10126 2016-02-11 13:06:44.850 1538 1 К слову скажу, актуальные планы выполнения недоступны через 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 TextData ApplicationName LoginName StartTime DatabaseName ---------------- ----------- ------------------------------------------------- ------------- ----------------------- --------------------- Hash Warning NULL Microsoft SQL Server Management Studio - 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 TextData ApplicationName LoginName StartTime DatabaseName ----------------------- ----------- ------------------------------------------------- ------------- ----------------------- --------------------- Missing Join Predicate NULL Microsoft SQL Server Management Studio - 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 ApplicationName LoginName StartTime DatabaseName --------------------------- ---------------------------------------------------------------- ------------------------------------------------- --------------- ----------------------- ---------------------- Missing Column Statistics NO STATS:([AdventureWorks2012].[dbo].[DatabaseLog].[PostTime]) Microsoft SQL Server Management Studio - Query 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 Microsoft SQL Server Management Studio - Query PC\SergeyS 2016-02-11 13:36:46.727 NULL Database Object:Created test Microsoft SQL Server Management Studio - Query PC\SergeyS 2016-02-11 13:36:46.760 tbl Table Object:Altered test Microsoft SQL Server Management Studio - Query PC\SergeyS 2016-02-11 13:36:46.803 tbl Table Object:Created test Microsoft SQL Server Management Studio - Query PC\SergeyS 2016-02-11 13:36:46.837 ix Index Object:Deleted test Microsoft SQL Server Management Studio - 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 Microsoft SQL Server Management Studio - 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 EventSubClass WHEN 1 THEN 'UP' WHEN 2 THEN '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:16.780 UP 552 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 2016-02-10 15:31:19.453 UP 894 2016-02-10 15:42:03.383 DOWN 698 2016-02-10 15:53:42.490 DOWN 518 2016-02-10 21:14:38.363 UP 697 Выводы
Дефолтный трейс является достаточно мощным средством для отслеживания состояния сервера. Разумеется, он имеет много ограничений, например, упомянутое ограничение в 20Мб. Но все же иногда он бывает очень полезным на этапе первичной диагностики проблем с SQL Server. Надеюсь мои примеры это наглядно смогли показать.
ссылка на оригинал статьи https://habrahabr.ru/post/277053/
Добавить комментарий