11.09.2015

Высокая загрузка CPU на сервере СУБД MS SQL Server

Наблюдаем высокую загрузку CPU по счетчикам Processor Time на сервере СУБД c MS SQL Server.
Что делать?

Симптом

Видим высокую загрузку CPU на сервере MS SQL Server.

Загрузку видим "сейчас", при этом по данным Performance Monitor, Диспетчера задач или Монитора ресурсов мы уверены, что основную нагрузку создает именно MS SQL Server.

Что требуется сделать

Существует два подхода к получению ответа на вопрос: "Почему и что именно создает такую нагрузку".

Каждый из подходов может оказаться полезным.

Рекомендуется проделать действия, указанные в двух подходах, и применять на практике тот (либо их комбинацию ), который более других подойдет к вашей ситуации.

Подход 1

Подход 2

Подход 1

1. Подключиться к серверу СУБД
2. Запустить MS Sql Server Management Studio
3. Выяснить, какие именно запросы создают нагрузку на CPU.
4. Выяснить, какие именно информационные базы создают нагрузку найденными запросами. Выполнить запросы (см ниже)
5. Проанализировать запросы
   1. Найти базу
   2. Найти запрос в sql
   3. Найти стек кода на встроенном языке, из которого выполняется запрос
6. Если найденный запрос выполняется сейчас несколькими пользователями (в случае, если несколько сеансов приводят к проблеме за счет частого выполнения проблемных запросов)
   1. Найти соответствующие сеансы в консоли администрирования найденной базы по spid
   2. Записать номер сеанса и время начала сеанса
   3. Завершить найденные сеансы
7. Если найденный запрос выполняется периодически множеством пользователей
   1. Понять причину неоптимальной работы запроса
   2. Исправить
8. Проверить, создают ли наиболее часто выполняемые запросы наибольшую нагрузку на CPU
   1. Понять причину неоптимальной работы часто выполняемых запросов
   2. Исправить
9. Получить индексы с высокими издержками при использовании
   1. Понять причину неоптимальной работы часто выполняемых запросов
   2. Исправить
10. Убедиться, что нагрузка на диск упала
11. Понять по журналу регистрации, что именно выполняли завершенные сеансы

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

Например, можно настроить технологический журнал с фильтрами только на один запрос. Может выглядеть так:

<?xml version="1.0" encoding="UTF-8"?>
   <config xmlns="http://v8.1c.ru/v8/tech-log">
   	<log location="С:\Sql_Reads" history="2">
   	<event>
  			<eq property="Name" value="DBMSSQL"/>
   		<like property="Sql" value="%Reference5774%"/>
   		<like property="Sql" value="%SELECT TOP%"/>
   	</event>
   	<property name="all"/>
   	</log>
   	<plansql/>
 	</config>

Смысл в том, чтобы указать такие фильтры

<like property="Sql" value="%Reference5774%"/>

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

Если всё аккуратно сделаете, то в полученном технологическом журнале запрос у вас будет только тот, который нужен.

Журнал получится небольшим.

Собственно стек из кода на встроенном языке будет сразу в конце события с запросом.

Top запросов, создающих нагрузку на CPU на сервере СУБД за последний час

SELECT
SUM(qs.max_elapsed_time) as elapsed_time,
SUM(qs.total_worker_time) as worker_time
into T1 FROM (
       select top 100000
       *
       from
       sys.dm_exec_query_stats qs
       where qs.last_execution_time > (CURRENT_TIMESTAMP - '01:00:00.000')
       order by qs.last_execution_time desc
) as qs
;

select top 10000
(qs.max_elapsed_time) as elapsed_time,
(qs.total_worker_time) as worker_time,
qp.query_plan,
st.text,
dtb.name,
qs.*,
st.dbid
INTO T2
FROM
sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) qp
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) st
left outer join sys.databases as dtb on st.dbid = dtb.database_id
where qs.last_execution_time > (CURRENT_TIMESTAMP - '01:00:00.000')
order by qs.last_execution_time desc
;
select top 100
(T2.elapsed_time*100/T1.elapsed_time) as percent_elapsed_time,
(T2.worker_time*100/T1.worker_time) as percent_worker_time,
T2.*
from
T2 as T2
INNER JOIN T1 as T1
ON 1=1
order by T2.worker_time desc
;
drop table T2
;
drop table T1
;

Нагрузка на CPU по базам

