Диагностика медленных запросов в 1С: от технологического журнала до плана в SSMS

Разрабатываю отчёт, проверяю на тестовых данных — всё быстро. Передаю заказчику — три минуты ожидания. Знакомая ситуация. Первый инстинкт — переписать запрос, добавить индекс, сузить период. Это угадывание, и оно редко помогает с первой попытки. За несколько лет я выработал маршрут, который по моему опыту даёт конкретный ответ за 10–15 минут без привлечения DBA: читать не 1С-код, а план выполнения SQL-запроса, в который платформа его превращает.

Почему отчёт тормозит — и при чём здесь SQL

Тяжёлый расчёт при выполнении запроса происходит в СУБД, а не в коде 1С. Платформа транслирует 1С-запрос в SQL и передаёт его MS SQL Server или PostgreSQL — весь расчёт выполняется там. Тормозит, как правило, тоже там.

Есть три основных сценария деградации. Первый — неоптимальный текст запроса: оптимизатор строит плохой план из-за структуры самого запроса. Второй — устаревшая статистика СУБД: оптимизатор оценивает количество строк неверно и выбирает неподходящий алгоритм соединения. Третий — нагрузка на дисковую подсистему: запрос написан нормально, но сервер физически не успевает читать данные. Статья про первый сценарий — он целиком в руках разработчика.

По симптомам можно примерно понять, куда смотреть в первую очередь. Если тормозит только при конкретных параметрах — например, для одного склада — похоже на parameter sniffing, плохой план под конкретное значение; смотреть plan cache в SSMS или событие DBMSSQL в ТЖ. Если тормозит всегда, вне зависимости от параметров — вероятнее неоптимальная структура запроса или отсутствующий предикат в виртуальной таблице, тут поможет связка ТЖ и плана в SSMS или pgAdmin. Если тормозит только под нагрузкой или по ночам — это уже похоже на конкуренцию за блокировки или I/O, смотреть sys.dm_os_wait_stats и счётчики производительности. А если было быстро и стало медленно после обновления базы — скорее всего устарела статистика или поменялся план, решается через UPDATE STATISTICS и sp_recompile.

Шаг 1. Найти виновный запрос через технологический журнал

Технологический журнал — штатный инструмент платформы, описанный в документации ИТС в разделе «Технологический журнал». Он фиксирует события платформы вместе с временными характеристиками. Нас интересуют два типа событий: SDBL — запрос на языке 1С до трансляции, и DBMSSQL / DBPOSTGRS — уже в SQL, с реальным временем выполнения на стороне СУБД.

Минимальный конфиг, который не разрастётся до нескольких десятков гигабайт за ночь: история хранится один час (history="1"), фильтр — только запросы длиннее 10 секунд. В платформе 8.3 начиная примерно с версии 8.3.8 значение Duration указывается в микросекундах, поэтому 10 секунд = 10 000 000 (точное поведение для вашей версии стоит свериться с документацией ИТС к конкретному релизу).

⚠️ ЗДЕСЬ СПОЙЛЕР (оформить кнопкой «Спойлер» в редакторе Хабра, заголовок: «logcfg.xml — минимальный конфиг технологического журнала»):

<?xml version="1.0" encoding="UTF-8"?>

<config xmlns="http://v8.1c.ru/v8/tech-log">

  <log location="C:\logs\tl" history="1">

    <event>

      <eq property="Name" value="SDBL"/>

      <gt property="Duration" value="10000000"/>

    </event>

    <event>

      <eq property="Name" value="DBMSSQL"/>

      <gt property="Duration" value="10000000"/>

    </event>

  </log>

</config>

⚠️ КОНЕЦ СПОЙЛЕРА

Для PostgreSQL — заменить DBMSSQL на DBPOSTGRS, синтаксис тот же. Файл кладётся в каталог conf рабочей директории сервера 1С. В типовой установке 1С:Предприятие 8.3 на Windows это обычно C:\Program Files\1cv8\conf\logcfg.xml; точный путь проверяйте по параметрам запуска службы ragent или в документации ИТС к конкретной версии. Платформа перечитывает файл примерно раз в минуту — перезапускать сервис не нужно.

