Автор: Daniel Farina
Перевод: Александр Гладченко
Проблема
Если вдруг один из запросов к SQL Server выполняется слишком долго, вы может получить его план исполнения, что даст вам понимание того, что этот запрос делает, но из этого плана вы не сможете точно определить, что запрос делает именно в это время, т.е. на каком операторе плана он «застрял»?
Продолжая читать эту статью, вы узнаете, как научится следить за прогрессом исполнения запроса в режиме реального времени.
Решение
Сколько раз вы задавали себе подобный вопрос: сколько времени нужно, чтобы процесс завершился? Вот какой случай произошёл на моей работе несколько дней назад: ко мне подошел аналитик с вопросом, на каком шаге плана исполнения находится его задача. Выполнив несколько запросов, я понял, что текущим шагом в его запросе была хранимая процедура, которая выполняла изменения данных, но это было единственное, что я мог ему сказать. Тут же мне в голову пришла мысль: было бы лучше, если бы эта задача решалась на экземпляре SQL Server 2014, вместо используемого для неё устаревшего SQL Server 2000. Дело в том, что в SQL Server 2014 появилось новое Dynamic Management View, позволяющее отслеживать на физическом уровне, что фактически запрос делает во время работы оператора. Я имею в виду динамическое административное представление (DMV): sys.dm_exec_query_profiles
Немного о sys.dm_exec_query_profiles
Для того чтобы эта DMV заработала, нам необходимо обеспечить доступ к реальным планам исполнения запросов (Actual Execution Plan). Как вы уже могли догадаться, этот способ не работает для планов, хранящихся в кэше (Plan Cache). Возможно у вас возник вопрос, почему мы не можем получить статус любого выполняемого на экземпляре запроса в режиме реального времени, и ответ тут простой: ничто не даётся бесплатно. Доступ к упомянутым выше показателям имеет стоимость в терминах производительности, и она возникает из-за того, что SQL Server для анализа запроса должен собрать детализированную статистику.
Планы, которые хранятся в Plan Cache, не содержат статистику исполнения. Они содержат оценки, которые используются для построения плана действий как такового. Когда мы говорим о статистике исполнения мы говорим о фактическом числе чтений, записи, процессорного времени и так далее.
Несколько способов получения данных о производительности SQL Server в реальном времени
Для SQL Server можно показать три способа, позволяющих получить фактический план исполнения запроса:
- Установка непосредственно в коде подлежащего анализу запроса одного из параметров исполнения SET STATISTICS PROFILE или SET STATISTICS XML в положение ON предоставляет нам возможность такого анализа.
- Создание server side trace в том числе с одним из этих двух событий: “Showplan Statistics Profile” или “Showplan Statistics XML”. Кроме того, если вам так удобнее, можно использовать приложение SQL Server Profiler.
- Создание сессии Extended Events и добавление в ней в качестве целевого события sqlserver.query_post_execution_showplan.
Последние два метода полезны, когда вы не можете добавить установку SET непосредственно в коде запроса, который необходимо проанализировать. Однако эти методы нужно использовать с осторожностью, поскольку они негативно влияют на производительность сервера.
Пример сценария трассировки на стороне SQL Server
Ниже представлен пример сценария, создающего трассировку с помощью события “Showplan XML Statistics Profile” и отфильтрованную по имени базы данных.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 |
<tt>USE master GO -- Create a Queue DECLARE @rc INT DECLARE @TraceID INT DECLARE @maxfilesize BIGINT SET @maxfilesize = 5 -- Please replace the text InsertFileNameHere, with an appropriate -- filename prefixed by a path, e.g., c:\MyFolder\MyTrace. The .trc extension -- will be appended to the filename automatically. If you are writing from -- remote server to local drive, please use UNC path and make sure server has -- write access to your network share EXEC @rc = sp_trace_create @TraceID OUTPUT, 0, N'InsertFileNameHere', @maxfilesize, NULL IF ( @rc != 0 ) GOTO error -- Client side File and Table cannot be scripted -- Set the events DECLARE @on BIT SET @on = 1 EXEC sp_trace_setevent @TraceID, 146, 12, @on EXEC sp_trace_setevent @TraceID, 146, 35, @on -- Set the Filters DECLARE @intfilter INT DECLARE @bigintfilter BIGINT EXEC sp_trace_setfilter @TraceID, 35, 0, 6, N'AdventureWorks2012' -- Set the trace status to start EXEC sp_trace_setstatus @TraceID, 1 -- display trace id for future references SELECT TraceID = @TraceID GOTO finish error: SELECT ErrorCode = @rc finish: -- Stops Capturing Events EXEC sp_trace_setstatus @TraceID, 0 GO -- Delete trace definition from Server EXEC sp_trace_setstatus @TraceID, 2 GO GO</tt> |
Пример сценария сеанса SQL Server Extended Events
Следующий сценарий создаст сессию расширенных событий для отслеживания событий «sqlserver.query_post_execution_showplan», с включением фильтрации по имени базы данных и с использованием кольцевого буфера в качестве цели.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 |
<tt>USE master GO --Create Extended Events Session CREATE EVENT SESSION [Capture_Query_Plan] ON SERVER ADD EVENT sqlserver.query_post_execution_showplan( WHERE ([database_name]=N'AdventureWorks2012')) ADD TARGET package0.ring_buffer WITH ( MAX_MEMORY = 4096 KB , EVENT_RETENTION_MODE = ALLOW_SINGLE_EVENT_LOSS , MAX_DISPATCH_LATENCY = 30 SECONDS , MAX_EVENT_SIZE = 0 KB , MEMORY_PARTITION_MODE = NONE , TRACK_CAUSALITY = OFF , STARTUP_STATE = OFF ) GO --Start Extended Events Session ALTER EVENT SESSION [Capture_Query_Plan] ON SERVER STATE = START GO --Stop Extended Events Session ALTER EVENT SESSION [Capture_Query_Plan] ON SERVER STATE = STOP GO --Drop Extended Events Session DROP EVENT SESSION [Capture_Query_Plan] ON SERVER GO</tt> |
Примеры
Для демонстрации примеров в этой статье я использую базу данных AdventureWorks2012, которую вы можете бесплатно скачать с CodePlex по этой ссылке:
http://msftdbprodsamples.codeplex.com/releases/view/55330
Предположим, у нас есть представленный ниже запрос, давайте посмотрим, что мы можем сделать.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
<tt>USE AdventureWorks2012 GO SET STATISTICS XML ON SELECT * FROM Sales.SalesOrderHeader OH INNER JOIN Sales.SalesOrderDetail OD ON OD.SalesOrderID = OH.SalesOrderID INNER JOIN Sales.Customer C ON C.CustomerID = OH.CustomerID INNER JOIN Production.Product P ON P.ProductID = OD.ProductID INNER JOIN Production.ProductSubcategory PS ON pS.ProductSubcategoryID = P.ProductSubcategoryID GO</tt> |
Расчёт предполагаемого процента завершения
Мы можем получить представление о предполагаемом проценте завершения нашего запроса, глядя на процент выполнения физических операторов в плане запроса. Но вы не найдете эту информацию в колонках DMVsys.dm_exec_query_profiles. Мы должны сделать небольшие математические вычисления с использованием значений в колонках estimate_row_count и row_count, предполагая, что estimate_row_count представляет собой 100 процентов задачи.
Здесь могут возникнуть некоторые проблемы; Надежность этого подхода определяется точностью оценки оптимизатором запросов количества строк данных, и это зависит от того, в каком состоянии во время исполнения запроса находится статистика. Вполне возможно, что используемая оптимизатором статистика окажется переоценённой или недооценённой относительно реальной кардинальности, т.ч. не стоит пугаться, если в результате процент исполнения превысит 100%.
Представленный ниже запрос показывает процент исполнения для каждого физического оператора в плане запроса, число используемых каждым оператором потоков, долю времени активности операторов и зависимых от них объектов, если это применимо.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
<tt>SELECT session_id , node_id , physical_operator_name , SUM(row_count) row_count , SUM(estimate_row_count) AS estimate_row_count , IIF(COUNT(thread_id) = 0, 1, COUNT(thread_id)) [Threads] , CAST(SUM(row_count) * 100. / SUM(estimate_row_count) AS DECIMAL(30, 2)) [% Complete] , CONVERT(TIME, DATEADD(ms, MAX(elapsed_time_ms), 0)) [Operator time] , DB_NAME(database_id) + '.' + OBJECT_SCHEMA_NAME(QP.object_id, qp.database_id) + '.' + OBJECT_NAME(QP.object_id, qp.database_id) [Object Name] FROM sys.dm_exec_query_profiles QP GROUP BY session_id , node_id , physical_operator_name , qp.database_id , QP.OBJECT_ID , QP.index_id ORDER BY session_id , node_id GO</tt> |
Следующий снимок экрана показывает результат исполнения этого запроса для анализа показанного ранее запроса, нуждающегося в профилировании.
Просмотр статуса, ассоциированного с операторами задачи
Можно соединить sys.dm_exec_query_profiles
с sys.dm_os_tasks
иsys.dm_os_waiting_tasks по колонке task_address Посмотрите на следующий запрос:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
<tt>SELECT QP.session_id , QP.node_id , QP.physical_operator_name , DB_NAME(database_id) + '.' + OBJECT_SCHEMA_NAME(QP.object_id, qp.database_id) + '.' + OBJECT_NAME(QP.object_id, qp.database_id) [Object Name] , OT.task_state , MAX(WT.wait_duration_ms) [wait_duration_ms] , WT.wait_type FROM sys.dm_exec_query_profiles QP INNER JOIN sys.dm_os_tasks OT ON OT.task_address = QP.task_address LEFT JOIN sys.dm_os_waiting_tasks WT ON WT.waiting_task_address = QP.task_address GROUP BY QP.session_id , QP.node_id , QP.physical_operator_name , OT.task_state , QP.database_id , QP.object_id , WT.wait_type GO</tt> |
Как можно видеть на скриншоте ниже, для анализируемого в предыдущем примере запроса мы располагаем информацией о состоянии
задачи для каждого физического оператора, его тип ожидания и о продолжительности исполнения, если это применимо.
Просмотр статуса, ассоциированного с операторами задачи
Можно соединить sys.dm_exec_query_profiles с sys.dm_os_tasks и sys.dm_os_waiting_tasks
по колонке task_address Посмотрите на следующий запрос:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
<tt>SELECT QP.session_id , QP.node_id , QP.physical_operator_name , DB_NAME(database_id) + '.' + OBJECT_SCHEMA_NAME(QP.object_id, qp.database_id) + '.' + OBJECT_NAME(QP.object_id, qp.database_id) [Object Name] , OT.task_state , MAX(WT.wait_duration_ms) [wait_duration_ms] , WT.wait_type FROM sys.dm_exec_query_profiles QP INNER JOIN sys.dm_os_tasks OT ON OT.task_address = QP.task_address LEFT JOIN sys.dm_os_waiting_tasks WT ON WT.waiting_task_address = QP.task_address GROUP BY QP.session_id , QP.node_id , QP.physical_operator_name , OT.task_state , QP.database_id , QP.object_id , WT.wait_type GO</tt> |
Как можно видеть на скриншоте ниже, для анализируемого в предыдущем примере запроса мы располагаем информацией о состоянии задачи для каждого физического оператора, его тип ожидания и о продолжительности исполнения, если это применимо.