WITH DB_CPU_Stats
AS
(SELECT DatabaseID, DB_Name(DatabaseID) AS [DatabaseName], SUM(total_worker_time) AS [CPU_Time_Ms]
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY (SELECT CONVERT(int, value) AS [DatabaseID]
             FROM sys.dm_exec_plan_attributes(qs.plan_handle)
             WHERE attribute = N'dbid') AS F_DB
GROUP BY DatabaseID)
SELECT ROW_NUMBER() OVER(ORDER BY [CPU_Time_Ms] DESC) AS [row_num],
      DatabaseName, [CPU_Time_Ms],
      CAST([CPU_Time_Ms] * 1.0 / SUM([CPU_Time_Ms]) OVER() * 100.0 AS DECIMAL(5, 2)) AS [CPUPercent]
FROM DB_CPU_Stats
WHERE DatabaseID > 4 -- system databases
AND DatabaseID <> 32767 -- ResourceDB
ORDER BY row_num OPTION (RECOMPILE);

Наибольшая нагрузка на CPU

SELECT TOP 10 
[Average CPU used] = total_worker_time / qs.execution_count
,[Total CPU used] = total_worker_time
,[Execution count] = qs.execution_count
,[Individual Query] = SUBSTRING (qt.text,qs.statement_start_offset/2, 
(CASE WHEN qs.statement_end_offset = -1 
THEN LEN(CONVERT(NVARCHAR(MAX), qt.text)) * 2 
ELSE qs.statement_end_offset END - 
qs.statement_start_offset)/2)
,[Parent Query] = qt.text
,DatabaseName = DB_NAME(qt.dbid)
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as qt
ORDER BY [Average CPU used] DESC;

Наиболее часто выполняемые запросы

SELECT TOP 10 
[Execution count] = execution_count
,[Inpidual Query] = SUBSTRING (qt.text,qs.statement_start_offset/2, 
        (CASE WHEN qs.statement_end_offset = -1 
           THEN LEN(CONVERT(NVARCHAR(MAX), qt.text)) * 2 
         ELSE qs.statement_end_offset END - qs.statement_start_offset)/2)
,[Parent Query] = qt.text
,DatabaseName = DB_NAME(qt.dbid)
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as qt
ORDER BY [Execution count] DESC;

Текущая статистика по задержкам (расшифровка задержек в библиотеке MSDN)

SELECT TOP 10
[Wait type] = wait_type,
[Wait time (s)] = wait_time_ms / 1000,
[% waiting] = CONVERT(DECIMAL(12,2), wait_time_ms * 100.0 
             / SUM(wait_time_ms) OVER())
FROM sys.dm_os_wait_stats
WHERE wait_type NOT LIKE '%SLEEP%' 
ORDER BY wait_time_ms DESC;

Индексы с высокими издержками при использовании

-- Create required table structure only.
-- Note: this SQL must be the same as in the Database loop given in the following step.
SELECT TOP 1
       [Maintenance cost]  = (user_updates + system_updates)
       ,[Retrieval usage] = (user_seeks + user_scans + user_lookups)
       ,DatabaseName = DB_NAME()
       ,TableName = OBJECT_NAME(s.[object_id])
       ,IndexName = i.name
INTO #TempMaintenanceCost
FROM   sys.dm_db_index_usage_stats s
INNER JOIN sys.indexes i ON  s.[object_id] = i.[object_id]
   AND s.index_id = i.index_id
WHERE s.database_id = DB_ID()
   AND OBJECTPROPERTY(s.[object_id], 'IsMsShipped') = 0
   AND (user_updates + system_updates) > 0 -- Only report on active rows.
   AND s.[object_id] = -999  -- Dummy value to get table structure.
;
 
-- Loop around all the databases on the server.
EXEC sp_MSForEachDB    'USE [?];
-- Table already exists.
INSERT INTO #TempMaintenanceCost
SELECT TOP 10
       [Maintenance cost]  = (user_updates + system_updates)
       ,[Retrieval usage] = (user_seeks + user_scans + user_lookups)
       ,DatabaseName = DB_NAME()
       ,TableName = OBJECT_NAME(s.[object_id])
       ,IndexName = i.name
FROM   sys.dm_db_index_usage_stats s
INNER JOIN sys.indexes i ON  s.[object_id] = i.[object_id]
   AND s.index_id = i.index_id
WHERE s.database_id = DB_ID()
   AND i.name IS NOT NULL    -- Ignore HEAP indexes.
   AND OBJECTPROPERTY(s.[object_id], ''IsMsShipped'') = 0
   AND (user_updates + system_updates) > 0 -- Only report on active rows.
