Технологический журнал 1С: как читать и не утонуть в гигабайтах

Технологический журнал — самый мощный диагностический инструмент платформы и самый пугающий. Включённый без фильтров, он за ночь создаёт сотню гигабайт текста, в котором ничего не найти. Настроенный правильно — за пятнадцать минут показывает точную причину проблемы с текстом запроса и именем пользователя. Разница целиком в одном XML-файле.

Журнал управляется одним файлом — logcfg.xml. Он лежит в каталоге conf установленной платформы.

На Windows это обычно C:\Program Files\1cv8\conf\logcfg.xml, на Linux — /opt/1cv8/conf/logcfg.xml. Файл читается платформой автоматически, перезапуск службы не требуется — изменения подхватываются в течение минуты.

Это удобно и опасно одновременно. Удобно — можно включить сбор на боевом сервере, снять данные и выключить, не трогая пользователей. Опасно — можно случайно оставить включённым, и через неделю обнаружить забитый диск.

Структура файла минимальна: корневой элемент config, внутри один или несколько log с указанием каталога и времени хранения, внутри них — фильтры событий.

<config xmlns="http://v8.1c.ru/v8/tech-log">
  <log location="D:\tj" history="4">
    <event>
      <eq property="name" value="EXCP"/>
    </event>
    <property name="all"/>
  </log>
</config>

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

И сразу правило, которое стоит принять как закон: каталог журнала никогда не должен быть на системном диске. Никогда.

Девяносто процентов пользы журнала даёт один приём — собирать только долгие события.

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

Рабочая конфигурация для поиска тормозящих запросов:

<log location="D:\tj" history="4">
  <event>
    <eq property="name" value="DBMSSQL"/>
    <ge property="duration" value="1000000"/>
  </event>
  <event>
    <eq property="name" value="TDEADLOCK"/>
  </event>
  <event>
    <eq property="name" value="TTIMEOUT"/>
  </event>
  <property name="all"/>
</log>

Такой набор на нормально работающей базе за сутки даёт мегабайты, а не гигабайты. И каждая строка в нём заслуживает внимания — это уже отфильтрованные проблемы, а не фон.

Обратите внимание: у TDEADLOCK и TTIMEOUT фильтра по длительности нет. Эти события редкие и важные все.

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

Связка SDBL плюс DBMSSQL — самая ценная для программиста: она позволяет от тяжёлого SQL-запроса дойти до конкретной строки кода конфигурации. Но и объём она даёт заметно больший, поэтому включается адресно и ненадолго.

Чего почти никогда не нужно: ADMIN, CONN, SCOM, SESN. Это служебные события, они пишутся постоянно и в диагностике производительности бесполезны.

Журнал пишется не в один файл, а в дерево каталогов: по процессу, по часу.

Имя каталога — это имя процесса и его идентификатор, например rphost_4812. Имя файла — дата и час: 26082410.log означает 2026 год, 08 месяц, 24 число, 10 часов.

Формат строки такой:

10:14:23.847012-2340156,DBMSSQL,4,process=rphost,p:processName=buh_prod,
t:clientID=41,t:applicationName=1CV8C,t:computerName=WS-BUH-07,
t:connectID=118,SessionID=54,Usr=Иванова,Trans=1,dbpid=93,
Sql='SELECT TOP 100 ...',Rows=0,RowsAffected=1247

Разбираем по частям:

• 10:14:23.847012 — время начала события с точностью до микросекунд;
• 2340156 — длительность в микросекундах, то есть 2,34 секунды;
• DBMSSQL — тип события;
• Usr — пользователь, от имени которого шёл запрос;
• t:computerName — с какой станции;
• Sql — сам текст запроса;
• RowsAffected — сколько строк затронуто.

Обратите внимание на важную деталь: время в начале строки — это время завершения события, а длительность указывает, сколько оно шло. Чтобы найти момент начала, вычитайте. Это регулярно путает при сопоставлении с жалобами пользователей.

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

Топ самых долгих событий за период:

Get-ChildItem D:\tj -Recurse -Filter *.log |
  Select-String -Pattern '^\d\d:\d\d:\d\d\.\d+-(\d+),DBMSSQL' |
  ForEach-Object {
    [PSCustomObject]@{
      Dur = [int64]$_.Matches[0].Groups[1].Value / 1000000
      Line = $_.Line.Substring(0, [Math]::Min(200, $_.Line.Length))
    }
  } | Sort-Object Dur -Descending | Select-Object -First 20

На Linux то же самое короче:

grep -rhoP '^\d\d:\d\d:\d\d\.\d+-\K\d+(?=,DBMSSQL)' /var/log/tj |
  sort -rn | head -20

Сколько событий по каждому пользователю:

grep -rho 'Usr=[^,]*' /var/log/tj | sort | uniq -c | sort -rn | head

Этих трёх команд хватает для большинства разборов. Специализированные парсеры нужны, когда надо агрегировать по нормализованному тексту запроса — то есть считать, что WHERE id=5 и WHERE id=7 это один запрос. Такое требуется при поиске «много мелких, но частых», а не «один большой».

Полезно понимать границы инструмента, иначе на него возлагают надежды, которых он не оправдает.

