Замер времени выполнения временных таблиц больших запросов

Итак, поскольку все разрабатываемые/поддерживаемые мною запросы я привык хранить в sel файлах, и обкатывать их в консоли, то я не стал заморачиваться с написанием новой обработки. Я просто добавил кнопку и её обработчик в консоль которой привык пользоваться. Поэтому в данной статье постараюсь описать именно суть моей доработки. А так же поделюсь модифицированной версией вполне стандартной консоли запросов.

Идея.

Однажды в очередной раз столкнувшись с тем, что в новой декаде отчет стал работать дольше чем обычно, я подумал что мне нужен инструмент, который бы мог замерить время выполнения каждого подзапроса (временной таблицы) моего большого запроса. Тогда бы я мог точно знать в чем проблема и как её можно решить. Я долго серфил по Интернету в поисках подобного инструмента. Но так ничего и не нашел. Тогда я стал думать как бы я мог это сделать сам.
Все сводилось к тому что мне надо было разбивать запрос на отдельные составляющие, и отдельно их выполнять засекая время выполнения.
Вариантов реализации в голове крутилось несколько. Но лишь путем проб и ошибок я пришел к тому который оказался реальным.

Разбивка запроса.

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

Текст = ЭлементыФормы.ТекстЗапроса.ПолучитьТекст();

МП = Новый Массив;   //Массив подзапросов
МП.Очистить();

Ш = 0;
Пока Найти(Текст, ";") > 0 Цикл
Текст = ОбрезатьНачалоТекста(Текст);
ПодЗапрос = СокрЛП(Сред(Текст,Найти(Текст,"ВЫБРАТЬ"),Найти(Текст,";") - Найти(Текст,"ВЫБРАТЬ") + 1));
Если НЕ СокрЛП(ПодЗапрос) = "" Тогда
МП.Добавить(ПодЗапрос);
КонецЕсли;

Текст = Сред(Текст, СтрДлина(ПодЗапрос) + 1, СтрДлина(Текст) - СтрДлина(ПодЗапрос) + 1);
Ш = Ш + 1;
Если Ш > 1000 Тогда
Прервать; //предохранитель от зацикливаний
КонецЕсли;
КонецЦикла;

Как видно в коде, я помещаю формирование каждой временной таблицы в массив, как отдельную единицу запроса.
Так же перед началом каждой итерации, я вызываю функцию ОбрезатьНачалоТекста.
Я делаю это для того что бы убрать из текста всевозможные комментарии и другие конструкции которые нам не понадобятся при измерении времени.

Вот код этой функции:

Функция ОбрезатьНачалоТекста(Текст)

Пока Найти(Текст, "ВЫБРАТЬ") > 1 Цикл
Текст = СокрЛ(Сред(Текст, 2));
КонецЦикла;

Если Найти(Текст, "ВЫБРАТЬ") = 0 Тогда
Текст = "";
КонецЕсли;

Возврат Текст;

КонецФункции

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

Создаем такую переменную где будем хранить эти данные. А так же я подготавливаю визуальные компоненты моей консоли запросов для отображения результатов.

ВВП = Новый Структура; //Время выполнения подзапроса
ВВП.Очистить();

//Подготовим ТЧ для отображения замеров времени
РезультатТаблица.Очистить();
РезультатТаблица.Колонки.Очистить();
ЭтаФорма.ЭлементыФормы.ТаблицаРезультата.Колонки.Очистить();
РезультатТаблица.Колонки.Добавить("ИмяПодзапроса");
РезультатТаблица.Колонки.Добавить("Время");

Для Каждого ТекПоле Из РезультатТаблица.Колонки Цикл  //добавим колонки в гриде
ЭтаФорма.ЭлементыФормы.ТаблицаРезультата.Колонки.Добавить(ТекПоле.Имя);
КонецЦикла;
Для Каждого ТекПоле Из ЭтаФорма.ЭлементыФормы.ТаблицаРезультата.Колонки Цикл
ТекПоле.Данные = ТекПоле.Имя;
КонецЦикла;

Теперь начинаем непосредственно процесс замера времени.

//Начинаем в цикле замеры времени.
Для Ш = 0 По МП.Количество() - 1 Цикл

Имя = ПолучитьИмяВременнойТаблицы(МП[Ш]);
ПЗ = Новый Запрос;
ПЗ.Текст = "";
УничтожениеВТ = "";

//На случай если в запросе используется одно имя временной таблицы несколько раз.
//Перед повторным созданием - удаляем отработавший экземпляр
Для Ж = 0 По Ш Цикл
ПризнакИспользованияРанее = Ложь;
Для К = 0 По Ж Цикл
Если ПолучитьИмяВременнойТаблицы(МП[Ж]) = ПолучитьИмяВременнойТаблицы(МП[К]) И НЕ К = Ж Тогда
ПризнакИспользованияРанее = Истина;
КонецЕсли;
КонецЦикла;
Если ПризнакИспользованияРанее Тогда
ПЗ.Текст = ПЗ.Текст + "
|УНИЧТОЖИТЬ " + ПолучитьИмяВременнойТаблицы(МП[Ж]) + ";
|" + МП[Ж];
Иначе
ПЗ.Текст = ПЗ.Текст + "
|" + МП[Ж];
УничтожениеВТ = УничтожениеВТ + "
|УНИЧТОЖИТЬ " + ПолучитьИмяВременнойТаблицы(МП[Ж]) + ";";
КонецЕсли;
КонецЦикла;

ПЗ.Текст = ПЗ.Текст + УничтожениеВТ;

