Проблема запросов и процедур

Поиск причин снижения производительности в нервозной обстановке, то есть в окружении менеджеров, инженеров, разработчиков, а порой и кого-нибудь из руководства, часто приводит к неверным решениям из-за недостатка диагностических данных, а также к пропуску части данных, необходимых для того, чтобы дать обоснованные рекомендации.

Недавно я столкнулся с примером такой ситуации, работая с администратором баз данных клиента. Решая некую задачу для этой компании, я получил сообщение, суть которого состояла в следующем: «Взгляните на этот запрос, от которого исходит больше двух миллиардов операций чтения к базе данных».

Такое сообщение заслуживает внимания! Я просмотрел результаты запроса. Метаданные выглядели несколько подозрительно и были неполными. Запрос действительно приводил к огромному числу операций чтения, но они выполнялись по завершении последней очистки метаданных DMV или после удаления плана запроса из кэша (в зависимости от того, какое событие произошло позже). Не каждое выполнение запроса приводило к двум миллиардам операций чтения, но таким был уровень активности в течение срока его жизни. Кроме того, в предоставленном наборе результатов недоставало метрик для выводов — отсутствовали XML код плана выполнения и метаданные счетчика выполнений (наряду с другими полезными метриками) для принятия решения. Я обратился за пояснениями к администратору баз данных, и мне был предоставлен другой набор результатов с планом запроса и инструкциями выполнения. Но когда я начал разбираться в происходящем, мне не удалось понять, где план запроса неверно взаимодействует с буферным пулом и диском, запрашивая эти страницы. На данном этапе я составил собственный исчерпывающий запрос и направил его экземпляру. В итоге у меня появились совершенно новое представление о проблеме и цель для изучения.

Инструментарий для работы

Важно, чтобы администратор базы данных располагал необходимым инструментарием (сценариями) для выполнения работы. Мы принимали неверные решения из-за ограниченного набора сценариев, который направлял нас по ложному следу. Я предложил администратору баз данных воспользоваться инструментом из моего комплекта, который будет описан ниже. В сущности, это два запроса на основе двух различных динамических административных представлений: одно ориентировано на статистику выполнения запросов, а другое изолирует метрики выполнения только для хранимых процедур. Правильно используя два сценария, вы получите исчерпывающее представление запросов и хранимых процедур, которые вызывают больше всего проблем с экземпляром. Этими проблемами могут быть:

большое число операций чтения;
большое число операций записи;
увеличенное время выполнения;
высокая нагрузка на процессор.

Эти два сценария настраиваются для каждого случая простым снятием комментариев с соответствующего предложения ORDER BY. Кроме того, в каждом сценарии можно снять комментарии с предложения WHERE, а затем заменить шаблонный параметр для фильтрации по имени базы данных, если нужно сузить область с уровня экземпляра до базы данных. В каждом запросе будут возвращены все статистические данные, относящиеся к:

описательной идентификации (имя, код, планы запросов);
действиям по чтению (логическим или физическим);
действиям по записи;
исторической информации по количеству возвращенных строк;
метрикам процессора;
времени выполнения, счетчикам, продолжительности.

В случае анализа запроса вы также получите данные о продолжительности существования кэша планов. Затем из этой информации выделяются минимальные, максимальные, средние и итоговые значения для каждой подкатегории.

Код запроса и тестовые результаты

Ниже приведен код для обоих аналитических запросов — сначала ориентированный на запросы, а следом предназначенный исключительно для хранимых процедур. Размер кода довольно велик, но вам не составит труда скопировать и вставить его в свой сценарий (естественно, полностью под вашу ответственность). Я даже поместил эти запросы в хранимые процедуры. Как всегда, я изменяю результаты, чтобы не раскрывать сведений о моих клиентах. Метрики взяты из практических применений, но все планы, код выполнения инструкций и имена изменены. Для лучшего отображения результатов я сначала экспортировал их в Excel.

Анализ требовательных запросов для экземпляра SQL Server приведен в листинге 1. Ядро этого запроса взято из динамического административного представления sys.dm_exec_procedure_stats, в котором хранятся данные о каждом кэшированном запросе, выполняемом в экземпляре.

После выполнения мы видим результаты (разделенные мною на категории), представленные на экранах 1-8. Первые два столбца повторяются только для удобства чтения исчерпывающих результатов.

Экран 1. Информация о процессоре

Экран 2. Информация о времени выполнения

Экран 3. Информация о логических операциях чтения

Экран 4. Информация о физических операциях чтения

Экран 5. Информация о записи

Экран 6. Информация о возвращенных строках

Экран 7. Информация о кэшировании и выполнении

Экран 8. Информация о коде и плане

Анализ требовательных хранимых процедур для экземпляра SQL Server представлен в листинге 2. Ниже рассматривается код и результаты запроса, направленного к динамическому административному представлению sys.dm_exec_procedure_stats. Некоторые столбцы не включены в это динамическое административное представление в отличие от родственного DMV в основе предшествующего запроса, поэтому результирующие столбцы немного иные.

