Публикация

Анализ быстродействия CRM с помощью SQL Profiler

Пишу кратко. Может кому-то следующая информация будет полезна и позволит сэкономить время.
Ниже я опишу как с помощью SQL Profiler я смог увидеть какие сервисы и в какой последовательности загружаются при запуске CRM с активным разделом - "Контрагенты". Также я смог получить информацию о времени потраченном при выполнении действий клиентской частью Terrasoft CRM и времени на выполнение запросов к БД.
Действия выполнялись на Terrasoft XRM 3.3.1.146 MS SQL.

Примечание: SQL Profiler-а нет в версии Express MS SQL Server

Шаги по подготовке:
1. CRM должна быть закрыта
2. Чистим папку с кэшем, чтобы увидеть все подтягиваемые сервисы из БД в профайлере.
Путь к папке для версии 3.3.1:
%appdata%\Terrasoft\3.3.1\Cache
3. Запускаем SQL Profiler

Получение трассировки запросов, выполняемых при загрузке CRM:
1. В SQL-Profiler создаем новую трассировку

2. Подключаемся к нашему серверу MS SQL

3. Запускаем трассировку со стандартными настройками:


4. Запускаем CRM и дожидаемся ее полной загрузки
5. Останавливаем трассировку
6. Сохраняем полученную трасировку в таблицу БД:

Подключаемся к базе и указываем базу и таблицу, в которую будут сохранены данные по трасировке.
Я использовал БД "master", владельца "dbo" и таблицу "tbl_trace1":

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

Очистка таблицы от мусора.
Далее, для очистки таблицы от ненужных для меня данных я выполнил следующие запросы на БД "master" в MS SQL Server Management Studio:
1. Удалил записи у которых TextData пустое, ИЛИ поле ApplicationName не равно "TSClient.exe", или Duration пустое, ИЛИ LoginName не равно вашему логину (в моем случае это был 'Supervisor'):

DELETE FROM tbl_trace1
WHERE TextData IS NULL OR Duration IS NULL OR ApplicationName <> 'TSClient.exe' OR LoginName <> 'Supervisor'


2. Удалил не нужные для анализа колонки - EventClass, ApplicationName, NTUserName, LoginName, ClientProcessID, SPID, BinaryData:

 

ALTER TABLE tbl_trace1
DROP COLUMN EventClass, ApplicationName, NTUserName, LoginName, ClientProcessID, SPID, BinaryData

 

 


Извлечение из таблицы трассировки полезной информации для дальнейшего анализа:
1. Добавляем колонки в таблицу:
DiffBetweenSteps - поле будет содержать значение времени в милисекундах, которое прошло между временем окончания выполнения предыдущего запроса и временем начала выполнения текущего запроса. Значение этого поля вмещает в себя время потраченное клиентской частью программы (выполнение скриптов, прорисовка окон и т.д. - все, что выполняется без обращения к серверу БД);
ServiceID и ServiceCode - поля содержащие ID и код сервиса, данные по которому подтягиваются из БД. По этим полям видно в какой последовательности выполняется загрузка сервисов во время запуска CRM;
PrevRowNumber - значение предыдущего по последовательности выполнения запроса, нужно для связки, если будет выполняться сортировка по какому-то полю.

ALTER TABLE tbl_trace1 ADD DiffBetweenSteps int, ServiceID uniqueidentifier, ServiceCode nvarchar(250), PrevRowNumber int


2. Создаем функцию для проверки того, что передаваемое как аргумент значение является GUID-значением и выполняем ее на базе данных "master" (в которой находиться наша таблица трассировки):

 

SET ANSI_NULLS ON
SET QUOTED_IDENTIFIER ON
go

