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. По технологическому журналу определяем лидера, исправляем в коде конфигурации.

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