ORDER BY [Maintenance cost]  DESC
;
'
-- Select records.
SELECT TOP 10 * FROM #TempMaintenanceCost
ORDER BY [Maintenance cost]  DESC
-- Tidy up.
DROP TABLE #TempMaintenanceCost

Подход 2

1. Подключиться к серверу СУБД. Запустить MS Sql Server Management Studio

2. Выяснить, какие именно базы создают наибольшую нагрузку на сервер СУБД за последний период (в течение которого наблюдается нагрузка). В этом примере период 1 час '01:00:00.000', его нужно будет изменить.

   Копировать в буфер обмена

   WITH DB_CPU_Stats
   AS
   (
   SELECT DatabaseID, DB_Name(DatabaseID) AS [DatabaseName], SUM(total_worker_time) AS [CPU_Time_Ms]
   FROM sys.dm_exec_query_stats AS qs
   CROSS APPLY (SELECT CONVERT(int, value) AS [DatabaseID]
                FROM sys.dm_exec_plan_attributes(qs.plan_handle)
                WHERE attribute = N'dbid') AS F_DB
   WHERE qs.last_execution_time > (CURRENT_TIMESTAMP - '01:00:00.000')
   GROUP BY DatabaseID)
   SELECT ROW_NUMBER() OVER(ORDER BY [CPU_Time_Ms] DESC) AS [row_num],
         DatabaseName, [CPU_Time_Ms],
         CAST([CPU_Time_Ms] * 1.0 / SUM([CPU_Time_Ms]) OVER() * 100.0 AS DECIMAL(5, 2)) AS [CPUPercent]
   FROM DB_CPU_Stats
   WHERE DatabaseID > 4 -- system databases
   AND DatabaseID <> 32767 -- ResourceDB
   ORDER BY row_num OPTION (RECOMPILE);

    