CREATE FUNCTION [dbo].[IsGuid] ( @testString varchar(38))
returns int
AS
begin
    declare @ret int
    SELECT  @ret = 0,
            @testString = REPLACE(REPLACE(@testString, '{', ''), '}', '')
    IF len(isnull(@testString, '')) = 36 AND
       @testString NOT LIKE '%[^0-9A-Fa-f-]%' AND
       -- check for proper positions of hyphens (-)  
       charindex('-', @testString) = 9 AND
       charindex('-', @testString, 10) = 14 AND
       charindex('-', @testString, 15) = 19 AND
       charindex('-', @testString, 20) = 24 AND
       charindex('-', @testString, 25) = 0
          SET @ret = 1
   
    RETURN @ret
end


Эта функция понадобиться в дальнейшем
3. Заполняем значение поля DiffBetweenSteps с помощью следующего sql кода:

 

 

-- Проставляем разницу во времени между окончанием одного запроса и началом выполнения следующего
declare @EndTimePrev datetime
declare @StartTimeNext datetime
declare @EndTimeNext datetime
declare @RowNumber int
declare @DiffBetweenSteps int

SET @EndTimePrev = NULL

declare c_Rec cursor FOR
  SELECT RowNumber, StartTime, EndTime FROM tbl_trace1

OPEN c_Rec
FETCH NEXT FROM c_Rec INTO @RowNumber, @StartTimeNext, @EndTimeNext
WHILE @@FETCH_STATUS=0
BEGIN
        SET @DiffBetweenSteps = DATEDIFF(millisecond, @EndTimePrev, @StartTimeNext)  

        IF (@DiffBetweenSteps IS NULL) SET @DiffBetweenSteps = 0

    UPDATE tbl_trace1
    SET DiffBetweenSteps = @DiffBetweenSteps  
    WHERE RowNumber = @RowNumber
   
    SET @EndTimePrev = @EndTimeNext

    FETCH NEXT FROM c_Rec INTO @RowNumber, @StartTimeNext, @EndTimeNext
END
CLOSE c_Rec
DEALLOCATE c_Rec


4. Заполняем полей ServiceID и ServiceCode с помощью следующего sql кода:

 

 

declare @RowNumber int
declare @ServiceGUID nchar(38)

-- Начиная с 205 позиции вырезаем 38 символов и сохраняем их в переменную @ServiceID
declare c_Rec cursor FOR
  SELECT RowNumber, substring(TextData, 205, 38) FROM tbl_trace1

OPEN c_Rec
FETCH NEXT FROM c_Rec INTO @RowNumber, @ServiceGUID
WHILE @@FETCH_STATUS=0
BEGIN
    -- Проверяем является ли вырезанный кусок текста GUID-значением
    IF (SELECT dbo.IsGuid(@ServiceGUID)) = 1
                BEGIN
                        -- Есди - да, то вытягиваем по полученому ID сервиса его код из рабочей базы CRM
                        UPDATE tbl_trace1
                        SET ServiceID = @ServiceGUID, ServiceCode = (SELECT Code FROM XRM.dbo.tbl_Service WHERE ID = @ServiceGUID)
                        WHERE RowNumber = @RowNumber           
                END
        ELSE
                BEGIN
                        UPDATE tbl_trace1
                        SET ServiceID = NULL, ServiceCode = ''
                        WHERE RowNumber = @RowNumber           
                END

    FETCH NEXT FROM c_Rec INTO @RowNumber, @ServiceGUID
END
CLOSE c_Rec
DEALLOCATE c_Rec

 

 

В коде

SELECT Code FROM XRM.dbo.tbl_Service WHERE ID = @ServiceGUID


вместо названия БД 'XRM' вам нужно указать название вашей рабочей CRM базы.

 

Поскольку запрос на полученние данных сервиса выглядит следующим образом:

exec sp_executesql N'SELECT TOP 1
        [tbl_Service].[ID] AS [ID],
        [tbl_Service].[XMLData] AS [XMLData]
FROM
        [dbo].[tbl_Service] AS [tbl_Service]
