Ночная синхронизация падала по превышению времени ожидания записи. Четыре ночи подряд, каждая хуже предыдущей. На четвёртую сервис лёг целиком: хост отвечает на пинг, порт соединяется за три миллисекунды, а по протоколу приложения ответа нет вообще.
В коде, который всё это устроил, стоял комментарий: безопасная операция без последствий.
Комментарий не врал по смыслу и врал по цене. Операция действительно ничего не меняла - и стоила столько, что укладывала принимающую сторону. Разбор ниже про то, как безусловное "ничего не делать" превращается в самоперегрузку, и почему одна сторона тут виновата не больше другой.
Чтение здорово, запись мертва
Первые три ночи всё выглядело странно: сервис явно нездоров, а любая проверка показывает норму.
Причина в том, что проверяли не то. Чтение отвечало за 40-130 миллисекунд с кодом 200. Любая проверка доступности, хоть автоматическая, хоть руками из браузера, отвечала как положено.
Запись при этом занимала 24 секунды, потом больше тридцати. А клиент имел жёсткое ограничение в 30 секунд без повторных попыток.
Отсюда картина "непонятно, то работает, то нет": половина операций укладывалась, половина нет, и от нагрузки зависело, какая именно.
Практический вывод. Проверка живости, которая делает только чтение, не доказывает работоспособности сервиса. Если приложение пишет - проверка обязана писать, хотя бы в служебный объект. Читающая проверка при записи, уехавшей в десятки секунд, покажет вам полное здоровье.
Второе, что вылезло тут же и обошлось дороже всего: пять баз обрабатывались в одном блоке перехвата ошибок. Падение одной уносило обработку остальных четырёх, хотя с ними всё было в порядке. Одна больная база превращалась в четыре потерянные ночи работы.
Четвёртая ночь: сервис перестал отвечать
К четвёртой ночи деградация дошла до конца.
Сеть в порядке: хост пингуется, соединение транспортного уровня (TCP, Transmission Control Protocol) устанавливается за три миллисекунды. А запрос по протоколу приложения висит без ответа.
Это характерная и полезная для диагностики картина. Порт соединяется - значит операционная система принимает соединение и ставит его в очередь. Ответа нет - значит приложение из этой очереди ничего не забирает. Оно не упало и не потеряло сеть, оно занято настолько, что не доходит до обработки.
Различать эти два состояния стоит уметь: "сервис недоступен" и "сервис занят" лечатся по-разному, а снаружи выглядят одинаково.
Проверяется это без специальных инструментов. Соединение на порт устанавливается - процесс жив и слушает. Запрос по протоколу висит дольше обычного времени ответа в разы - процесс не успевает разбирать очередь. Если же соединение не устанавливается вовсе, разговор про приложение можно не начинать: смотреть надо сеть, правила фильтрации и то, запущен ли процесс.
Наш код и комментарий про безопасную операцию
Теперь причина, и она на нашей стороне.
Синхронизация после каждого обновления документа безусловно вызывала операцию перемещения документа в нужный раздел - для каждого документа коллекции, независимо от того, находился он уже там или нет.
Рядом стоял комментарий, что операция безопасна и ничего не делает, если документ уже на месте.
Комментарий был технически верен. Результат операции не менялся - документ, уже лежащий в нужном разделе, оставался там же.
Масштаб: коллекция из 1 417 документов, около 1 400 вызовов за прогон. Каждую ночь, независимо от того, изменилось хоть что-нибудь или нет.
Почему комментарий врал
Здесь и находится главный урок статьи.
Операция была идемпотентной по результату и очень дорогой по стоимости. Это два независимых свойства, и в голове они обычно склеиваются в одно.
"Ничего не меняет" читается как "ничего не делает". Между тем сервис на каждый такой вызов синхронно прогонял три своих обработчика и пересчитывал структуру коллекции, а она весила 139 килобайт. То есть тысяча четыреста раз за ночь принимающая сторона перестраивала одно и то же дерево и записывала один и тот же результат.
Здесь стоит остановиться на слове "синхронно". Дорогая работа сама по себе ещё терпима: она отъедает процессор, прогон идёт дольше, все живут. Смертельной её делает то, что она выполняется в том же потоке, который обязан отвечать на входящие запросы. Пока идёт пересчёт, отвечать некому, и для любого клиента сервис в этот момент отсутствует. Тысяча четыреста таких окон подряд складываются в непрерывное отсутствие.
Формально ноль изменений. Фактически - плотный поток тяжёлых операций записи, которые сервис обязан выполнить, потому что откуда ему знать, что результат не изменится.
Правило, которое стоит забрать: идемпотентность описывает результат, а не цену. Прежде чем вызывать операцию безусловно, надо ответить, во что обходится вызов, который ничего не изменит. Если ответ "столько же, сколько настоящий" - вызывать безусловно нельзя.
Проверка на своей стороне при этом почти бесплатна: сравнить текущее положение с целевым и вызывать только при расхождении. Одно условие.
Усилитель на принимающей стороне
Виноват не только вызывающий код, и вот вторая половина картины.
Принимающий сервис работал в один процесс: веб-интерфейс, фоновый обработчик и механизм совместного редактирования - всё в одном цикле обработки событий.
При такой конфигурации тяжёлая фоновая работа не просто конкурирует с интерфейсом за ресурсы, она блокирует его целиком. Процесс крутился на ста процентах в пользовательском режиме, и обработать входящее соединение было некому. Отсюда и висящие без ответа запросы при живом порте.
То есть наш код создавал нагрузку, а конфигурация сервиса превращала нагрузку в полный отказ. Убери любую из двух половин - катастрофы не будет. Именно поэтому "программист не виноват" здесь не фигура речи. Код, безусловно вызывающий идемпотентную операцию, на нормально сконфигурированном приёмнике всего лишь замедлил бы синхронизацию. Сервис бы устоял.
Отклонённая версия
На ревью высказали подозрение: возможно, испортилась карта соответствия документов, и синхронизация гоняет данные впустую именно из-за неё.
Версия правдоподобная и проверяемая. Сделали сплошную сверку: 696 записей карты из 696 сопоставлены с фактическим состоянием. Ноль устаревших, ноль отсутствующих.
Карта в полном порядке, версия закрыта. Проверка заняла меньше времени, чем занял бы спор о ней.
Что сделали с обеих сторон
Лечение оказалось несоразмерно простым по сравнению с масштабом отказа.
Прежде чем чинить, стоило убедиться, что понята вся картина, - отсюда и проверка версии выше. Дальше правки.
На стороне сервиса - снять ограничение в один процесс. Приложение пошло в пять процессов, и фоновая работа перестала блокировать обслуживание запросов.
На своей стороне - одно условие перед вызовом: сравнить, где документ лежит сейчас, с тем, где он должен лежать, и вызывать перемещение только при расхождении.
Плюс подняли ограничение времени ожидания записи до 90 секунд и добавили три повторные попытки вместо одной попытки без повторов.
Повторные попытки чуть не создали новую аварию
Повтор по таймауту выглядит безобидной страховкой ровно до момента, когда до него доходит очередь на операции создания.
Создание документа на таймауте неидемпотентно. Сервер успел применить запись, ответ до нас не доехал, клиент считает попытку неудачной и повторяет. В итоге в приёмнике два одинаковых документа, и второй мы создали собственными руками, страхуясь от сбоя.
Причём именно в этот период вероятность такого сценария была максимальной: запись шла десятками секунд и упиралась в порог, то есть таймаут наступал ровно там, где сервер работу уже начал и, скорее всего, доделал.
Закрыли это пробой перед повтором: перед тем как повторять создание, идём и проверяем, не появился ли документ с таким заголовком. Если появился, повтор превращается в чтение и запись не отправляется.
Общее правило отсюда простое. Повторные попытки можно вешать только на операции, у которых повтор ничего не ломает. На запись, которая создаёт сущность, повтор без предварительной проверки состояния вешать нельзя, и таймаут тут опаснее явной ошибки: явная ошибка хотя бы честно говорит, что сервер запрос отверг.
И вот тут честная оговорка, которую надо проговорить вслух. Позже наблюдалась запись длительностью 77 секунд при поднятом ограничении 90. Запас составил 17 процентов. Это подобрано впритык: любая новая нагрузка на сервис, и мы снова упрёмся в ту же стену. Правильно было бы разобраться, почему запись вообще занимает больше минуты. Порог мы подняли вместо этого.
Код ответа врёт в обе стороны
Пока разбирались, наткнулись на соседний случай в той же связке систем, и он отдельно поучительный.
Пакетная архивация напечатала в журнал FAILED на все 35 документов. Пошли смотреть, что не заархивировалось, и обнаружили, что заархивированы все 35, в правильном порядке, с шагом примерно в полсекунды на вызов. Мутация применилась полностью, а ответ пришёл ошибочный.
Обратная ошибка живёт в том же коде: обёртка над вызовами возвращала пустой словарь на любой ответ, отличный от 200, и не поднимала исключение. Вызывающий код видел "пусто" и шёл дальше. Тихий провал, который в журнале выглядит как штатная работа.
На встроенном языке тот же глушитель выглядит как пустой блок Исключение вокруг вызова: ошибка проглочена, вызывающий код едет дальше, в журнале штатная работа. Чтением такое место не находится, зато находится поиском по коду. У меня для этого Анализ кода внешних обработок 1С: пустой перехват и запись объекта внутри цикла там отдельные правила, каждая находка с номером строки. Конфигурацию он не читает, только .epf и .erf, зато самописные обёртки над обменом у меня жили как раз в них.
Отсюда правило, которым теперь пользуюсь: код ответа сообщает про попытку и ничего не сообщает про состояние объекта. Когда операция важная, состояние надо перечитать. И журнал, в котором написано FAILED, стоит проверять так же придирчиво, как журнал, в котором написано OK: ошибочный FAILED заставляет чинить то, что уже работает, и это дорогое занятие.
Ещё один пример из той же серии. Архивация возвращала 403, и первая версия была "сервисному пользователю не хватает прав". Прав хватало, токен был администраторский. 403 приходил на попытку заархивировать уже заархивированное: по смыслу это "поздно, уже сделано", хотя код говорит про запрет. Гипотезу про права мы проверили и отбросили, а на реальную причину вышли, посмотрев фактическое состояние документа. Порядок действий работает почти всегда: сначала смотрим состояние объекта, потом лезем в права.
Как выкатывали фикс
Отдельная история, стоившая суток.
Фикс уехал в основную ветку, сборка прошла, все проверки отчитались успешно. На проде поведение не изменилось, и это выяснилось только следующей ночью, когда синхронизация отработала по-старому. Оказалось, фильтр путей в цепочке выкатки не включал каталог со скриптами: изменения в нём проходили сборку, но задачу выкатки не запускали. Пришлось докатывать руками.
Вторые грабли ровно там же. Пересоздание контейнера, то есть среды, в которой поднят сам сервис, во время активного прогона убивает прогон и оставляет после себя замок, который потом снимаешь вручную. То есть сама выкатка фикса создаёт следующий инцидент, если делать её в окно, когда задание работает.
Вывод не про конкретный инструмент. Если у вас ночное задание, то выкладка исправлений в это задание обязана иметь своё окно, а факт доезда изменений на прод надо проверять отдельно от факта "сборка зелёная". Иначе диагностика идёт по коду, которого на проде нет.
Контрольный прогон
Результат после правок:
| Показатель | Значение |
|---|---|
| Баз обработано | 5 из 5 |
| Код возврата | 0 |
| Время прогона | 344 секунды |
| Перемещений документов | 0 (было около 1 400) |
| Пропущено без изменений | 680 |
| Обновлено | 5 |
| Создано новых | 3 |
Следующий прогон - 215 секунд, ноль созданных, ноль обновлённых, 682 пропущено. Сервис отвечает кодом 200 за 47 миллисекунд при фоновой загрузке процессора 77-89 процентов.
Обратите внимание на последнюю цифру: загрузка процессора осталась высокой, а отвечать сервис стал за 47 миллисекунд. Это и есть доказательство того, что дело было в блокирующем характере нагрузки. Объём тут вторичен.
Счётчики между собой не сходятся, и я это не спрятал
Здесь надо сказать неудобное, пока читатель не сложил числа сам.
Карта соответствия ведёт 696 записей. В контрольном прогоне 680 пропущено, 5 обновлено, 3 создано, в сумме 688. Восемь записей не объясняются ничем: они не попали ни в одну из категорий отчёта. На следующем прогоне картина снова другая: 682 пропущено при нуле созданных и нуле обновлённых, то есть с 688 не сходится ещё на шесть.
Что это, я честно не знаю. Наиболее вероятная версия - документы, уходящие в другую ветку обработки и не попадающие в счётчики отчёта. Это именно версия: специально мы её не проверяли, потому что к моменту, когда числа сошлись в одну таблицу, авария была уже закрыта.
Отдельно про 1 417 и 696, чтобы не путались. 1 417 - это размер коллекции на принимающей стороне, по ней и шли безусловные перемещения. 696 - число записей в нашей карте соответствия. Это разные множества, и полного объяснения разрыва между ними у меня тоже нет.
Вывод из этого абзаца невесёлый и полезный: отчёт ночного задания надо проектировать так, чтобы сумма его категорий сходилась с общим числом обрабатываемых объектов, и расхождение выводилось отдельной строкой. Иначе диагностика превращается в вычитание чисел из разных строк журнала, что вы сейчас и наблюдали.
Почему прогон без работы всё равно стоит три минуты
Прогон, в котором ноль перемещений, занимает 215 секунд вместо 344. Разница в 129 секунд приходится на восемь записей контрольного прогона, три создания и пять обновлений, если поделить - около 16 секунд на запись. Порядок ровно тот, ради которого поднимали порог ожидания: запись на этом сервисе по-прежнему медленная, просто теперь её мало.
Всё остальное время уходит на обход коллекции. То есть даже после исправления синхронизация тратит основное время на проверку того, что работы нет.
Это нормально для такой схемы, но означает, что следующий шаг оптимизации, если он понадобится, лежит в способе понять, что менялось с прошлого раза. Перемещения тут уже ни при чём. Пока коллекция обходится целиком, время прогона будет расти вместе с её размером, независимо от объёма изменений.
Что осталось незакрытым
Хронический фон процессора объяснения не получил. До исправлений сервис держал около 83 процентов постоянно, и после устранения главной причины высокая фоновая загрузка никуда не делась - просто перестала мешать. Что её создаёт, в этом разборе не установлено.
Запас по времени ожидания мал. Семнадцать процентов - это не запас, это отсрочка.
Причина медленной записи не найдена. Мы обошли её повторами и увеличенным порогом, устранить не смогли.
Счётчики прогона не сходятся с картой соответствия. 688 против 696 в контрольном прогоне и ещё шесть расхождения на следующем. Версия есть, проверки нет.
Стоимость инцидента не посчитана. Сколько суток сервис был недоступен всем пользователям и скольких людей это задело, мы не замеряли. Видно только, что недоступность длилась не меньше двух суток. Поэтому история читается как техническая, хотя по-хорошему её надо было предъявлять бизнесу в часах простоя.
Пары "до и после" по главной метрике нет. Сколько занимал прогон до исправления, никто не мерил: до аварии никому не приходило в голову, что это интересная величина. Есть 344 и 215 секунд после, а с чем их сравнивать - неизвестно. Если вы читаете это перед похожим разбором, снимите текущее время прогона сейчас, пока всё работает. Замер, сделанный после аварии, доказывает вдвое меньше.
Открытый вопрос
Вопрос, на который у меня нет уверенного ответа. Комментарий "безопасно, ничего не делает" был написан честно и оказался ловушкой, потому что описывал результат и молчал про стоимость. У меня ощущение, что это очень распространённый класс комментариев - формально правдивых и вводящих в заблуждение. Кто-нибудь ввёл у себя правило писать в таких местах ещё и цену? Интересно, работает ли это на практике или превращается в ещё одно поле, которое никто не заполняет.
Другие наши инструменты:
- Анализ нагрузки кластера 1С - показывает, кто именно держал базу и кто грузил сервер в конкретный час. Ровно тот вопрос, с которого начинается разбор ночного окна.
- Журнал транзакций переполнен: кто держит и чем - вторая половина той же ночи. Обмен пишет пачками, журнал растёт, и место кончается раньше, чем заканчивается регламент.
- Трансформатор SQL в 1С - переводит запрос из профайлера обратно в имена справочников и регистров. Нужен, когда видно, что база стоит, а чей это запрос непонятно.
- Карта объёмов базы 1С - что в базе занимает место и как быстро растёт. Обмены обычно оставляют следы именно в регистрах, и видно это только по объёмам.
Вступайте в нашу телеграмм-группу Инфостарт