Журнал видит то, что происходит внутри платформы. Всё, что снаружи, для него не существует.

Он не покажет, что диск перегружен репликацией виртуальной машины — увидит только, что запрос выполнялся девять секунд, и вы решите, будто виноват запрос. Не покажет, что сеть между сервером приложений и СУБД просела: длительность вырастет, причина останется за кадром. Не покажет нехватку памяти на уровне гипервизора, конкуренцию за процессор с соседней виртуалкой, деградировавший RAID-массив.

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

Обратная ошибка тоже встречается. Администратор смотрит только на счётчики, видит загрузку процессора 45 % и свободную память, делает вывод «с сервером всё в порядке» и закрывает заявку. А в журнале в это время лежит запрос на 40 секунд, который выполняется двести раз в день и не грузит ни процессор, ни память — он просто ждёт блокировку.

Второе ограничение: журнал показывает симптом с точностью до запроса, но не объясняет, почему запрос стал медленным. Один и тот же текст может выполняться за 30 миллисекунд и за 30 секунд в зависимости от плана, статистики и объёма данных. Для ответа на «почему» нужен уже план выполнения на стороне СУБД.

Ну и третье. Журнал не расскажет, что операция вообще не запускалась. Регламентное задание, которое молча не отработало из-за требований назначения функциональности, в логе не оставит ничего — просто не будет строк. Отсутствие событий тоже информация, но её надо специально искать, а взгляд за неё не цепляется.

Событие TDEADLOCK — самое информативное, и читать его надо уметь.

Взаимоблокировка возникает, когда два процесса держат по ресурсу и каждый ждёт ресурс другого. Круг замкнулся, и платформа принудительно снимает одного из участников.

В логе это выглядит как строка с перечислением участников и захваченных ими ресурсов. Ключевые поля — DeadlockConnectionIntersections, где перечислены соединения и что именно они держали.

Практический алгоритм разбора:

1. Найти все TDEADLOCK за период и посмотреть, повторяются ли участники.
2. Определить, какие таблицы фигурируют в конфликте. Обычно это регистры накопления.
3. По Usr и времени понять, какие действия выполняли пользователи.
4. Связать с кодом через SDBL, если он собирался.

Типичная причина в 1С — разный порядок обращения к ресурсам в двух разных местах кода. Одна обработка сначала блокирует остатки, потом цены; другая — сначала цены, потом остатки. Пока они не пересекаются во времени, всё работает. Стоит двум пользователям запустить их одновременно — круг замыкается.

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

У клиента-дистрибьютора мы разбирали серию из 40–60 взаимоблокировок в день. Все — между проведением реализации и фоновым заданием расчёта себестоимости, которое крутилось каждые 15 минут в рабочее время. Перенос задания на ночь убрал 100 % случаев за сутки. Код при этом остался неоптимальным, но проблема исчезла — иногда достаточно и этого.

Несколько правил, выработанных на собственных ошибках.

• Всегда указывайте history. Четыре часа для отладки, сутки для наблюдения. Это страховка от забытого включения.
• Каталог — только на отдельном диске с запасом места и, желательно, с мониторингом свободного объёма.
• Включили — поставьте себе напоминание выключить. Буквально, в календарь.
• Сохраняйте logcfg.xml шаблонами. У нас лежит набор готовых файлов: «медленные запросы», «блокировки», «падения», «полный разбор». Копируется нужный, а не пишется с нуля в момент аварии.
• Не собирайте всё сразу. Соблазн включить все события «чтобы наверняка» заканчивается объёмом, в котором ничего не найти.
• Снимайте лог в момент проблемы, а не после. Журнал не ретроспективен: если он не был включён, данных за прошлую неделю не появится.

Последний пункт означает, что на серверах с регулярными жалобами имеет смысл держать постоянно включённым минимальный набор: TDEADLOCK, TTIMEOUT и DBMSSQL с порогом от 5 секунд. Объём такой конфигурации на здоровой базе — единицы мегабайт в сутки, зато в момент инцидента данные уже есть.

Мы такой «дежурный» журнал ставим всем клиентам на поддержке. За два года он ни разу не создал проблем с местом и раз пять избавил от необходимости воспроизводить аварию заново.

В каких единицах указывается длительность в logcfg.xml?

В микросекундах. Одна секунда — это 1000000. Ошибка на три порядка в меньшую сторону — самая частая причина того, что журнал за ночь занимает десятки гигабайт.

Нужно ли перезапускать сервер после правки logcfg.xml?

Нет, платформа перечитывает файл автоматически в течение примерно минуты. Это позволяет включать сбор на боевом сервере и выключать его, не трогая пользователей.

Какие события включать, если непонятно, что искать?

Начните с TDEADLOCK, TTIMEOUT и DBMSSQL с порогом от одной секунды. Этот набор мал по объёму и покрывает большинство проблем с производительностью и блокировками.

Можно ли посмотреть журнал за прошлую неделю, если он не был включён?

Нет. Технологический журнал не ретроспективен: он пишет только с момента включения. Именно поэтому на проблемных серверах имеет смысл держать постоянно включённым минимальный набор событий.