После воспроизведения медленного отчёта в папке C:\logs\tl появятся файлы вида YYYYMMDDHHMMSS.log. Пример строки из журнала:

00:05:43.241011-11234567,DBMSSQL,5,process=rphost,p:processName=1cv8s,

SessionID=1234,Usr=Иванов,

sql=SELECT T1._Fld157RRef,T1._Fld158,SUM(T1._Fld223) FROM _AccumRg223 T1

    GROUP BY T1._Fld157RRef,T1._Fld158,

Rows=48291,RowsAffected=48291

Ключевые поля: первое число после временной метки — Duration в микросекундах; sql — сырой SQL-запрос; SessionID — для поиска смежных событий; Rows — количество возвращённых строк. Порог в 10 секунд ориентировочный: если SLA отчёта — 5 секунд, имеет смысл снизить до 5000000. На нагруженном сервере слишком низкий порог быстро заполнит диск.

Шаг 2. Вытащить SQL и получить план в SSMS / pgAdmin

SQL из поля sql в журнале — фрагмент реального батча, который платформа отправила в СУБД. Запустить его напрямую не всегда получится: 1С активно использует временные таблицы (#tt1, #tt2 и подобные), которые создаются в рамках сессии и к моменту чтения журнала уже уничтожены.

-- Так выглядит фрагмент из ТЖ с временной таблицей

INSERT INTO #tt1 (_f1, _f2)

SELECT Reference157.IDRRef, Reference157.Description

FROM _Reference157

WHERE Reference157.Fld3456 = @P1

Два рабочих способа получить исполняемый план. Первый: в консоли запросов 1С:Предприятие нажать кнопку «Показать запрос» — платформа отобразит SQL-текст с контекстом, его можно скопировать в SSMS. Второй: в SSMS (версия 18+) найти полный батч через sys.dm_exec_sessions по SessionID прямо в момент выполнения тяжёлого отчёта.

В SSMS перед запуском добавить:

SET STATISTICS IO ON;

SET STATISTICS TIME ON;

И включить «Include Actual Execution Plan» (Ctrl+M). Запрос выполнится и вернёт план с метриками — в том числе Logical reads: число страниц, прочитанных из буферного пула.

В pgAdmin:

EXPLAIN (ANALYZE, BUFFERS, FORMAT TEXT)

SELECT ... -- ваш запрос

BUFFERS показывает количество блоков из shared buffers и с диска — аналог Logical/Physical reads в MS SQL.

Как 1С транслирует объекты метаданных в SQL

Физические имена таблиц SQL зависят от внутреннего номера объекта метаданных — именно поэтому имена вроде _AccumRg223 непонятны без дополнительного контекста. Посмотреть соответствие можно через SSMS Object Explorer или утилитой v8unpack.

Справочник разворачивается в таблицу Reference<N> прямым SELECT, без подзапроса. С регистрами сложнее: СрезПоследних() на регистре сведений (таблица InfoRg<N>) превращается в подзапрос с ROW_NUMBER() OVER (PARTITION BY <измерения> ORDER BY Period DESC) на MS SQL — на PostgreSQL похожая логика через оконную функцию, конкретный вид плана зависит от версии платформы. Остатки() на регистре накопления (AccumRg<N>) — это подзапрос с GROUP BY и агрегатами по всей таблице или за указанный период, а Обороты() — SELECT SUM(...) GROUP BY по диапазону дат.

Ключевой момент: SQL для виртуальных таблиц содержит вложенный подзапрос. Условия, приписанные снаружи через ГДЕ, применяются к результату этого подзапроса — внутрь они не проникают. Это и есть источник главного антипаттерна, который разберём дальше на конкретном примере.

Поведение СрезПоследних() на MS SQL и PostgreSQL различается в деталях реализации. Это стоит проверять на реальной тестовой базе: выполнить запрос с виртуальной таблицей и сравнить планы в обоих окружениях, если они доступны.

Читаем план: три плохих паттерна

Открытый план выполнения — дерево операторов. Каждый узел — шаг обработки данных. Смотреть нужно на ширину стрелок (объём данных между узлами) и на жёлтые предупреждения в свойствах узла.

Первый паттерн — Table Scan или Index Scan вместо Index Seek: в плане видна иконка «Clustered Index Scan» с высоким estimated cost. Типичная 1С-причина — условие наложено снаружи виртуальной таблицы, и оптимизатор не видит предикат внутри подзапроса. Лечится передачей условия параметром виртуальной таблицы в скобках. Второй — Nested Loop на больших наборах: в плане тысячи выполнений внешней ветки, потому что один из источников не отфильтрован до соединения; помогает добавить отбор до соединения или перенести условие в параметры виртуальной таблицы. Третий, самый неприятный — Hash Match Spill: узел Hash Match с предупреждением, в свойствах SSMS Spill Level больше нуля. Значит промежуточный результат не помещается в память и сбрасывается на tempdb или диск — если проблема системная, а не разовая, это уже задача DBA по настройке памяти, а не запроса.

Про Hash Match Spill: MS SQL фиксирует это через Extended Events (события hash_warning и sort_warning) — подробная спецификация в разделе «Extended Events» на Microsoft Learn; в SSMS спилл виден в свойствах узла плана как «Spill Level > 0». Одиночный спилл — не катастрофа, но если он происходит при каждом запуске отчёта — время выполнения кратно вырастает из-за дисковых операций. Ориентир по Logical Reads на запрос к регистру с 1 млн строк: до 10 000 страниц — приемлемо, 50 000+ — повод изучить план. Общепринятого норматива нет, цифра из практики.

Главная ловушка — условие снаружи виртуальной таблицы

Условие ГДЕ, наложенное снаружи виртуальной таблицы, не попадает внутрь подзапроса СУБД — это главная причина Table Scan на регистре. Разберу на конкретном примере: запрос к остаткам товаров на складе, который кажется логичным.

// Плохой вариант

ВЫБРАТЬ

    Ост.Склад,

    Ост.Номенклатура,

    Ост.КоличествоОстаток

ИЗ

    РегистрНакопления.ТоварыНаСкладах.Остатки КАК Ост

ГДЕ

    Ост.Склад = &Склад

Что происходит в СУБД: платформа разворачивает Остатки() в подзапрос, который суммирует всю таблицу _AccumRg<N> с GROUP BY. Предикат Склад = &Склад применяется к результату подзапроса. Сканируется весь регистр — независимо от того, что нужен один склад.

Исправленный вариант:

// Хороший вариант

ВЫБРАТЬ

    Ост.Склад,

    Ост.Номенклатура,

    Ост.КоличествоОстаток

ИЗ

    РегистрНакопления.ТоварыНаСкладах.Остатки(&Период, Склад = &Склад) КАК Ост

Условие Склад = &Склад передаётся параметром виртуальной таблицы. Платформа включает его внутрь подзапроса с GROUP BY — оптимизатор получает предикат на нужном уровне и может использовать индекс.

Фрагмент плана до исправления (pgAdmin, текстовый формат):

->  Hash Aggregate  (cost=18432.00..18500.00 rows=68 ...)

      ->  Seq Scan on "_AccumRg223" t1  (cost=0.00..16800.00 rows=832000 ...)

Фрагмент плана после:

->  Hash Aggregate  (cost=312.00..315.00 rows=12 ...)

      ->  Index Scan using "_AccumRg223_ByDim_RRR" on "_AccumRg223" t1

            (cost=0.10..290.00 rows=240 ...)

            Index Cond: ("_Fld157RRef" = $1)

832 000 строк против 240 строк. Разница в три минуты ожидания объясняется именно этим. То же правило работает для СрезПоследних() и Обороты() — условия нужно передавать в скобках, а не накладывать снаружи через ГДЕ. В СКД это задаётся через параметры виртуальной таблицы в свойствах набора данных.

Чеклист — диагностика за 10 минут

Весь маршрут укладывается в шесть шагов. Сначала включить технологический журнал через logcfg.xml на сервере 1С — файлы должны появиться в папке за 1-2 минуты, если их нет, проверить путь и права. Дальше воспроизвести отчёт и найти запрос: искать по *.log слово DBMSSQL, смотреть на поле Duration — кандидат на разбор это то, что больше 5 000 000 мкс. Затем получить SQL через консоль запросов 1С, кнопку «Показать запрос» — важно проверить, нет ли среди виртуальных таблиц таких, что используются без параметров. Открыть план в SSMS (Ctrl+M) или через pgAdmin EXPLAIN ANALYZE и смотреть на операторы Scan, Nested Loop, Hash Match — Scan на большой таблице сразу красный флаг. Проверить паттерны через Plan Explorer или pgAdmin: Logical Reads, Spill, широкие стрелки между узлами — если Logical Reads выше 50 000, стоит смотреть дальше. И последний шаг — замерить ещё раз через ТЖ после правки и сравнить Duration до и после; по опыту, улучшение в 3-10 раз достижимо без привлечения DBA.

Когда без DBA не обойтись

Разработчик упирается в стену в трёх ситуациях — и во всех трёх дальше без прав на СУБД не продвинуться.

Устаревшая статистика: оптимизатор оценивает 100 строк вместо 1 000 000, выбирает Nested Loop там, где нужен Hash Join. Нужен UPDATE STATISTICS AccumRg<N> (MS SQL) или ANALYZE (PostgreSQL). Требуются права dbowner на уровне СУБД.

Отсутствующий индекс: если виртуальная таблица с параметрами всё равно сканирует данные — возможно, нет составного индекса по нужным измерениям. Создание индекса — DDL. Для штатных регистров 1С это исключительный случай: платформа создаёт индексы автоматически при реструктуризации, но кастомные конфигурации иногда приводят к нестандартным сочетаниям измерений.

PostgreSQL не пробрасывает предикат во вложенный подзапрос СрезПоследних(). Это известное поведение, связанное с тем, как PostgreSQL обрабатывает оконные функции внутри подзапросов — предикат снаружи не «протекает» вниз. Решение — материализовать промежуточный результат во временную таблицу или использовать QProcessing (настройка уровня сервера, задача DBA).

Что передать DBA в виде задачи:

• SQL-запрос из ТЖ — поле sql.

• Скриншот или XML плана с отмеченным узлом-аномалией.

• Метрику: Duration и Logical Reads до и после попытки исправления.

• Версию платформы (p:processName из ТЖ) и версию СУБД (SELECT @@VERSION в MS SQL).

• Время воспроизведения и имя пользователя из ТЖ — для поиска смежных событий.

Отдельно стоит проговорить пару моментов, которые обычно всплывают на этом этапе. ЕстьNull(Поле, ЗначениеПоУмолчанию) транслируется в ISNULL() (MS SQL) или COALESCE() (PostgreSQL) и почти не влияет на план, если не применяется к индексируемому столбцу в условии ГДЕ — для отбора лучше явная проверка ГДЕ Таблица.Поле ЕСТЬ NULL, оптимизатор обрабатывает её предсказуемее. А МЕЖДУ транслируется в BETWEEN и используется оптимизатором для диапазонного сканирования по индексу, если поле в него входит — для дат в регистрах накопления это стандартный способ ограничить период, и точно так же, как с условием на склад, МЕЖДУ &НачалоПериода И &КонецПериода нужно передавать параметром самой виртуальной таблицы, а не через ГДЕ снаружи.