948 секунд против 66: что делать, когда висит отчет, и как перестать гадать

UPD 23.10.2026. Исправлены единицы порога в фильтре техжурнала: в logcfg.xml свойство duration задается в сотнях микросекунд, 20 секунд это value="200000". Подробности в разделе про техжурнал. Спасибо triviumfan за поправку.

Составной отчет, наш обзор сезона, формировался 15 минут. Он собирает данные из других отчетов блока через одну функцию ТаблицаОтчета(...), и первое желание было понятным: отключать разделы по одному и смотреть, какой тормозит. Это долго и ничего не гарантирует. Вместо этого rac показал, что сеанс занят запросом к СУБД, а техжурнал с порогом длительности за один прогон назвал виновника: один SQL на 240 секунд и точную строку модуля, откуда он пришел. После переписывания одного вложенного отчета обзор стал собираться за 66 секунд вместо 948.

В статье «89 минут против 6: реструктуризация большой серверной базы» rac и опознание своих rphost были вспомогательным шагом. Здесь с них все начинается.

Стенд: 1С:Бухгалтерия предприятия КОРП 3.0, платформа 8.5.1, серверная база на MSSQL. На машине несколько кластеров разных версий.

Первый шаг: rac session list

Слово «висит» описывает четыре разных состояния: сервер выполняет запрос, сервер ничего не делает и ждет клиента, клиента уже нет, а вызов идет, или мешает фоновое задание. Лечатся они по-разному, и одна команда отделяет их друг от друга.

У нашего кластера 8.5 служба RAS постоянно не запущена, поэтому поднимаем ее на время. Версия ras и rac должна совпадать с версией кластера: RAS соседнего кластера другой версии тут не поможет.

$bin = "C:\Program Files\1cv8\8.5.1.1507\bin"

Start-Process "$bin\ras.exe" -ArgumentList 'cluster','--port=5545','localhost:5540' -WindowStyle Hidden

& "$bin\rac.exe" cluster list localhost:5545

& "$bin\rac.exe" session list --cluster=<uuid> localhost:5545

Если у кластера заведен администратор, добавьте --cluster-user и --cluster-pwd. Из длинного вывода по сеансу нужны несколько полей. Вот одна из сессий того дня:

session-id            : 63

calls-all             : 78

db-proc-info          : "56"

duration-all-dbms     : 261347

duration-current      : 391235

duration-current-dbms : 129172

cpu-time-current      : 1484

Время в миллисекундах. duration-current показывает, сколько длится текущий серверный вызов (здесь 391 секунда), duration-current-dbms сколько длится текущее обращение к СУБД внутри него (129 секунд). db-proc-info дает номер соединения на SQL Server, тот же dbpid потом встретится в техжурнале. Если оба времени растут от замера к замеру, сервер занят запросом, и дальше нужен техжурнал.

Неприятная деталь, которая объясняет «сервер тормозит у всех»: когда клиент отваливается по таймауту или его закрывают, вызов на сервере продолжает выполняться. Это не зависание, это тот же долгий SQL, только без получателя. Пользователь не дождался, запустил отчет снова и добавил второй такой же вызов. В нашем списке было несколько сессий с duration-current около шести минут одновременно. Снимать такие сеансы можно штатно, через rac session terminate или консоль кластера, но сначала убедитесь, что это действительно ваш отчет, а не чья-то проводка.

И еще одна проверка, на которой легко потерять час: при нескольких кластерах на машине загрузка процессора rphost ничего не значит, пока вы не опознали свои процессы по версии платформы в пути и порту -regport. Команда для этого есть в предыдущей статье.

Техжурнал с порогом: текст SQL и строка BSL

Прямого доступа к SQL Server у нас на стенде не было: под Windows-учеткой sqlcmd не пускал, представления DMV недоступны. Техжурнал оказался не запасным путем, а единственным, и при этом лучшим: в нем есть то, чего DMV не покажут, стек вызовов BSL.

