Кассы 1С висели с обеда, серверы перезагрузили трижды. Через три недели искать причину было уже не по чему

В воскресенье около часа дня у розничной сети, которая работает в нескольких странах, зависли кассы. Чеки пробивались долго, товар искался долго. Системные администраторы перезагрузили сервер 1С и сервер СУБД в 17:22, потом сервер 1С ещё раз в 21:00, потом оба сервера утром. К утру отпустило. Почему висело, не знал никто.

Утром в понедельник меня попросили выяснить, почему висели кассы. По горячим следам я успел доказать, что проблема общая для всех баз сразу. Через три недели заказчик начал официальное расследование и собрал все логи за четыре дня вокруг аварии. К этому времени почти всё, что могло назвать виновника, стёрлось или не собиралось вовсе.

Главная находка пришла из событий vCenter: в день аварии админы трижды расширяли диск tempdb, с 250 до 300 ГБ за 1 час 41 минуту. Ни в одном письме это не связали со сбоем. Точную причину я так и не назвал. Ниже про то, почему её не назвать и что надо было поставить заранее.

Что за хозяйство

11 боевых баз 1С: ERP и розничные конфигурации. Все на одном экземпляре SQL Server: виртуальная машина на 48 ядер, общий tempdb из 8 файлов на отдельном диске 250 ГБ. Все базы обслуживает один кластер 1С: около 19 рабочих процессов rphost, ограничений памяти на процессы нет. Серверы виртуальные, под VMware.

tempdb это служебная база SQL Server, одна на весь экземпляр. Туда уходят временные таблицы наших запросов (ПОМЕСТИТЬ) и сортировки, которым не хватило памяти. Поэтому если одна база забивает tempdb, тормозят все одиннадцать.

Утро: как я понял, что проблема общая

Индикатор зависаний я взял из журнала регистрации. Кассир при зависании перезапускает 1С, и каждый перезапуск это событие _$Session$_.Start. Входы дают и фоновые задания, и веб-сервисы, но их фон в обычный день тот же, поэтому я сравнивал с тем же днём недели неделей раньше:

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

Отбор = Новый Структура;
Отбор.Вставить("ДатаНачала", НачалоДня(ДатаСбоя));
Отбор.Вставить("ДатаОкончания", КонецДня(ДатаСбоя));
Отбор.Вставить("Событие", "_$Session$_.Start");

Записи = Новый ТаблицаЗначений;
ВыгрузитьЖурналРегистрации(Записи, Отбор, "Дата");

ВходовПоЧасам = Новый Соответствие;
Для Каждого Запись Из Записи Цикл
	НомерЧаса = Час(Запись.Дата);
	Было = ВходовПоЧасам[НомерЧаса];
	ВходовПоЧасам.Вставить(НомерЧаса, ?(Было = Неопределено, 0, Было) + 1);
КонецЦикла;

Сильнее чисел оказались минуты. Пики совпали во всех базах сразу: 14:20, 15:10, 17:10-17:20. Ошибка в коде одной базы, если она не задевает общие ресурсы, соседей в ту же минуту не роняет. Значит, болел общий слой: СУБД, tempdb, кластер 1С или железо под ними. Виновником при этом могла быть и одна база, если она забила общий ресурс. К этому вернусь ниже.

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

Блокировки исключил цифрой. Таймаутов блокировок в рознице в день аварии 28, неделей раньше тоже 28. Это хронический фон закрытия смен. Поток чеков просел на 10-15%, но не обвалился: кассы работали, только медленно.

Журнал ошибок SQL Server (xp_readerrorlog) из всего, что есть у SQL Server, единственный хранит историю после перезапуска. В нём видна перезагрузка ОС, ручной рестарт службы в 20:48, массовые kill соединений после рестартов. Ни одной записи о нехватке места. Подвох: часть ошибок нехватки места в tempdb SQL Server в этот журнал не пишет, так что отсутствие записи ничего не доказывает.

Кластер 1С через rac. Истории он не хранит, только текущее состояние. Показал, что кластер перезапущен утром и что в 09:07 все сеансы сбросили ещё раз. И что ограничений памяти на rphost нет: утром процессы держали 73 ГБ, самые большие по 10 ГБ.

Итог утра такой: проблема общая, а что именно творилось на SQL Server, уже не восстановить, перезагрузки всё стёрли. Если у вас висит прямо сейчас, до перезагрузки сохраните в файл хотя бы xp_readerrorlog и вывод rac session list. Это две минуты.

Через три недели: где должны были лежать следы

Техлид заказчика запросил у админов доступ на чтение ко всем логам за четыре дня вокруг аварии. Админы собрали опись, и по ней сложилась картина ниже. Два слова из таблицы. DMV это системные представления SQL Server, которые копят ожидания и задержки файлов с момента запуска службы. system_health это встроенная запись последних проблем сервера, включена по умолчанию.