Как и в описанном выше случае выполнения сценария, результаты (разделенные мною на категории) представлены на экранах 9-15. Первые два столбца повторяются только для удобства чтения исчерпывающих результатов.

Экран 9. Идентификация процедуры и счетчик выполнения

Экран 10. Информация о процессоре

Экран 11. Информация о времени выполнения

Экран 12. Информация о логических операциях чтения

Экран 13. Информация о физических операциях чтения

Экран 14. Информация об операциях записи

Экран 15. Информация о выполнении и коде или плане процедуры

Как мы видим, вновь динамические административные представления играют роль исчерпывающего источника информации для диагностики проблем SQL Server (конечно, начиная с версии SQL Server 2005). Именно поэтому такие конструкции представляют собой мой излюбленный компонент SQL Server, а компания Microsoft продолжает совершенствовать и расширять объекты динамического управления в каждом выпуске своих продуктов.

Листинг 1. Анализ требовательных запросов

SELECT TOP 25 db_name(eST.[dbid]) AS [database]
        , eQS.execution_count

        -- ПРОЦЕССОР
        , eQS.min_worker_time AS [min_cpu]
        , eQS.max_worker_time AS [max_cpu]
        , eQS.total_worker_time/ISNULL(eQS.execution_count, 1)
                AS [avg_cpu]
        , eQS.last_elapsed_time AS [last_cpu]
        , eQS.total_worker_time AS [total_cpu]

        -- ЗАТРАЧЕННОЕ ВРЕМЯ
        , eQS.min_elapsed_time AS [min_duration]
        , eQS.max_elapsed_time AS [max_duration]
        , eQS.total_elapsed_time/ISNULL(eQS.execution_count, 1)
                AS [avg_duration]
        , eQS.last_elapsed_time AS [last_duration]
        , eQS.total_elapsed_time AS [total_duration] 

        -- ЛОГИЧЕСКИЕ ОПЕРАЦИИ ЧТЕНИЯ
        , eQS.min_logical_reads AS [min_logical_reads]
        , eQS.max_logical_reads AS [max_logical_reads]
        , eQS.total_logical_reads/ISNULL(eQS.execution_count, 1)
                AS [avg_logical_reads]
        , eQS.last_logical_reads AS [last_logical_reads]
        , eQS.total_logical_reads

        -- ФИЗИЧЕСКИЕ ОПЕРАЦИИ ЧТЕНИЯ
        , eQS.min_physical_reads AS [min_physical_reads]
        , eQS.max_physical_reads AS [max_physical_reads]
        , eQS.total_physical_reads/ISNULL(eQS.execution_count, 1)
                AS [avg_physical_reads]
        , eQS.last_physical_reads AS [last_physical_reads]
        , eQS.total_physical_reads

        -- ЛОГИЧЕСКИЕ ОПЕРАЦИИ ЗАПИСИ
        , eQS.min_logical_writes AS [min_writes]
        , eQS.max_logical_writes AS [max_writes]
        , eQS.total_logical_writes/ISNULL(eQS.execution_count, 1)
                AS [avg_writes]
        , eQS.last_logical_writes AS [last_writes]
        , eQS.total_logical_writes AS [total_writes]

        -- ПОДСЧЕТ СТРОК
        , eQS.min_rows AS [min_rows]
        , eQS.max_rows AS [max_rows]
        , eQS.total_rows/ISNULL(eQS.execution_count, 1) AS [avg_rows]
        , eQS.last_rows AS [last_rows]
        , eQS.total_rows

        -- КЭШ И ВРЕМЯ ВЫПОЛНЕНИЯ
        , eQS.last_execution_time
        , eQS.creation_time
        , DATEDIFF(Minute, eQS.creation_time, GetDate())
                AS 'minutes_in_cache'
        , eQS.execution_count/ISNULL(DATEDIFF(Minute, NULLIF
                (eQS.creation_time,0), GetDate()), 1) AS [calls/minute]
        , eQS.execution_count/ISNULL(DATEDIFF(Second, NULLIF
                (eQS.creation_time,0), GetDate()), 1) AS [calls/second]


        -- ПОДРОБНОСТИ ИНСТРУКЦИЙ И ТЕКСТА ЗАПРОСА
        , eST.text AS [batch_text]
        , SUBSTRING
                (
                        eST.text, (eQS.statement_start_offset/2) + 1
                                ,
                                        (
                                                (
                                                      CASE eQS.statement_end_offset 
                                                              WHEN -1 THEN
                                                              DATALENGTH(eST.text) 
                                                              ELSE eQS.statement_end_offset 
                                                        END
                                                                - eQS.statement_start_offset
                                                )/2
                                        ) + 1
                ) AS [statement_executing]
        , eQP.[query_plan]
        , eQS.[plan_handle]