WHERE([tbl_Service].[ID] = @P1)'
,N'@P1 nvarchar(38)',N'{64A6CED0-5C42-481F-97CA-C9632144B101}'


, где в конце указывается значение ID сервиса, то по этому ID мы можем получать необходимые данные о загружаемом сервисе, такие как код сервиса, его местонахождение в дереве сервисов и т.д. Для себя мы возьмем только код сервиса, чтобы наглядно было видно какой сервис запрашивается из БД.
5. Проставляем значение предыдущего шага в поле PrevRowNumber

 

-- Простановка предыдущего шага
declare @PrevRowNumber int
declare @RowNumber int

SET @PrevRowNumber = 0

declare c_Rec cursor FOR
  SELECT RowNumber FROM tbl_trace1

OPEN c_Rec
FETCH NEXT FROM c_Rec INTO @RowNumber
WHILE @@FETCH_STATUS=0
BEGIN
    UPDATE tbl_trace1
    SET PrevRowNUmber = @PrevRowNumber  
    WHERE RowNumber = @RowNumber
   
    SET @PrevRowNumber = @RowNumber

    FETCH NEXT FROM c_Rec INTO @RowNumber
END
CLOSE c_Rec
DEALLOCATE c_Rec


6. В итоге, с помощью SQL-запроса

 

 

SELECT RowNumber, TextData, CPU, Reads, Writes, Duration/(1000) AS Duration_t, StartTime, EndTime, ServiceCode, DiffBetweenSteps, PrevRowNumber
FROM tbl_trace1


выводим следующую таблицу:

7. Также можно выполнить сортировки по разным колонкам и увидеть:

 

 

 

SELECT RowNumber, TextData, CPU, Reads, Writes, Duration/(1000) AS Duration_t, StartTime, EndTime, ServiceCode, DiffBetweenSteps, PrevRowNumber
FROM tbl_trace1
ORDER BY CPU DESC

 

SELECT RowNumber, TextData, CPU, Reads, Writes, Duration/(1000) AS Duration_t, StartTime, EndTime, ServiceCode, DiffBetweenSteps, PrevRowNumber
FROM tbl_trace1
ORDER BY Duration_t DESC

 

SELECT RowNumber, TextData, CPU, Reads, Writes, Duration/(1000) AS Duration_t, StartTime, EndTime, ServiceCode, DiffBetweenSteps, PrevRowNumber
FROM tbl_trace1
ORDER BY DiffBetweenSteps DESC
  • каке запросы сколько используют процессорного времени в милисекундах на их выполнение

  • Выводимая таблица:

     

  • какие запросы дольше всего выполнялись, отсортировав по полю Duration. Значение в поле Duration храниться в микросекундах, делю на 1000, чтобы выводилось в милисекундах:

  • Выводимая таблица:

     

  • увидеть между какими запросами дольше всего происходили операции на стороне клиента, что поможет локализировать место в работе клиентской части Террасофт, которое требует больше всего времени на выполнение:

  • Выводимая таблица:

     

  • поля Reads и Writes показывают количество логических чтений и записей с жесткого диска на сервере во время выполнения события (запроса)

8. Также можно подсчитать общее время на выполнение запросов (ServerDuration), общее время на выполнение клиентской частью (ClientDuration), общее время на запуск CRM (OverallDuration):

SELECT Sum(Duration)/1000 AS ServerDuration, Sum(DiffBetweenSteps) AS ClientDuration, Sum(Duration/1000+DiffBetweenSteps) AS OverallDuration
FROM tbl_trace1


Выводимое значение:

 

Аналогичным образом можно анализировать не только процесс запуска CRM, а любое выполняемое действие с CRM, например, открытие окна редактирования.

Прикрепил SQL код, используемый мною - SLQ_code.txt
В архиве прикрепил картинки в их исходном размере - Images.zip.

Будет желание, делитесь полезными замечаниями :smile:

Поделиться

0 комментариев
Войдите или зарегистрируйтесь, чтобы комментировать