Сохранилось немного: журнал System с событиями 1074, ERRORLOG дня аварии, два дампа упавшего rphost, история заданий SQL Agent и бэкапов, логи IIS, события vCenter. Событие 1074 Windows пишет, когда перезагрузку запускает человек или программа, и в нём стоит выбранная причина: у перезагрузки в 17:22 "Planned", у вечерней в 21:00 "Unplanned".

Поворот: tempdb расширяли трижды, и никто этого не связал

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

Три расширения за 1 час 41 минуту, плюс 50 ГБ. Похоже, tempdb кончался: диск просто так трижды за два часа не растят. В переписке и в описи логов расширения выглядели рабочими действиями админов, и как симптом их никто не прочитал. Что именно админы видели в тот момент, сколько было занято в самом tempdb и почему после третьего расширения не отпустило, я не знаю: вопрос задан, ответа нет.

Графики vCenter подозрение с ресурсов машин сняли, но только в пределах средних за 2 часа: у сервера СУБД процессор 13-18%, память 10-16%, задержка дисков до 1 мс; у сервера 1С процессор до 31%, память до 16%, задержка до 3 мс. Balloon на обеих ноль, то есть гипервизор память у машин не отбирал. Минутный пик в таких средних мог утонуть.

Теперь приём для тех, у кого 1С крутится под VMware. События и графики vCenter читаются без отдельных библиотек, голым SOAP на адрес /sdk. REST (/api/...) событий не отдаёт. Сначала вход: RetrieveServiceContent, затем SessionManager.Login, дальше запросы идут с cookie из ответа. События по машине за интервал:

<QueryEvents xmlns="urn:vim25">
  <_this type="EventManager">EventManager</_this>
  <filter>
    <entity>
      <entity type="VirtualMachine">vm-NN</entity>
      <recursion>self</recursion>
    </entity>
    <time>
      <beginTime>2026-01-01T00:00:00Z</beginTime>
      <endTime>2026-01-02T00:00:00Z</endTime>
    </time>
  </filter>
</QueryEvents>

Время в событиях UTC, его надо перевести в местное. Расширение диска приходит как VmReconfiguredEvent, в нём capacityInKB до и после. Открытие консоли админом это VmAcquiredTicketEvent. Графики берутся через QueryPerf, для прошлого месяца есть только intervalId 7200, те самые 2 часа. События хранятся 30 дней по умолчанию, так что у разбора есть дедлайн. У нас к началу расследования из этих тридцати дней прошли три недели.

Что можно утверждать, а что нет

Утверждать можно вот что. Проблема в общем слое. Диск tempdb трижды расширяли за 1 час 41 минуту. Падение rphost в 15:10 совпало с худшим моментом. SQL Server сам не падал, все рестарты сделали люди. Блокировки 1С на уровне прошлой недели.

Нельзя утверждать, какой запрос и какая база съели tempdb. Всё, что это показывает, либо не собиралось, либо стёрлось. Главный стиратель следов тут сами перезагрузки: каждая обнуляла DMV, заводила новый ERRORLOG и сбрасывала кластер. Волну в 15:10 к тому же могло дать само падение rphost, на одном процессе сидят сеансы разных баз. Но в 14:20 и 17:10 базы совпали по минутам и без падения.

Дальше гипотеза. Тяжёлый запрос одной из баз или брошенная транзакция раздули tempdb, а общий tempdb утащил за собой все одиннадцать баз. Почему запрос мог быть тяжёлым: на сервере стоят max degree of parallelism = 0 и cost threshold for parallelism = 5. Ноль значит, что один запрос может занять все 48 ядер, пятёрка значит, что параллельный план получает почти любой запрос тяжелее совсем простого. Косвенный намёк дало утро после аварии: в 09:07, сразу после ручного сброса сеансов, за 8 минут прошло 550 взаимоблокировок внутри параллельных запросов в двух розничных базах. Для воскресенья это не доказательство, но параллельные планы на этом сервере ведут себя плохо.

Про брошенную транзакцию у меня есть прецедент в этой же инфраструктуре, раньше аварии. Транзакция ERP держала около 56 000 X-блокировок и 27 тысяч страниц tempdb. Сброс сеанса 1С её не закрыл, помог только KILL на стороне SQL Server. По объёму это около 210 МБ, до пятидесяти гигабайт далеко. Но механизм тот же: транзакция пережила сброс сеанса, и 1С про неё уже ничего не знала.

Обе половины гипотезы можно проверить у себя. Эту проверку делает наша обработка Чек-ап СУБД под 1С: она выносит вердикт по MAXDOP и порогу параллелизма, сверяет число файлов tempdb с числом ядер, а в библиотеке скриптов у неё есть "Кто занимает tempdb и version store" и "Долгие транзакции и что держит журнал".