Делаем копию logcfg.xml в каталоге bin\conf нужной версии платформы и добавляем к существующей конфигурации отдельный временный журнал:

<log location="D:\1C_TJ_SQL" history="24">

  <event>

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

    <gt property="duration" value="200000"/>

  </event>

  <event>

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

    <gt property="duration" value="200000"/>

  </event>

  <property name="all"/>

</log>

Длительность в микросекундах, 20 000 000 означает 20 секунд.

UPD 23.10.2026, исправление. В фильтре logcfg.xml свойство duration задается в сотнях микросекунд, поэтому 20 секунд это value="200000". Для микросекунд есть отдельное свойство durationus. А в самой строке журнала длительность пишется в микросекундах (-239572998 ниже это 240 секунд), отсюда и наша путаница. Ошибку нашел в комментариях triviumfan, спасибо. Мы перепроверили по протоколу той диагностики: с порогом 20000000, то есть 2000 секунд, журнал за 11 минут работы отчета не записал ни одного события, а виновника поймал порог 1000000, то есть 100 секунд.

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

Мелочь, на которой можно споткнуться: если править файл из bash через heredoc, последовательность \1 в пути D:\1C_TJ_SQL превращается в управляющий символ, и журнал молча пишет непонятно куда. Правьте через PowerShell ([IO.File]::WriteAllText) и перечитывайте результат. После диагностики верните файл из копии.

Запустили отчет, дождались, открыли журнал rphost. Событие выглядело так (сокращено):

11:26.787000-239572998,DBMSSQL,4,level=DEBUG,process=rphost,...,AppID=1CV8C,...,Trans=0,dbpid=56,Sql='SELECT

...

FROM (SELECT DISTINCT

(CAST(DATEPART(YEAR, T2._Fld48141) AS NUMERIC(4)) - 2000) AS Q_001_F_000_

FROM dbo._AccumRg48136 T2 WHERE ...) T1

INNER JOIN (SELECT DISTINCT ... FROM dbo._AccumRg48136 T4 ...) T3

ON 1=1

