Я календарь переверну — и снова 5 апреля: CPU-утилизация во имя интернационализации

Я Антон Пронькин, разработчик в команде развития сервисов продаж для юридических лиц. Недавно наша команда столкнулась с необычным поведением системы, которая начала использовать избыточное количество CPU-ресурсов.

В начале года мы запустили миграцию сервиса в новое хранилище PostgreSQL с существующего NoSQL-решения. Сервис среднестатистический, не High-Load, но занимает ключевое место в обработке бизнес-процессов, отвечает за генерацию заданий для коммуникаций с клиентами. Без проблем держит поступающие 30 RPS, ежедневно обрабатывает около миллиона джобов, хранит сотни миллионов строк данных и в среднем потребляет 125ms CPU.

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

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

Достижение требований по утилизации CPU

Проходит очередной релиз для миграции таблицы в PostgreSQL с новой схемой. Новые фичи закрыты фичатоглами, пайплайн деплоя зеленый, обычный релиз здорового человека.

Ближе к вечеру прилетает алерт «Высокое потребление CPU».

Что-то пошло не так, и спустя час после релиза сервис начал потреблять значительно больше CPU, чем обычно, — более чем в 10 раз. Просадки после пиков — не улучшение ситуации, а случаи, когда k8s перезапускал контейнеры, которые выходили за разумные квоты.

Мы решили откатить версию, так как до релиза подобного поведения не наблюдалось. Параллельно смотрели на другие графики, чтобы оценить влияние и найти источник проблемы. На дашбордах ничего не вызывало подозрений. Потребление RAM не изменилось, RPS не увеличился, в Kafka сообщений поступать больше не стало, количество джобов держится стабильно.

Поднялась предыдущая версия приложения, но вот незадача: спустя 15 минут поды начали аналогично чем-то заражаться и потреблять предельное количество CPU, из-за чего сразу заработали себе маркер «больные».

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

• инфраструктурные изменения (например, изменения в инфраструктуре базы данных, обновления в k8s, обновления политик и т. д.);

• то, что проблему занесли не в последнем релизе, но только сейчас сработал триггер;

• ошибочные данные, которые раньше не получали.

Проверили бизнесовые процессы — работают штатно. Иногда сервис отвечает на запросы чуть дольше, чем обычно, но в пределах SLA. Сразу ничего найти не удалось, и мы решили продолжить на следующий день.

Новый день — новые открытия

Исследование метрик подсветило важный момент превышения утилизации CPU. На инстансах с проблемой начинают аллоцироваться гигабайты данных в короткий срок, при этом размеры куч (gen0, gen1, gen2, loh, poh) не увеличиваются, значит, аллоцируются небольшие объекты, которые сразу собираются GC.

Теория аллокации малых объектов и частой сборки подтвердилась метриками времени сборки мусора и частоты запусков GC.

Такой частый запуск GC может провоцировать потребление CPU с троттлингом, но все равно непонятно, что могло быть источником такого поведения.

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

Отбрасываем возможные причины, добавляем новые проблемы

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

Для исключения инфраструктурных зависимостей рассмотрели:

• все работы на используемых инстансах базы данных;

• перестроения в работе индексов и конекшенов; 

• изменения в политиках k8s; 

• расположение «больных» подов по кластерам и нодам k8s; 

• работы на кластерах Kafka.

Для исключения последних изменений в коде решили откатиться на 4 релиза назад. Откатываться на несколько версий опасно, потому что обратная совместимость часто соблюдается только для 1—2 релизов. Мы изучили все изменения и запустили релиз, но проблема продолжила воспроизводится и на коде двухнедельной давности.

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

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

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

Последними под нож попали фичатоглы чтения, а затем и записи данных в новые источники. Так мы исключали новую работу с PostgreSQL, но цена этого — нарушение миграции, из-за чего потребуется повторный запуск (+3 дня).

Обновили, передеплоили, и — о, чудо! — потребление нормализовалось. Вечер пятницы не подвел — на выходные ушли с облегчением.

Локализация проблемного кода

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

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

К концу дня все фичатоглы и джобы были включены, но… никаких аномалий на сервисе не заметили. Проблема самоустранилась? Будем ждать!

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

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

Смотрим под капот: снимаем дампы и профили

Параллельно исследованиям в поисках триггера не отпускала мысль о бесконечной аллокации ресурсов. К сожалению, проект большой, и даже агентский режим AI не справляется с поиском возможных проблем без каких-либо деталей. У нас есть завязка на память, а значит, потенциально может помочь снятие дампа с последующим анализом.

К сожалению, не удалось снять сырой дамп с контейнера в k8s, но SRE направили на утилиту Runtime Diagnostic Tools, которая позволяет снимать дампы с работающих инстансов.

Снимаем классический дамп памяти

