27.07.2016
Видим высокую загрузку CPU на сервере MS SQL Server, при этом в результате анализа на уровне СУБД не удалось установить источник проблемы. Например, имеется большое количество разных запросов, нагрузка от каждого из которых сравнительно небольшая.
Загрузку видим "сейчас", при этом по данным Performance Monitor, Диспетчера задач или Монитора ресурсов мы уверены, что основную нагрузку создает именно MS SQL Server.
Невозможность установить источник высокой нагрузки может быть связана с тем, что в конфигурации присутствуют большие пакетные запросы. При этом на уровне СУБД эти пакеты разбиваются на большое количество сравнительно небольших запросов, влияние каждого из которых на общую нагрузку невелико.
Другая возможная причина - динамическое формирование текстов запросов в коде конфигурации. Это также приводит к тому, что на уровне СУБД один запрос делится на несколько, с пропорциональным размыванием нагрузки между отдельными запросами.
Для расследования необходимо сгруппировать запросы по какому-то признаку. На практике хорошо работает группировка по строкам контекста конфигурации, из которых были вызваны запросы. Также может оказаться полезной группировка запросов по пользователям информационной базы, действия которых инициировали запрос или по сеансам этих пользователей.
Суть методики заключается в параллельном сборе трассировки запросов на сервере СУБД и технологического журнала 1С:Предприятия, с последующим объединением и агрегацией данных.
Для обеспечения возможности объединения данные технологического журнала выгружаются на СУБД с помощью скрипта на perl, и далее запросы нормализуются путем удаления всех переменных и незначащих элементов (например, имен временных таблиц, имен параметров, пробелов, переносов строк), с последующим вычислением хэша MD5 от полученной в результате нормализации строки. После этого запросы трассировки группируются по хэшам, и в процессе группировки вычисляются средние значения по колонкам "Duration", "CPU", "Reads" и "Writes". Полученные данные объединяются с данными технологического журнала, и используются для оценки влияния каждого из контекстов на процессор или диск.
Поскольку тот или иной код конфигурации может быть вызван различными способами (в разных контекстах), то для анализа используются только первая и последняя строка полного стека вызова.
Для того, чтобы собрать данные для расследования, необходимо:
1. Проанализировать, какая база данных, расположенная на сервере, создает наибольшую нагрузку.
2. Подготовить файл настройки технологического журнала logcfg.xml с отбором по событиям DBMSSQL и по имени информационной базы. Сбор планов запросов включать не нужно.
3. Подготовить скрипт для сбора трассировки на сервере СУБД.
Для этого:
4. Синхронно включить сбор трассировки (выполнить подготовленный скрипт) и сбор технологического журнала (поместить подготовленный файл logcfg.xml в каталог настроек сервера 1С:Предприятия).
Трассировку рекомендуется включать до начала сбора ТЖ, чтобы собрать данные по всем тем запросам, которые попадут в технологический журнал.
5. Через заданное время сбор трассировки завершится автоматически. Синхронно отключить сбор технологического журнала.
6. Создать базу на сервере СУБД для выгрузки таблиц трассировок и контекстов, например, базу "_Traces". В этой базе создать функцию хэширования с помощью шаблона Создание функции хэширования.sql
7. Выгрузить собранную трассировку в таблицу на SQL-сервере, например, в таблицу "Trace".
Для этого воспользуйтесь шаблоном скрипта Загрузка трассировки в таблицу.sql.
В шаблоне необходимо задать имя таблицы, в которую будет выгружаться трассировка, и указать путь к файлу с собранной трассировкой.
8. В той же базе создать таблицу для выгрузки контекстов с помощью шаблона Создание таблицы контекстов.sql
9. Выгрузить собранный технологический журнал в таблицу контекстов.
Для этого необходимо:
cat <ПутьКСобранномуТехнологическомуЖурналу> | perl <ПутьКСкрипту> ,
где:
Узнать текущий каталог в среде Cygwin можно с помощью команды pwd.
10. Выполнить хэширование таблицы трассировки.
Для этого необходимо:
11. Выполнить хэширование таблицы контекстов.
Для этого необходимо:
Для анализа собранных данных необходимо:
Копировать в буфер обмена«%SELECT% T1._Fld13230RRef% FROM dbo._InfoRg13229 T1% T1._Fld13230RRef = @P3%».
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);
Пример файла logcfg.xml с отбором по событиям DBMSSQL и имени информационной базы
Копировать в буфер обмена<?xml version="1.0"?> <ns:config xmlns:ns="http://v8.1c.ru/v8/tech-log"> <ns:log history="4" location="C:\Logs\DBMSSQL"> <ns:event> <ns:eq property="Name" value="DBMSSQL"/> <ns:eq property="p:processName" value="ИмяИнформационнойБазы"/> </ns:event> <ns:property name="All"/> </ns:log> </ns:config>Копировать в буфер обмена
-- Create a Queue declare @rc int declare @TraceID int declare @DataBaseID int declare @DurationMin int declare @maxfilesize bigint declare @TraceFileName nvarchar(256) set @DurationMin = <ДлительностьСбораТрассировки> -- Длительность сбора трассировки в минутах set @maxfilesize = <МаксимальныйРазмерФайла> -- Максимальный размер файла трассировки в Мб set @DataBaseID = <НомерБД> set @TraceFileName = N'<ПутьКФайлуТрассировки>' -- Укажите максимальный размер файла трассировки в Мб, -- идентификатор базы данных и имя файла трассировки, например c:\MyFolder\MyTrace. -- Расширение ".trc" в имени файла трассировки добавится автоматически. -- Можно использовать сетевой каталог (предварительно нужно убедиться, что -- у службы сервера SQL есть права на запись в этот каталог) ----------------------------------------------- -- Получить состояние трассировки: --select * from sys.fn_trace_getinfo(@traceid) -- Остановить трассировку: --exec sp_trace_setstatus @traceid, 0 -- Повторно запустить трассировку: --exec sp_trace_setstatus @traceid, 1 -- Закрыть трассировку и удалить ее определение с сервера: --exec sp_trace_setstatus @traceid, 2 declare @stop_time datetime = DateAdd(mi, @DurationMin, GetDate()) print '@stop_time = ' + cast(@stop_time as varchar(100)) exec @rc = sp_trace_create @TraceID output, 0, @TraceFileName, @maxfilesize, @stop_time if (@rc != 0) goto error print @TraceID -- Client side File and Table cannot be scripted -- Set the events declare @on bit set @on = 1 -- RPC:Completed exec sp_trace_setevent @TraceID, 10, 1, @on -- TextData exec sp_trace_setevent @TraceID, 10, 3, @on -- DatabaseID exec sp_trace_setevent @TraceID, 10, 12, @on -- SPID exec sp_trace_setevent @TraceID, 10, 13, @on -- Duration exec sp_trace_setevent @TraceID, 10, 14, @on -- StartTime exec sp_trace_setevent @TraceID, 10, 15, @on -- EndTime exec sp_trace_setevent @TraceID, 10, 16, @on -- Reads exec sp_trace_setevent @TraceID, 10, 17, @on -- Writes exec sp_trace_setevent @TraceID, 10, 18, @on -- CPU -- SQL:BatchCompleted exec sp_trace_setevent @TraceID, 12, 1, @on -- TextData exec sp_trace_setevent @TraceID, 12, 3, @on -- DatabaseID exec sp_trace_setevent @TraceID, 12, 12, @on -- SPID exec sp_trace_setevent @TraceID, 12, 13, @on -- Duration exec sp_trace_setevent @TraceID, 12, 14, @on -- StartTime exec sp_trace_setevent @TraceID, 12, 15, @on -- EndTime exec sp_trace_setevent @TraceID, 12, 16, @on -- Reads exec sp_trace_setevent @TraceID, 12, 17, @on -- Writes exec sp_trace_setevent @TraceID, 12, 18, @on -- CPU -- Set the Filters declare @intfilter int declare @bigintfilter bigint set @intfilter = @DataBaseID exec sp_trace_setfilter @TraceID, 3, 0, 0, @intfilter -- 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
Шаблон Создание функции хэширования.sql
Копировать в буфер обменаUSE [_Traces]
GO
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE FUNCTION [dbo].[fn_GetSQLHash](@TSQL nvarchar(max))
RETURNS varchar(4000)
AS
BEGIN
DECLARE @i int
DECLARE @length int
DECLARE @Template as nvarchar(50)
DECLARE @Cnt int
IF (CHARINDEX('#', @TSQL) > 0)
BEGIN
SET @Cnt = 8
WHILE @Cnt > 0
BEGIN
SET @Template = '%#tt' + REPLICATE('[0-9]', @Cnt) + '%'
set @i = 1;
set @length = 3+@Cnt;
while @i > 0
begin
set @i = patindex(@Template, @TSQL);
if @i > 0
set @TSQL = stuff(@TSQL, @i, @length, '#TempTable');
end;
SET @Cnt = @Cnt - 1
END
END
SET @TSQL = REPLACE ( @TSQL , ' ' , '')
SET @TSQL = REPLACE ( @TSQL , 'execsp_executesqlN''' , '')
SET @TSQL = REPLACE ( @TSQL , CHAR(10) , '')
SET @TSQL = REPLACE ( @TSQL , CHAR(13) , '')
IF (CHARINDEX(''',N''', @TSQL) > 0)
SET @TSQL = SUBSTRING(@TSQL, 1, CHARINDEX(''',N''', @TSQL) - 1)
IF (CHARINDEX('@', @TSQL) > 0)
BEGIN
SET @Cnt = 4
WHILE @Cnt > 0
BEGIN
SET @Template = '%@P' + REPLICATE('[0-9]', @Cnt) + '%'
set @i = 1;
set @length = @Cnt+2;
while @i > 0
begin
set @i = patindex(@Template, @TSQL);
if @i > 0
set @TSQL = stuff(@TSQL, @i, @length, '');
end;
SET @Cnt = @Cnt - 1
END
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
Шаблон Загрузка трассировки в таблицу.sql
Копировать в буфер обменаUSE [_Traces]
select TextData,
BinaryData,
DatabaseID,
SPID,
Duration,
StartTime,
EndTime,
Reads,
Writes,
CPU
INTO dbo.Trace
from ::fn_trace_gettable(N'<ПутьКФайлуТрассировки>', default)
Шаблон Создание таблицы контекстов.sql Копировать в буфер обменаUSE [_Traces] GO SET ANSI_NULLS ON GO SET QUOTED_IDENTIFIER ON GO CREATE TABLE [dbo].[Contexts]( [Id] [bigint] IDENTITY(1,1) NOT NULL, [Duration] [bigint] NULL, [ContextFirstLine] [nvarchar](max) NULL, [ContextLastLine] [nvarchar](max) NULL, [Sql] [nvarchar](max) NULL, [Usr] [nvarchar](100) NULL, [SessionID] [nvarchar](50) NULL ) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY] GO CREATE UNIQUE NONCLUSTERED INDEX [By_id] ON [dbo].[Contexts] ( [Id] ASC )WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, SORT_IN_TEMPDB = OFF, IGNORE_DUP_KEY = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY] GO
Скрипт parse_contexts_to_file.sql
Копировать в буфер обмена#!/usr/bin/perl
use utf8;
use strict;
use Encode qw(decode encode);
open(file_events,"> events.csv");
flock(file_events,2);
my $old_point=select(file_events);
my $counter = 0;
my $event;
my %actions = (
'DBMSSQL' => [
{
'action' => sub {
my ($event) =@_;
# Получение длительности события
my $duration;
my($date, $garbage) = split /,DBMSSQL/, $event;
if ($date =~ /^\d{2}:\d{2}\.\d+-(\d+)/) {
$duration = $1;
}
# Получение текста запроса из свойства "Sql"
my ($garbage, $Sql) = split /Sql="/, $event;
if ($Sql) {
($Sql, $garbage) = split /"/, $Sql;
if ($Sql =~ /^{call sp_executesql\(N'/) {
$Sql =~ s/^{call sp_executesql\(N'//g;
}
if ($Sql =~ /.*', N'.*/) {
($Sql, $garbage) = split /', N'/, $Sql;
}
$Sql =~ s/'/''/g;
} else {
($garbage, $Sql) = split /Sql='/, $event;
($Sql, $garbage) = split /'/, $Sql;
}
($Sql, $garbage) = split /\np_0:/, $Sql;
my ($garbage, $SessionID) = split /SessionID=/, $event;
my ($SessionID, $garbage) = split /,/, $SessionID;
$SessionID = 0 if (!$SessionID);
# Получение прочих свойств
my ($garbage, $Usr) = split /Usr=/, $event;
my ($Usr, $garbage) = split /,/, $Usr;
$Usr = "Platform" if (!$Usr);
my ($garbage, $context) = split /Context=/, $event;
if ($context =~ /^[^'"].*,/) {
$context =~ s/,.*//g;
}
my $context_first_line;
my $context_last_line;
if ($context =~ /\n/) {
my @mlc = split /\n/, $context;
$context_last_line = $mlc[$#mlc];
$context_first_line = $mlc[0]; #($mlc[0] =~ s/^\s+|'$//g);
$context_first_line =~ s/^\s+|'$//g;
if (!$context_first_line && $context_last_line) {
$context_first_line = $mlc[1];
}
}
$context_first_line =~ s/^\s+|'$//g;
$context_first_line =~ s/'//g;
$context_first_line = "" unless ($context_first_line);
my $utf_cntx_first_line = encode('cp1251', decode('utf8', $context_first_line));
$context_last_line =~ s/^\s+|'$//g;
$context_last_line =~ s/'//g;
$context_last_line = "" unless ($context_last_line);
my $utf_cntx_last_line = encode('cp1251', decode('utf8', $context_last_line));
my $utf_Usr = encode('cp1251', decode('utf8', $Usr));
my $utf_Sql = encode('cp1251', decode('utf8', $Sql));
if ($utf_Sql) {
print "$counter$duration$utf_cntx_first_line$utf_cntx_last_line$utf_Sql$utf_Usr$SessionID";
$counter++;
}
},
},
],
);
while (<>) {
$event=process_event($event) if /^\d\d:\d\d\.\d+/;
$event .= $_;
}
# Обработка последней строки
process_event($event) if ($event =~ m/^\d\d:\d\d\.\d+/);
select($old_point);
close(file_events);
sub process_event($) {
my ($event) = @_;
return unless $event;
foreach my $event_type ( keys %actions ) {
next unless $event =~ /^[^,]+,$event_type,/;
foreach my $issue ( @{ $actions{$event_type} }) {
&{$issue->{action}}($event);
}
}
}
Шаблон Загрузка техжурнала в таблицу.sql
Копировать в буфер обмена
USE [_Traces]
IF columnproperty(object_id('Contexts'),'HashSQL','AllowsNull') IS NOT NULL
ALTER TABLE Contexts DROP COLUMN HashSQL
IF columnproperty(object_id('Contexts'),'HashSQLMD5','AllowsNull') IS NOT NULL
ALTER TABLE Contexts DROP COLUMN HashSQLMD5
BULK INSERT dbo.[Contexts]
FROM '<ПутьКФайлу>\events.csv'
WITH
(
FIELDTERMINATOR ='',
ROWTERMINATOR ='',
CODEPAGE = 1251
);
Шаблон Хэширование таблицы трассировки.sql
Копировать в буфер обменаUSE [_Traces]
GO
IF columnproperty(object_id('Trace'),'HashSQL','AllowsNull') IS NOT NULL
ALTER TABLE Trace DROP COLUMN HashSQL
IF columnproperty(object_id('Trace'),'HashSQLMD5','AllowsNull') IS NOT NULL
ALTER TABLE Trace DROP COLUMN HashSQLMD5
ALTER TABLE [dbo].[Trace] ADD HashSQL VARCHAR(4000) NULL, HashSQLMD5 varbinary(32) NULL;
GO
DECLARE @ROW_COUNT int
DECLARE @PACKET_SIZE int
SET @PACKET_SIZE = 10000
SET @ROW_COUNT = @PACKET_SIZE
WHILE (@ROW_COUNT = @PACKET_SIZE)
BEGIN
UPDATE TOP (@PACKET_SIZE) [dbo].Trace SET [HashSQL] = [dbo].fn_GetSQLHash(TextData) WHERE [HashSQL] IS NULL
SET @ROW_COUNT = @@ROWCOUNT
END
----------------------------------------------------------------------------------------------------
SET @PACKET_SIZE = 100000
SET @ROW_COUNT = @PACKET_SIZE
WHILE (@ROW_COUNT = @PACKET_SIZE)
BEGIN
UPDATE TOP (@PACKET_SIZE) [dbo].Trace SET [HashSQLMD5] = HashBytes('MD5', HashSQL) WHERE [HashSQLMD5] IS NULL
SET @ROW_COUNT = @@ROWCOUNT
END
Шаблон Хэширование таблицы контекстов.sql Копировать в буфер обмена
USE [_Traces]
GO
IF columnproperty(object_id('Contexts'),'HashSQL','AllowsNull') IS NOT NULL
ALTER TABLE Contexts DROP COLUMN HashSQL
IF columnproperty(object_id('Contexts'),'HashSQLMD5','AllowsNull') IS NOT NULL
ALTER TABLE Contexts DROP COLUMN HashSQLMD5
ALTER TABLE [dbo].[Contexts] ADD HashSQL VARCHAR(4000) NULL, HashSQLMD5 varbinary(32) NULL;
GO
DECLARE @ROW_COUNT int
DECLARE @PACKET_SIZE int
SET @PACKET_SIZE = 10000
SET @ROW_COUNT = @PACKET_SIZE
WHILE (@ROW_COUNT = @PACKET_SIZE)
BEGIN
UPDATE TOP (@PACKET_SIZE) [dbo].Contexts SET [HashSQL] = [dbo].fn_GetSQLHash(sql) WHERE [HashSQL] IS NULL
SET @ROW_COUNT = @@ROWCOUNT
END
----------------------------------------------------------------------------------------------------
SET @PACKET_SIZE = 100000
SET @ROW_COUNT = @PACKET_SIZE
WHILE (@ROW_COUNT = @PACKET_SIZE)
BEGIN
UPDATE TOP (@PACKET_SIZE) [dbo].Contexts SET [HashSQLMD5] = HashBytes('MD5', HashSQL) WHERE [HashSQLMD5] IS NULL
SET @ROW_COUNT = @@ROWCOUNT
END
Шаблон Агрегация трассировки.sql
Копировать в буфер обменаUSE [_Traces]
GO
SELECT sum([Duration]) / count([HashSQLMD5]) as Duration
,sum([Reads]) / count([HashSQLMD5]) as Reads
,sum([Writes]) / count([HashSQLMD5]) as Writes
,sum([CPU]) / count([HashSQLMD5]) as CPU
,[HashSQLMD5]
INTO [dbo].[TraceAvg]
FROM [dbo].[Trace]
GROUP BY [HashSQLMD5]
Копировать в буфер обменаUSE [_Traces]
GO
DECLARE @TotalCPU bigint
SELECT
Contexts.[ContextLastLine],
sum(TraceAvg.CPU) as CPU,
(100 * sum(TraceAvg.CPU) / @TotalCPU) as WeightCPU
INTO #Tmp1
FROM [dbo].[Contexts] as Contexts
LEFT JOIN [dbo].[TraceAvg] as TraceAvg
ON Contexts.[HashSQLMD5] = TraceAvg.[HashSQLMD5]
GROUP BY Contexts.[ContextLastLine]
SET @TotalCPU = (SELECT SUM(CPU) FROM #Tmp1)
SELECT
Tmp1.[ContextLastLine],
Tmp1.CPU as CPU,
(100 * Tmp1.CPU / @TotalCPU) as WeightCPU
FROM #Tmp1 as Tmp1
ORDER BY CPU desc
DROP TABLE #Tmp1
SELECT
Contexts.[ContextFirstLine],
sum(TraceAvg.CPU) as CPU,
(100 * sum(TraceAvg.CPU) / @TotalCPU) as WeightCPU
INTO #Tmp2
FROM [dbo].[Contexts] as Contexts
LEFT JOIN [dbo].[TraceAvg] as TraceAvg
ON Contexts.[HashSQLMD5] = TraceAvg.[HashSQLMD5]
GROUP BY Contexts.[ContextFirstLine]
SET @TotalCPU = (SELECT SUM(CPU) FROM #Tmp2)
SELECT
Tmp2.[ContextFirstLine],
Tmp2.CPU as CPU,
(100 * Tmp2.CPU / @TotalCPU) as WeightCPU
FROM #Tmp2 as Tmp2
ORDER BY CPU desc
DROP TABLE #Tmp2
Шаблон Получение плана запроса по тексту.sql Копировать в буфер обменаSELECT TOP 10 total_worker_time/execution_count AS [Avg CPU Time],
qs.plan_generation_num,
qp.query_plan,
SUBSTRING(st.text, (qs.statement_start_offset/2)+1,
((CASE qs.statement_end_offset
WHEN -1 THEN DATALENGTH(st.text)
ELSE qs.statement_end_offset
END - qs.statement_start_offset)/2) + 1) AS statement_text
FROM sys.dm_exec_query_stats AS qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) AS st
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) as qp
WHERE UPPER(st.text) like '<ОтборПоТекстуЗапроса>'
ORDER BY creation_time DESC;
Анализ запросов по контексту.sql
Копировать в буфер обменаuse [_Traces] SELECT sum(t2.reads) as sum_reads, t2.HashSQLMD5 FROM Contexts as t1 INNER JOIN Trace as t2 ON t1.HashSQLMD5 = t2.HashSQLMD5 where contextlastline = N'<СтрокаКонтекста>' GROUP by t2.HashSQLMD5 order by sum_reads desc creation_time DESC;