Для Каждого СтрокаПараметров Из мФормаПараметров.Параметры Цикл
Если СтрокаПараметров.ЭтоВыражение Тогда
ПЗ.УстановитьПараметр(СтрокаПараметров.ИмяПараметра, Вычислить(СтрокаПараметров.ЗначениеПараметра));
Иначе
ПЗ.УстановитьПараметр(СтрокаПараметров.ИмяПараметра, СтрокаПараметров.ЗначениеПараметра);
КонецЕсли;
КонецЦикла;

//Засекаем время
ВремяНачалаВыполнения = ТекущаяДата();
Попытка
ПЗ.Выполнить();
Исключение
Сообщить(ОписаниеОшибки());
Возврат;
КонецПопытки;
Затрачено = ТекущаяДата() - ВремяНачалаВыполнения;
ОбщееВремя = ДатуВЧисло(Дата(Формат('19000101'+Затрачено, "ДФ='dd.MM.yyyy HH:mm:ss'")));
Предыдущие = 0;
Для Каждого ТВ Из ВВП Цикл
Предыдущие = Предыдущие + ТВ.Значение;
КонецЦикла;
ТекущееВремя = ОбщееВремя - Предыдущие;
Если ТекущееВремя < 0 Тогда
ТекущееВремя = 0;
КонецЕсли;
ВВП.Вставить(Имя, ТекущееВремя);
Сообщить("Талица: " + Имя + " Время: " + Формат(ЧислоВДату(ТекущееВремя), "ДФ='HH:mm:ss'"));
НС = РезультатТаблица.Добавить();
НС.ИмяПодзапроса = Имя;
НС.Время = Формат(ЧислоВДату(ТекущееВремя), "ДФ='HH:mm:ss'");

КонецЦикла;

Как видно в коде, каждую итерацию цикла замера, мы начинаем с получения имени формируемой временной таблицы, а так же с создания нового запроса и его текста. Говоря о тексте, мы как порядочные люди, помимо того что создаем временные таблицы, должны их по завершению и уничтожать, поэтому в конце запроса мы последовательно уничтожаем все что создано. Но бывает так что в разных частях запроса, могут использоваться одинаковые наименования временных таблиц для разных целей. Для этого организуем вложенный цикл для анализа того, какие временные таблицы мы уже создавали ранее и при необходимости зачищаем не нужные таблицы перед созданием новых с таким же именем. 
А для определения имени текущей временной таблицы мы используем такую не хитрую функцию:

Функция ПолучитьИмяВременнойТаблицы(ПодЗапрос)

Старт = Найти(ПодЗапрос, "ПОМЕСТИТЬ") + 9;
Количество = Найти(ПодЗапрос, "ИЗ") - Старт;
НаименованиеВТ = СокрЛП(Сред(ПодЗапрос, Старт, Количество));

Возврат НаименованиеВТ;

КонецФункции

После того как с текстом запроса все решено и он готов к исполнению, надо заполнить используемые параметры запроса. Здесь для каждой консоли запросов будут свои нюансы, ну а в моем примере решение для моей консольки. Я стандартным способом заполняю параметры запроса теми значениями что указаны пользователем.

Когда текст запроса готов, и все параметры запроса заполнены, самое время выполнить его и проверить, как долго он выполняется.
Для этого я использую вполне известные приемы для замеров времени. Разве что с временем я оперирую на уровне чисел. То есть храню время выполнения и произвожу с ним математические операции как с числом. Для этого я использую пару простейших функций

// Функция преобразует получаемую в параметре дату в формат числа (TDouble)
// Если параметр TDouble установлен в Истина, точка отчета: 30.12.1899 12:00:00 (Традиционно для Delphi)
// Если параметр TDouble установлен в Ложь (по умолчанию), точка отчета: 01.01.1900 00:00:00 (по умолчанию точка отсчета для 1С)
Функция ДатуВЧисло(Знач пДата, TDouble = Ложь)

Возврат ?(TDouble, (пДата - Дата(1899,12,30,12,0,0)) / 86400, (пДата - Дата(1900,01,01,0,0,0)) / 86400);

КонецФункции

Функция ЧислоВДату(Знач пДата, TDouble = Ложь)

Возврат Дата(?(TDouble, Дата(1899,12,30,12,0,0) + (пДата * 86400), Дата(1900,01,01,0,0,0) + (пДата * 86400)));

КонецФункции

Результаты замера времени я вывожу в ту часть формы консоли куда обычно выводится результат запроса. Но для того что бы отслеживать процесс замера динамически и понимать на каком он этапе, я так же использую вывод замеров через «Сообщить». 

Итак, в результате мы получаем в консоли запросов, дополнительную кнопку, которая не просто выполняет запрос, а делает это столько раз, сколько в запросе временных таблиц. И при этом делает замер времени выполнения каждой из них. Таким образом если выяснится что одна из 40 временных таблиц выполняется за 80% общего времени — вы будете знать где необходимо провести оптимизацию. И действия Ваши будут полны решимости и результата.

p.s.
 Лично я для дебага и замеров делаю отдельную версию запроса. В ней я все результирующие таблицы (не временные) так же помещаю во временные таблицы с условными именами вроде ВТ_ДебагN. Так же если общее время выполнения запроса приближено к 15-20-30 минутам, то почем бы не наложить ограничения «ПЕРВЫЕ NNNNN» в ключевых подзапросах, для экономии времени. Но тут стоит понимать что чем больше данных тем более реальной будет картина замера, и некоторые подзапросы с маленьким количеством данных могут попросту не проявить своих тормозов. Поэтому с этим надо осторожно.

Желаю всем правильных и быстро работающих запросов! 🙂 

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