LEFT OUTER JOIN (SELECT ... GROUP BY (CAST(DATEPART(YEAR, T7._Fld48141) ...) T6

ON (T1.Q_001_F_000_ = T6.Q_001_F_000_) AND ...

',Rows=14,RowsAffected=-1,Context='...

  Отчет.<Обзор>.МодульМенеджера : 1861 : Дан.Вставить("РаботыПоСадам", ТаблицаОтчета("<ОтчетПоРаботам>", ...));

    Отчет.<Обзор>.МодульМенеджера : 633 : Вывод.Вывести(Процессор);'

Число после дефиса в начале строки и есть длительность: 239 572 998 микросекунд, почти 240 секунд. Поле Context дает стек до строки: обзор, строка 1861, вызов ТаблицаОтчета для конкретного вложенного отчета. Следующее событие в журнале пришло со строки 1862, тот же отчет в другом разрезе, еще 244 секунды. Перебором разделов мы бы это искали долго.

По тексту SQL видна и причина. Вложенный отчет считал год через ГОД(День) и соединял «все годы» со «всеми ключами» (ON 1=1), а затем с подзапросом агрегатов по выражению от даты, без временной таблицы. Результат 14 строк, а работы на четыре минуты. Запрос переписали на временные таблицы с отбором по дате, и обзор целиком ускорился с 948 до 66 секунд.

Пакет запросов: замер по временным таблицам

Если тормозит один отчет на СКД с длинным пакетом, техжурнал покажет SQL, но сопоставить его с конкретной временной таблицей бывает трудно: имена в SQL обезличены. Проще замерить каждую часть пакета отдельно, с общим менеджером временных таблиц.

Части = СтрРазделить(ТекстПакета, ";");

МВТ = Новый МенеджерВременныхТаблиц;

Лог = Новый Массив;

Для Каждого Часть Из Части Цикл

    Если ПустаяСтрока(Часть) Тогда Продолжить; КонецЕсли;

    Запрос = Новый Запрос(Часть);

    Запрос.МенеджерВременныхТаблиц = МВТ;

    Запрос.УстановитьПараметр("НачалоПериода", НачалоПериода);

    Запрос.УстановитьПараметр("КонецПериода", КонецПериода);

    Т0 = ТекущаяУниверсальнаяДатаВМиллисекундах();

    Имя = "";

    Поз = СтрНайти(Часть, "ПОМЕСТИТЬ ");

    Если Поз > 0 Тогда Имя = СтрПолучитьСтроку(СокрЛП(Сред(Часть, Поз + 10, 40)), 1); КонецЕсли;

    Попытка

        Запрос.Выполнить();

        Лог.Добавить(Имя + ": " + (ТекущаяУниверсальнаяДатаВМиллисекундах() - Т0) + " мс");

    Исключение

        Лог.Добавить(Имя + ": ОШИБКА " + КраткоеПредставлениеОшибки(ИнформацияОбОшибке()));

    КонецПопытки;

КонецЦикла;

Разрезать пакет по ; грубо: точка с запятой внутри комментария или строкового литерала ломает разбор, и у меня последние части упали с «Ожидается выражение ВЫБРАТЬ». Для замера это не помешало, медленный шаг стоял раньше.

Наш отчет контроля данных на тестовой базе формировался около пяти минут (в одном из прогонов только этот шаг занял шесть). Замер показал, что 14 временных таблиц из 15 вместе укладываются в 0,76 секунды, а одна занимает 365. Это было соединение с регистром состояний по условию на период, без предварительного сужения. Решение стандартное: сначала отобрать в индексированную временную таблицу нужные ключи за период, потом соединять с регистром по ним. Отдельно заменили соединения с табличными частями документов по нетипизированным полям на индексированные временные таблицы. После этого отчет на той же базе стал собираться за секунды.

Сервер простаивает, а клиент ждет

Обратная картина. Мы прогоняем отчеты скриптом: тонкий клиент запускается с /Execute и внешней обработкой, которая выполняет код и пишет результат в файл. Однажды такой прогон обзора дважды «висел» по 50 минут. В rac у сеанса duration-current = 0, текущего вызова нет, процессор rphost не растет, файл результата не появляется.

Причина была на экране клиента, который никто не видел: модальное окно «Ошибка инициализации модуля... Слишком много фактических параметров». В модуле менеджера вызов собственной функции передавал 8 аргументов, а параметров у нее 7. Проверка ошибок проекта в EDT эту ошибку не показала, и она доехала до базы. Клиент ждал, пока закроют окно, скрипт ждал клиента до таймаута, и снаружи это выглядело как очень долгий запрос.

Вывод простой: если «висит», а у сервера нет текущего вызова, ждать бесполезно. Снимайте клиент, смотрите на окно, ищите ошибку компиляции или исключение. При изменении числа аргументов сверяйте вызовы с сигнатурой вручную.

Там же рядом второй ложный след скриптового прогона. Внешняя обработка, запущенная пользователем без права «Администрирование», работает в безопасном режиме, и фоновое задание из нее его наследует. Привилегированный модуль там привилегий не поднимает, и вы получаете «Нарушение прав доступа» в коде, который интерактивно работает. Все, что зависит от привилегированного режима, проверяйте в настоящей форме под тестовым пользователем.

Фоновые и регламентные задания

Задание висит и держит базу. Регламентное «Извлечение текста» из БСП, которое запускается каждые 85 секунд, однажды встало внутри извлечения файла с открытой транзакцией. Соединение с SQL у этого сеанса «спало» двое с половиной суток, а на третий день задание не дало обновить конфигурацию. rac session terminate вызов не снял. Помог только перезапуск rphost в окно без пользователей. Перед таким перезапуском посмотрите, кто еще работает в этом процессе: там может оказаться чей-то конфигуратор.

Разбор показал, что полнотекстовый индекс в базе ни разу не строился, а примерно у 1 900 файлов из 4 852 текст «извлечь не удалось». Задание выключили, включать его обратно будем только вместе с построением индекса. На время обновления регламентные задания можно запретить штатно:

rac infobase update --cluster=<uuid> --infobase=<uuid> --infobase-user=<user> --infobase-pwd=<pwd> --scheduled-jobs-deny=on localhost:5545

После обновления верните off.

Задание «выполнено», а данные стоят. Регламентная загрузка из внешней SQL-базы на рабочей базе не двигалась шесть дней. Первая причина: в расписании, выставленном через форму, остался пустой «повторять каждые ... дней», то есть ПериодПовтораДней = 0. Повтор в течение дня работает только в день установки, со следующего дня задание не стартует вообще, без ошибок и без записей в журнале. Проверяйте оба поля: ПериодПовтораДней = 1 и нужный ПериодПовтораВТечениеДня.

Историю запусков смотрите с отбором по имени метода:

Задания = ФоновыеЗадания.ПолучитьФоновыеЗадания(

    Новый Структура("ИмяМетода", "<Модуль>.<Метод>"));

Отбор по ИдентификаторРегламентногоЗадания, переданному строкой, платформа проигнорировала и отдала всю историю базы.

Вторая причина вскрылась после починки расписания: задание пошло каждые полчаса, данные частично поступали, а состояние загрузки стояло. Формат(0, "ЧГ=0") возвращает пустую строку, и условие "... > " + Формат(Счетчик, "ЧГ=0") превращалось в WHERE ... > ORDER BY. Исключение ловилось внутри процедуры загрузки и писалось в журнал, а фоновое задание завершалось успешно. История фоновых заданий в таком случае честно говорит «Задание выполнено». Правду знает журнал регистрации:

ТЗ = Новый ТаблицаЗначений;

Отбор = Новый Структура("Событие", "<ИмяСобытияЗагрузки>");

ВыгрузитьЖурналРегистрации(ТЗ, Отбор);

// колонка уровня называется Уровень

Числа в текст запроса к внешней базе теперь подставляем только через функцию с форматом "ЧГ=0; ЧН=0".

Шпаргалка

Чеклист, в порядке от дешевого к дорогому:

1. Поднять RAS нужной версии и снять rac session list два раза с интервалом.
2. Определить картину: запрос в СУБД, ожидание клиента, вызов без клиента или фоновое задание.
3. Для запроса: временный техжурнал DBMSSQL и SDBL с порогом 20 секунд, один прогон, поля Sql и Context.
4. Для пакета на СКД: замер по временным таблицам.
5. Для простаивающего сервера: окно в клиенте, ошибка компиляции, число аргументов.
6. Для задания: расписание, история по имени метода, журнал регистрации.
7. Вернуть logcfg.xml из копии и остановить временный RAS.

Сеансы снимаем только штатно, через rac или консоль кластера, и только когда понятно, что именно снимаем. Соединения на стороне SQL Server в обход платформы не трогаем: так легко оставить базу в непредсказуемом состоянии.

Главное, что изменилось в моей работе после этих случаев: вопрос «что тормозит» я больше не задаю коду. Сначала спрашиваю сервер, занят ли он вообще, и только потом читаю модули. Ответ «не занят» сразу уводит поиск от запросов: к клиенту, к расписанию, к журналу регистрации. Ответ «занят» за один прогон с техжурналом дает строку модуля.

Если у вас был зависший отчет, который не укладывается ни в одну из этих четырех картин, опишите его в комментариях: платформа, СУБД, что показали rac и техжурнал. Особенно интересны случаи с управляемыми блокировками и TLOCK, до них в этой истории дело так и не дошло.