Попробовали снять первый дамп. Артефакты дампа сохранились, открыть файл с расширением gcdump в графическом представлении с визуализацией связей можно в Visual Studio, но у нас MacOS. Попробуем для начала через утилиту от Microsoft dotnet-gcdump:

dotnet gcdump report dump.gcdump
 
     28,313,689  GC Heap bytes
        364,211  GC Heap objects
 
   Object Bytes 	Count  Type
        130,584     	1  System.Object[] (Bytes > 100K)  [System.Private.CoreLib.dll]
         98,352     	1  System.Int32[] (Bytes > 10K)  [System.Private.CoreLib.dll]
         64,366     	1  System.String (Bytes > 10K)  [System.Private.CoreLib.dll]
         22,080     	2  Entry<System.String,System.String>[] (Bytes > 10K)  [System.Private.CoreLib.dll]
         22,080     	1  Bucket[] (Bytes > 10K)  [System.Private.CoreLib.dll]
         20,046     	5  System.Char[] (Bytes > 10K)  [System.Private.CoreLib.dll]
         16,408    	   15  System.Byte[] (Bytes > 10K)  [System.Private.CoreLib.dll]
         16,344     	3  System.Object[] (Bytes > 10K)  [System.Private.CoreLib.dll]
...
(и еще 12420 строк)

Данных много, а полезность не очень высокая. Мы сортировали таблицу по объему памяти и количеству объектов, но в топе всегда были системные и примитивные типы. 

Мы осознали две вещи:

1. Нужен инструмент просмотра дампов помощнее консоли.

2. Дамп может не показать источник проблемы. По графикам видно, что данные быстро собираются GC и утечки памяти в прямом смысле нет, поэтому нужно запускать профайлер, который покажет затраченное время по операциям.

Профайлинг с анализом в Pyroscope

У Runtime Diagnostic Tools есть отличный инструмент Continuous-profiling, который запускает профайлинг на время, а затем позволяет визуально изобразить его в Pyroscope. Запускаем!

Открываем в режиме Diff View профили с двух подов: проблемного и не проблемного. Так можно подсветить различия в использовании процессорного времени.

Если снимать профили с одного пода (до начала проблемы и после), на картинке будет больше серых зон, так как потоки и стеки вызовов смогут сматчиться друг с другом. Для большинства красных столбцов можно найти соответствующие зеленые столбцы примерно той же ширины и высоты. Но на глаза попадаются столбцы, для которых нет аналогичных по ширине и высоте.

Подозрения начал вызывать класс PersonalBeforeCalculator, но строгих доказательств для его обвинения пока не было.

Профайлинг для бедных — смотрим в браузере

Параллельно анализу профилей через Pyroscope мой коллега пробовал снять профиль и открыть его в альтернативных инструментах. Runtime Diagnostic Tools поддерживает снятие обычного профиля за выбранный промежуток времени.

В итоге получили профиль в формате nettrace и вопрос «Чем это открыть?». От того же Microsoft есть утилита dotnet-trace. Сама по себе отрисовать профиль она не сможет, но конвертировать в другие форматы — без проблем! Например, можно одной командой конвертировать в тип, который понятен для Chromium, — даже скачивать вьюеры не придется.

dotnet trace convert profile.nettrace --format chromium -o profile_chromium