3. Получаем список запросов, которые создали нагрузку за последний час, посчитанный по 10000 запросов. (Выполняется около 2 минут).

   Копировать в буфер обмена

   SELECT
   SUM(qs.max_elapsed_time) as elapsed_time,
   SUM(qs.total_worker_time) as worker_time
   into T1 FROM (
          select top 100000
          *
          from
          sys.dm_exec_query_stats qs
          where qs.last_execution_time > (CURRENT_TIMESTAMP - '01:00:00.000')
          order by qs.last_execution_time desc
   ) as qs
   ;
    
   select top 10000
   (qs.max_elapsed_time) as elapsed_time,
   (qs.total_worker_time) as worker_time,
   qp.query_plan,
   st.text,
   dtb.name,
   qs.*,
   st.dbid
   INTO T2
   FROM
   sys.dm_exec_query_stats qs
   CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) qp
   CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) st
   left outer join sys.databases as dtb on st.dbid = dtb.database_id
   where qs.last_execution_time > (CURRENT_TIMESTAMP - '01:00:00.000')
   order by qs.last_execution_time desc
   ;
   select
   (T2.elapsed_time*100/T1.elapsed_time) as percent_elapsed_time,
   (T2.worker_time*100/T1.worker_time) as percent_worker_time,
   T2.*
   from
   T2 as T2
   INNER JOIN T1 as T1
   ON 1=1
   order by T2.worker_time desc
   ;
   drop table T2
   ;
   drop table T1
   ;

    

   В первую очередь смотрим на percent_worker_time и percent_elapsed_time. Нагрузка не должна быть «размазана» между всеми запросами.

    

   4.1. Если нагрузка "размазана" по запросам, нужно настраивать трассировку

   4.1.1. Для этого на сервере должна быть директория для трассировки.

   Нужно директорию указать вместо 'InsertFileNameHere' в скрипте ниже.

   Размер файла трассировки ограничен 1 Гб.

   Копировать в буфер обмена

   -- Create a Queue
   declare @rc int
   declare @TraceID int
   declare @maxfilesize bigint
   set @maxfilesize = 1024
    
   -- 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, 10, 15, @on
   exec sp_trace_setevent @TraceID, 10, 8, @on
   exec sp_trace_setevent @TraceID, 10, 16, @on
   exec sp_trace_setevent @TraceID, 10, 48, @on
   exec sp_trace_setevent @TraceID, 10, 1, @on
   exec sp_trace_setevent @TraceID, 10, 9, @on
   exec sp_trace_setevent @TraceID, 10, 17, @on
   exec sp_trace_setevent @TraceID, 10, 18, @on
   exec sp_trace_setevent @TraceID, 10, 66, @on
   exec sp_trace_setevent @TraceID, 10, 3, @on
   exec sp_trace_setevent @TraceID, 10, 12, @on
   exec sp_trace_setevent @TraceID, 10, 13, @on
   exec sp_trace_setevent @TraceID, 10, 14, @on
   exec sp_trace_setevent @TraceID, 12, 15, @on
   exec sp_trace_setevent @TraceID, 12, 8, @on
   exec sp_trace_setevent @TraceID, 12, 16, @on
   exec sp_trace_setevent @TraceID, 12, 48, @on
   exec sp_trace_setevent @TraceID, 12, 1, @on
   exec sp_trace_setevent @TraceID, 12, 9, @on
   exec sp_trace_setevent @TraceID, 12, 17, @on
   exec sp_trace_setevent @TraceID, 12, 14, @on
   exec sp_trace_setevent @TraceID, 12, 18, @on
   exec sp_trace_setevent @TraceID, 12, 66, @on
   exec sp_trace_setevent @TraceID, 12, 3, @on
   exec sp_trace_setevent @TraceID, 12, 12, @on
   exec sp_trace_setevent @TraceID, 12, 13, @on
    
   -- Set the Filters
   declare @intfilter int
   declare @bigintfilter bigint
    
   -- 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: 
   go

    

   4.1.2. Останавливаем трассировку, когда уверены, что трассировку собрали в интересующий период нагрузки.

   Копировать в буфер обмена

   exec sp_trace_setstatus @TraceID, 0

    

   4.1.3. Сохраняем трассировку в тестовую БД test в таблицу trace, в которой будем анализировать загрузку.

    

   4.1.4.  Добавляем в таблицу trace две колонки HashSQL varchar(4000) и HashSQLMD5 varbinary(32).

   Копировать в буфер обмена

   ALTER TABLE [test].[dbo].[trace] ADD HashSQL VARCHAR(4000) NULL, HashSQLMD5 varbinary(32) NULL ;

   Затем выполняем:

   Копировать в буфер обмена

   UPDATE  [test].[dbo].[trace] SET [HashSQL] = dbo.fn_GetSQLHash(SUBSTRING([TextData], 1, 4000));
   UPDATE  [test].[dbo].[trace] SET [HashSQLMD5] = HashBytes('MD5', HashSQL);

    

   В качестве альтернативы для этих целей можно использовать курсор:

    

   Копировать в буфер обмена

   DECLARE @RowNumber int
   DECLARE @TextData nvarchar(4000)
   DECLARE @HashSQL nvarchar(4000)
    
    
   DECLARE hash_cursor CURSOR
       FOR SELECT TextData,RowNumber FROM [test].[dbo].[trace]
   OPEN hash_cursor
    
   FETCH NEXT FROM hash_cursor
   INTO @TextData, @RowNumber
    
   WHILE @@FETCH_STATUS = 0
   BEGIN
    
   SET @HashSQL = [test].[dbo].fn_GetSQLHash(@TextData)
    
   UPDATE [test].[dbo].[trace] 
   SET  [HashSQL] = @HashSQL
   ,[HashSQLMD5] = HashBytes('MD5', @HashSQL)
   WHERE RowNumber = @RowNumber
    
   FETCH NEXT FROM hash_cursor 
       INTO @TextData, @RowNumber
   END 
    
   CLOSE hash_cursor
   DEALLOCATE hash_curso

   Листинг fn_GetSQLHash

   Копировать в буфер обмена

   CREATE FUNCTION fn_GetSQLHash(@TSQL nvarchar(4000))  
   RETURNS varchar(4000)  
   AS  
   BEGIN  
    DECLARE @TmpTableName nvarchar(4000)  
    DECLARE @i int  
     
    SET @TmpTableName = ''  
     
    IF (CHARINDEX('#', @TSQL) > 0)  
    BEGIN  
     SET @TmpTableName = SUBSTRING(@TSQL, CHARINDEX('#', @TSQL), 4000)  
     IF (CHARINDEX(' ', @TmpTableName) > 0)  
     BEGIN
       SET @TmpTableName = SUBSTRING(@TmpTableName, 1, CHARINDEX(' ', @TmpTableName) - 1)  
     END
    END  
     
    SET @TSQL = REPLACE ( @TSQL , @TmpTableName , 'TEMPTABLE')  
    SET @TSQL = REPLACE ( @TSQL , ' ' , '')  
    SET @TSQL = REPLACE ( @TSQL , ' ' , '')  
    SET @TSQL = REPLACE ( @TSQL , ' ' , '')  
    SET @TSQL = REPLACE ( @TSQL , 'execsp_executesqlN''' , '')  
    SET @TSQL = REPLACE ( @TSQL , CHAR(10) , '')  
     
    IF (CHARINDEX(''',N''', @TSQL) > 0)  
     SET @TSQL = SUBSTRING(@TSQL, 1, CHARINDEX(''',N''', @TSQL) - 1)  
     
    SET @i = 1  
      
    WHILE @i < 30  
    BEGIN  
     SET @TSQL = REPLACE ( @TSQL , '@P' + CAST(@i AS varchar), '')  
     SET @i = @i + 1  
    END  
     
    SET @TSQL = REPLACE ( @TSQL , '{', '')  
    SET @TSQL = REPLACE ( @TSQL , '}', '')  
    SET @TSQL = REPLACE ( @TSQL , '''', '')  
    SET @TSQL = REPLACE ( @TSQL , '"', '')  
    SET @TSQL = REPLACE ( @TSQL , '.', '')  
    SET @TSQL = REPLACE ( @TSQL , ',', '')  
    SET @TSQL = REPLACE ( @TSQL , ';', '')  
    SET @TSQL = REPLACE ( @TSQL , ':', '')  
    SET @TSQL = REPLACE ( @TSQL , '@', '')  
    SET @TSQL = REPLACE ( @TSQL , '?', '')  
    SET @TSQL = REPLACE ( @TSQL , '=', '')  
    SET @TSQL = UPPER(@TSQL)  
    SET @TSQL = LEFT(@TSQL, 4000)  
     
    RETURN(@TSQL);  
     
   END 

   4.1.5. Анализируем трассировку. Например, смотрим:

   Копировать в буфер обмена

   SELECT TOP 100
      [HashSQL] as HashSQL
         ,SUM([CPU]) as SumCPU
         ,SUM([Reads]) as SumReads
         ,SUM([Writes]) as SumWrites
         ,SUM([Duration]) as SumDuration
         ,[DatabaseID] as DatabaseID
         ,SUM([RowCounts]) as SumRowCounts
     FROM [test].[dbo].[trace]
     WHERE [DatabaseID] = 12345
     GROUP BY 
     [HashSQL]
     ,[DatabaseID]
   ORDER BY SumCPU desc

   Находим наиболее интересные запросы по SUM([CPU]).

   В целом эту же методику можно использовать для поиска по Reads, Writes, Duration,  и т.д.

    

   4.1.6. Для того, чтобы найти запрос в коде конфигурации настраиваем тех журнал вида

   Копировать в буфер обмена

   <?xml version="1.0" encoding="UTF-8"?>
   <config xmlns="http://v8.1c.ru/v8/tech-log">
   <log location="С:\Sql_Reads" history="2">
   <event>
   <eq property="Name" value="DBMSSQL"/>
   <like property="Sql" value="%SELECT TOP%Reference5774%"/>
   </event>
   <property name="all"/>
   </log>
   <plansql/>
   </config>

    

   Где в строке

   Копировать в буфер обмена

   <like property="Sql" value="%SELECT TOP%Reference5774%"/>

   указываем ключевые слова из запроса.

    

   4.1.7. По технологическому журналу определяем лидера, исправляем.

    

   4.2. Если есть явный лидер, лучше начать с этого лидера и повторить алгоритм.

   4.2.1. Для того, чтобы найти запрос в коде конфигурации настраиваем тех журнал вида

   Копировать в буфер обмена

   <?xml version="1.0" encoding="UTF-8"?>
   <config xmlns="http://v8.1c.ru/v8/tech-log">
   <log location="С:\Sql_Reads" history="2">
   <event>
   <eq property="Name" value="DBMSSQL"/>
   <like property="Sql" value="%SELECT TOP%Reference5774%"/>
   </event>
   <property name="all"/>
   </log>
   <plansql/>
   </config>

    

   Где в строке

   Копировать в буфер обмена

   <like property="Sql" value="%SELECT TOP%Reference5774%"/>

   указываем ключевые слова из запроса.

   4.2.2. По технологическому журналу определяем лидера, исправляем в коде конфигурации.

   В собранном технологическом журнале будет искомый запрос с указанием стека на встроенном языке, "откуда" этот запрос выполнялся.