FROM sys.dm_exec_query_stats AS eQS 
        CROSS APPLY sys.dm_exec_sql_text(eQS.sql_handle) AS eST 
        CROSS APPLY sys.dm_exec_query_plan (eQS.plan_handle) AS eQP
WHERE db_name(eST.[dbid]) = ''
--ORDER BY eQS.total_logical_reads/ISNULL(eQS.execution_count, 1) DESC;
         -- [avg_logical_reads]
--ORDER BY eQS.total_physical_reads/ISNULL(eQS.execution_count, 1) DESC;
        -- [avg_physical_reads]
--ORDER BY eQS.total_logical_writes/ISNULL(eQS.execution_count, 1) DESC;
        -- [avg_logical_writes]
--ORDER BY eQS.total_worker_time/ISNULL(eQS.execution_count, 1) DESC;
           -- [avg_cpu]
--ORDER BY eQS.total_elapsed_time/ISNULL(eQS.execution_count, 1) DESC;
          -- [avg_duration]
--ORDER BY eQS.total_rows/ISNULL(eQS.execution_count, 1) DESC;
                         -- [avg_rows]

Листинг 2. Анализ требовательных хранимых процедур

SELECT TOP 25 db_name(eST.[dbid]) AS [database]
        , OBJECT_SCHEMA_NAME(ePS.[object_id], ePS.database_id)
                AS [schema_name]
        , OBJECT_NAME(ePS.[object_id], ePS.database_id)
                AS [procedure_name]
        , ePS.execution_count

        -- ПРОЦЕССОР
        , ePS.min_worker_time AS [min_cpu]
        , ePS.max_worker_time AS [max_cpu]
        , ePS.total_worker_time/ISNULL(ePS.execution_count, 1)
                AS [avg_cpu]
        , ePS.last_elapsed_time AS [last_cpu]
        , ePS.total_worker_time AS [total_cpu]

        -- ЗАТРАЧЕННОЕ ВРЕМЯ
        , ePS.min_elapsed_time AS [min_duration]
        , ePS.max_elapsed_time AS [max_duration]
        , ePS.total_elapsed_time/ISNULL(ePS.execution_count, 1)
                AS [avg_duration]
        , ePS.last_elapsed_time AS [last_duration]
        , ePS.total_elapsed_time AS [total_duration] 

        -- ЛОГИЧЕСКИЕ ОПЕРАЦИИ ЧТЕНИЯ
        , ePS.min_logical_reads AS [min_logical_reads]
        , ePS.max_logical_reads AS [max_logical_reads]
        , ePS.total_logical_reads/ISNULL(ePS.execution_count, 1)
                AS [avg_logical_reads]
        , ePS.last_logical_reads AS [last_logical_reads]
        , ePS.total_logical_reads

        -- ФИЗИЧЕСКИЕ ОПЕРАЦИИ ЧТЕНИЯ
        , ePS.min_physical_reads AS [min_physical_reads]
        , ePS.max_physical_reads AS [max_physical_reads]
        , ePS.total_physical_reads/ISNULL(ePS.execution_count, 1)
                AS [avg_physical_reads]
        , ePS.last_physical_reads AS [last_physical_reads]
        , ePS.total_physical_reads

        -- ЛОГИЧЕСКИЕ ОПЕРАЦИИ ЗАПИСИ
        , ePS.min_logical_writes AS [min_writes]
        , ePS.max_logical_writes AS [max_writes]
        , ePS.total_logical_writes/ISNULL(ePS.execution_count, 1)
                AS [avg_writes]
        , ePS.last_logical_writes AS [last_writes]
        , ePS.total_logical_writes AS [total_writes]

        -- КЭШ И ВРЕМЯ ВЫПОЛНЕНИЯ
        , ePS.last_execution_time

        -- ПОДРОБНОСТИ ИНСТРУКЦИЙ И ТЕКСТА ЗАПРОСА
        , eST.text AS [procedure_code]
        , ePS.[plan_handle]

FROM sys.dm_exec_procedure_stats AS ePS 
        CROSS APPLY sys.dm_exec_sql_text(ePS.sql_handle) AS eST 
        CROSS APPLY sys.dm_exec_query_plan (ePS.plan_handle) AS eQP
WHERE db_name(eST.[dbid]) = ''
ORDER BY ePS.total_logical_reads/ISNULL(ePS.execution_count, 1) DESC;
           -- [avg_logical_reads]
--ORDER BY ePS.total_physical_reads/ISNULL(ePS.execution_count, 1) DESC;
        -- [avg_physical_reads]
--ORDER BY ePS.total_logical_writes/ISNULL(ePS.execution_count, 1) DESC;
        -- [avg_logical_writes]
--ORDER BY ePS.total_worker_time/ISNULL(ePS.execution_count, 1) DESC;
           -- [avg_cpu]
--ORDER BY ePS.total_elapsed_time/ISNULL(ePS.execution_count, 1) DESC;
          -- [avg_duration]
--ORDER BY ePS.total_rows/ISNULL(ePS.execution_count, 1) DESC;
                          -- [avg_rows]