Открываем сконвертированный профиль в Chrome (chrome://tracing) и смотрим на профиль в разрезе про тредам. 

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

Тред, занятый одной операцией, — не приближенный скриншот. Ширина этого стека вызовов соответствует потоку выше. По методам видим уже знакомый PersonalBeforeCalculator — можно начинать его подозревать.

Нестареющая классика: работаем с Visual Studio под Windows

Одновременно с предыдущими исследованиями мы открыли профиль в Visual Studio, который расставил все точки над i. В блоке выделений памяти увидели большой объем, занимаемый типами для работы с датами.

Почти 50 ГБ выделений на типы Period и классы для работы с таймзонами! В коде у нас единственный потребитель этих классов — тот самый PersonalBeforeCalculator. Для сравнения приведу аллокации честного контейнера.

Допрос подозреваемого PersonalBeforeCalculator

Параллельно тремя разными способами мы вышли на одну и ту же сущность — PersonalBeforeCalculator. Небольшой класс, который определяет календарную дату и время по рабочим часам (рабочим интервалам, в бизнесовом контексте — интервалам доступности). 

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

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

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

Исследуя класс, заметили самое подозрительное место — цикл while с перебором доступных дней. Непонятно только, почему спустя 6 лет бесперебойной работы он начал барахлить.

while (periodLeft.ToDuration() > periodToday.ToDuration()) // Пока остались нераспределенные часы
{
    periodToday = await WorkPeriodToday(plannedDate);      // Получаем доступные часы сегодня (учитывая выходные, праздники, интервалы доступности)
    periodLeft -= periodToday;                             // Вычитаем из нераспределенных часов сегодняшние
 
    plannedDate = plannedDate.Plus(Duration.FromDays(1)).Date.AtStartOfDayInZone(timeZone);  // Переходим на следующий день
}

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

Мы проверили входные параметры по логам — все значения в допустимых пределах. Первоначальные periodLeft, plannedDate, timeZone имеют корректные, адекватные значения. AI сканировал класс несколько раз, но не нашел входных значений, при которых сервис входит в бесконечный цикл с подобными симптомами.

Оставалась только console.log-отладка — добавляем избыточное логирование под фичатоглом, и на прод.

В предвкушении локализации проблемы мы следили за логами. Но судьба распорядилась иначе: плавающая проблема снова ушла. 

Ловля с поличным

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

Попался! По логам увидели экстремальное количество итераций цикла.

Развернутые логи показали, что дни обрабатываются корректно, но, дойдя до 5 апреля, зацикливаются. Скорее всего, 5 апреля конец света, происходит какая-то магия с таймзонами.

Для данного случая таймзона — Australia/Sydney. Уже настораживает, ведь целевая аудитория нашего направления — жители РФ. Но из кода никогда таких ограничений не было, мы всегда обрабатывали их корректно.

Что же происходит в Австралии 5 апреля? Время начинает идти наоборот? 

Математика против реальности: проблемы часовых поясов

Мы собрали юнит-тест с проблемными данными и запустили дебаг в режиме лайвкодинга. Вся команда разработки наблюдала и ждала развязки.

[Fact]
public void CalculateNextDay()
{
    var timezone = DateTimeZoneProviders.Tzdb["Australia/Sydney"];
 
    var dayLocal = new LocalDateTime(2026, 4, 5, 0, 0);
    var nextDayLocal = new LocalDateTime(2026, 4, 6, 0, 0);
 
    var day = dayLocal.InZoneStrictly(timezone);
    var nextDay = day.Plus(Duration.FromDays(1));
 
    Assert.Equal(nextDayLocal.InZoneStrictly(timezone), nextDay);
}

Когда мы заметили результаты работы day.Plus(Duration.FromDays(1)), сначала сложилось впечатление, что случилась магия уровня Австралии. Написанный тест падал с ошибкой несоответствия ожидаемой даты. 

Expected: 2026-04-06 00:00:00 Australia/Sydney (+10)
Actual:   2026-04-05 23:00:00 Australia/Sydney (+10)

Мы приблизились к разгадке дня X. Вероятно, не сразу, но можно найти ответ.

В момент прибавления суток под капотом в UTC к Instant справедливо добавлялось 24 часа из Duration. Только новая дата имела другой часовой пояс (+10 вместо +11), из-за чего перевод в ZonedDateTime возвращал именно 23:00 предыдущего дня и цикл застревал в прошлых сутках.

Запуск калькулятора происходит по ряду условий при выполнении джобов. В нашем случае инстанс брал джоб и входил в бесконечную обработку, а спустя время он становился протухшим и брался в работу новым инстансом, что объясняет постепенное начало влияния в каждом контейнере.

В цикле крылась проблема: получалась смесь вычислений в UTC и специфичной таймзоне, причем неявно, под капотом. Для решения проблемы можно проводить вычисления только в UTC или только в специфической таймзоне. Для нас предпочтительным оказался второй вариант, так как большинство вычислений основаны на локальном времени клиента. Сделали фикс — юнит-тест прошел! 

[Fact]
public void CalculateNextDay()
{
    var timezone = DateTimeZoneProviders.Tzdb["Australia/Sydney"];
 
    var dayLocal = new LocalDateTime(2026, 4, 5, 0, 0);
    var nextDayLocal = new LocalDateTime(2026, 4, 6, 0, 0);
 
    var day = dayLocal.InZoneStrictly(timezone);
    // var nextDay = day.Plus(Duration.FromDays(1)); 
    var nextDay = day.LocalDateTime.PlusDays(1).InZoneStrictly(timezone); 
 
    Assert.Equal(nextDayLocal.InZoneStrictly(timezone), nextDay);
}

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

Как ложные триггеры привели к ложным выводам 

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

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

Выводы

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

Список выводов на основе траблшутинга:

1. Для сервисов должны быть настроены алерты на высокое потребление CPU и троттлинг.

2. Инструменты диагностики рантайма помогают находить узкие места в сервисе, могут быть установлены заранее и пригодиться в будущем.

3. Важно задавать условия принудительного выхода из цикла. Например, ограничение на количество итераций.

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

5. Иногда баги выстреливают только через годы, когда меньше всего ждешь.

6. Закон Мерфи работает в ИТ не хуже, чем в жизни.

Несмотря на пройденные трудности, я благодарен команде за вовлечение и мощный технический брейншторм. А как часто вы сталкивались с проблемами часовых поясов? Буду рад обсудить ваши сценарии в комментариях.