Пишу кратко. Может кому-то следующая информация будет полезна и позволит сэкономить время.
Ниже я опишу как с помощью 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.
Будет желание, делитесь полезными замечаниями 