Что я предложил: чёрный ящик и регламент аварии

Раз следы стирают перезагрузки, писать их надо раньше перезагрузки и туда, где рестарт их не достанет.

База снимков на сервере СУБД. Своя небольшая база и задание SQL Agent раз в минуту: активные запросы с текстом и планом, блокировки, занятость tempdb по сеансам, свободное место на дисках, прирост ожиданий и задержек файлов, долгие транзакции, выданная память. Хранение 14 дней. По моей оценке это сотни мегабайт и доли процента процессора, замера ещё нет. Работает внутри SQL Server, поэтому пишет и тогда, когда висит кластер 1С.

Снимки кластера через RAS в служебную базу 1С: рабочие процессы (память, загрузка, время вызова, перезапуски) и сеансы (база, пользователь, на каком rphost, время в СУБД, блокировки).

Связка двух снимков. SQL Server помнит у каждого соединения PID процесса, который его открыл: поле host_process_id. У соединений 1С это PID rphost. Снимок SQL говорит, какая база и с какого rphost заняла tempdb и каким запросом. Снимок RAS за ту же минуту говорит, какие сеансы и каких пользователей обслуживал этот rphost. На одном процессе сеансов много, поэтому PID сужает круг до процесса, а не до человека. Со стороны SQL Server это выглядит так (временные таблицы держатся в сеансе между запросами, поэтому считаются и законченные задачи, и идущие):

SELECT TOP (10)
    s.session_id,
    s.host_process_id AS pid_rphost,
    DB_NAME(s.database_id) AS база,
    (ss.страниц + ISNULL(ts.страниц, 0)) * 8 / 1024 AS tempdb_мб
FROM sys.dm_exec_sessions AS s
JOIN (SELECT session_id,
             SUM(user_objects_alloc_page_count - user_objects_dealloc_page_count
               + internal_objects_alloc_page_count - internal_objects_dealloc_page_count) AS страниц
      FROM sys.dm_db_session_space_usage
      GROUP BY session_id) AS ss ON ss.session_id = s.session_id
LEFT JOIN (SELECT session_id,
             SUM(user_objects_alloc_page_count - user_objects_dealloc_page_count
               + internal_objects_alloc_page_count - internal_objects_dealloc_page_count) AS страниц
      FROM sys.dm_db_task_space_usage
      GROUP BY session_id) AS ts ON ts.session_id = s.session_id
WHERE s.is_user_process = 1
ORDER BY tempdb_мб DESC;

Со стороны кластера PID есть в списке рабочих процессов, а у каждого сеанса указан процесс, на котором он сидит:

rac process list --cluster=<id кластера>    # у каждого rphost: process (идентификатор) и pid
rac session list --cluster=<id кластера>    # у каждого сеанса: process, на котором он сидит

По замыслу, будь это в день аварии, круг подозреваемых сузился бы до одного процесса и одного запроса в первые десять минут. Связка логически верная, но в работе я её ещё не проверял.

Регламент аварии. Перед перезагрузкой убедиться, что свежий снимок есть, и только потом перезагружать. Кассы стоят, все торопятся, поэтому правило записывается заранее, вместе с тем, кто его выполняет.

Остальное короче:

• техжурнал 1С хранить 7 дней, включить EXCP, TLOCK, TDEADLOCK, TTIMEOUT и долгие DBMSSQL;
• ERRORLOG 30 файлов вместо 6;
• журнал Application поднять с 20 МБ до 512 МБ;
• оповещение о свободном месте в tempdb, чтобы узнать раньше касс;
• ограничения памяти rphost на кластере;
• SQL Server поставить на последнее накопительное обновление, сейчас на нём нет ни одного;
• MAXDOP 8 и cost threshold 50 вместо 0 и 5.

Статус на начало ноября: всё это отправлено техлиду заказчика, внедрение не начато. Поэтому пишу "предложено".

Чего я не знаю. Дампы rphost не разбирались, причина падений процесса неизвестна. События хостов и хранилищ vCenter я не видел из-за прав, поэтому проблема хранилища на уровне хоста исключена не до конца: только на уровне машин и только по средним за 2 часа.

А как у вас: есть ли записанный порядок действий на случай "всё висит", и что в нём стоит раньше перезагрузки?

Другие наши инструменты диагностики 1С:

• Анализ нагрузки кластера 1С - копит историю сеансов, памяти и блокировок регламентным заданием, чтобы после аварии было что смотреть кроме текущего состояния консоли.
• Чек-ап сервера 1С - покажет, стоят ли на кластере ограничения памяти рабочих процессов и что будет при их превышении. В этой истории их не было вовсе.
• Журнал регистрации для нейросети - кто заходил и какая ошибка повторяется, отборами, без чтения журнала целиком.