Постановка проблемы
Недавно для решения одной задачи я начал писать микросервис: всё было хорошо, стори двигались, и кодовая база плавно, но верно росла. И в один прекрасный день мы начали ловить ошибки. Метод на один и тот же запрос отвечал или 200, или 502, что значило «Микросервис в данный момент не отвечает». Ничего страшного в этом не было: в сервисе еще только тестировали первые задачи. Это была отличная возможность потренироваться в поиске утечек памяти без вреда для нервной системы.
На тот момент мы использовали .NET 8.
Расследование: изучаем метрики
В сыром микросервисе у нас еще не было экспорта метрик в Grafana или чего-то подобного. Именно поэтому первым делом я смотрел метрики пода через kubectl.
1. Смотрим метрики всех подов
Команды kubectl top pod или kubectl top pod -n <namespace>, если у вас несколько неймспейсов. Если не знаете название неймспейса, то посмотрите их список командой kubectl get namecpace. Параметр -n можно передавать во все команды, далее о нём не говорим. Получаем подобный вывод:
Так можно увидеть, сколько каждый под занимает памяти (в мегабайтах) и CPU (в ядрах, в данном случае это millicore, равный 0,001 core).
Можно фильтровать выборку по конкретному поду: kubectl top pod hh-service-backend- 34yt13idgfe. В ответе получим то же самое для одного пода.
Если у вас в одном поде запущено несколько контейнеров, то можно посмотреть разбивку на ресурсы внутри пода командой kubectl top pod hh-service-backend-34yt13idgfe --containers.
2. Проверяем лимиты
Если вы вдруг не знаете, сколько ваш под запрашивает ресурсов в кубере при старте, и его лимиты, то проверяем их командой kubectl describe pod hh-service-backend-34yt13idgfe.
Ответ довольно большой, и весь нам не нужен, интересны только следующие строки:
Такой вывод означает, что под запрашивает на старте 0,1 ядра и 200 МБ памяти, а его лимит — 400 МБ.
Кроме того, в контексте задачи нас интересует поле Restart Count: 10 — количество рестартов пода. В хорошем случае оно должно быть равно 0.
3. Собираем метрику с пода по времени
Итак, в микросервисе не было сбора метрик, поэтому первым делом я анализировал ситуацию почти вручную. Себе в помощь написал команду для сбора значения памяти и вывода в файл get-memory.bat. Код ниже собирает данные из вывода команды kubectl в csv-файл.
@echo off
set POD=sourcing-integrator-backend-5797ccb6bf-4d4fx set NAMESPACE=dev
set OUTPUT_FILE=memory.csv set INTERVAL_SECONDS=5
:loop
for /f "tokens=3" %%m in ('kubectl top pod %POD% -n %NAMESPACE% --no-headers') do (
echo %date% %time%; %%m >> %OUTPUT_FILE%
)
echo Memory value written to %OUTPUT_FILE%
timeout /t %INTERVAL_SECONDS% /nobreak >nul goto loop
По полученным данным строим график и получаем следующую картину:
На этом этапе стало понятно, что память растет константно и постоянно вверх до перезапуска микросервиса.
Расследование: кастомный сбор метрик с вызовов методов API
Второй моей мыслью было, что где-то в проекте прячется вредоносный метод, который генерирует лишние долгоживущие объекты.
Для начала я решил проследить, сколько памяти и процессорного времени тратит каждый вызов API моего микросервиса. Для этого написал код, отслеживающий эту статистику до и после вызова.
В первую очередь нужен класс, который инкапсулирует всю логику сбора метрик внутри себя, у меня это ResourcesUsageAsyncWatcher. Основная идея в том, чтобы захватить AsyncLocal маркер на время запроса. Каждая смена контекста записывает использованную память в текущем потоке, а при срабатывании .Stop() останавливаем таймер и записываем время, прошедшее от инициализации экземпляра класса.
Полный код ResourcesUsageAsyncWatcher.
internal sealed class ResourcesUsageAsyncWatcher
{
private readonly ThreadLocal<(int ThreadId, long AllocatedBytes)?> contextStart = new();
private readonly Stopwatch timer = Stopwatch.StartNew(); private volatile bool isRunning = true;
public ResourcesUsageAsyncWatcher()
{
_ = new AsyncLocal<object>(OnContextChanged) { Value = true };
}
public ContextSwitchMetrics Totals { get; } = new(); public void Stop()
{
isRunning = false; timer.Stop();
Totals.AddElapsedMilliseconds(timer.ElapsedMilliseconds);
Totals.SetTotalBytes(GC.GetTotalAllocatedBytes());
contextStart.Dispose();
}
private void OnContextChanged(AsyncLocalValueChangedArgs<object> args)
{
if (!isRunning)
{
return;
}
var threadId = Environment.CurrentManagedThreadId; if (args.PreviousValue == null)
{
contextStart.Value = (threadId, GC.GetAllocatedBytesForCurrentThread());
return;
}
if (args.CurrentValue != null)
{
return;
}
var start = contextStart.Value; contextStart.Value = null;
// Выходим, если поток не тот или отсутствует контекст if (start == null || start.Value.ThreadId != threadId)
{
return;
}
Totals.AddAllocatedBytes(
GC.GetAllocatedBytesForCurrentThread() - start.Value.AllocatedBytes);
}
public sealed class ContextSwitchMetrics
{
private long allocatedBytes;
private long elapsedMilliseconds; private long totalBytes;
public long AllocatedBytes => allocatedBytes;
public long ElapsedMilliseconds => elapsedMilliseconds; public long TotalBytes => totalBytes;
internal void AddAllocatedBytes(long value) => Interlocked.Add(ref allocatedBytes, value);
internal void AddElapsedMilliseconds(long value) => Interlocked.Add(ref elapsedMilliseconds, value);
public void SetTotalBytes(long totalBytesNow) =>
{
Interlocked.Add(ref totalBytes, totalBytesNow);
}
}
}
Теперь можно использовать полученный класс там, где требуется измерять утечки памяти. Я написал Middleware и с его помощью ловил метрики на http-запросы в сервис.
internal class GcMetricsMiddleware : IMiddleware
{
public async Task InvokeAsync(HttpContext context, RequestDelegate next)
{
var resourceLogger = context.RequestServices.GetRequiredService<ILogger>
();
// создаём
var resourceWatcher = new ResourcesUsageAsyncWatcher();
// даём методу выполнится
await next(context);
// останавливаем сбор и логгируем информацию
resourceWatcher.Stop();
var totals = resourceWatcher.Totals; resourceLogger.Info(
"request {requestPath} resources: elapsedMilliseconds
{elapsedMilliseconds} allocatedBytes {allocatedBytes} totalBytes {totalBytes}",
context.Request.Path,totals.ElapsedMilliseconds, totals.AllocatedBytes,totals.TotalBytes);
}
}
Из таких логов можно сложить вполне неплохие метрики в Elastic search.
Если у вас лог в Elastic сразу разбивается на параметры, то удобно искать по ним. Для этого надо пройти по пути Elastic -> Dashboards -> Create dashboard -> Create visualization.
В фильтр ввести что-то вроде messageTemplate : "request {requestPath} resources: elapsedMilliseconds {elapsedMilliseconds} allocatedBytes {allocatedBytes} totalBytes {totalBytes}" and requestPath : "api/test".
Создать простой график с такими параметрами сначала для значения allocatedBytes, затем для totalBytes:
Получится график по выделяемой памяти на вызов метода:
И график изменения общей памяти, которую занимает микросервис:
График подтверждает результаты, полученные запросом в kubectl: память растет линейно и не сбрасывается. А каждый вызов метода создает еще больше долгоживущих объектов, которые сохраняются вплоть до рестарта сервиса.
Расследование: локальный запуск
Дальше я использовал встроенный профилировщик debug режима Jet Brains Rider и получил следующие результаты:
Как видно на графике, объекты коротко живут в 0-м и 1-м поколении и почти сразу отправляются во 2-е поколение GC. Это значит, что при работе приложения накапливается множество долгоживущих больших объектов. Эта память с высокой вероятностью не будет очищена до конца работы приложения.
Такую проблему решает переключение сборщика мусора .NET в серверный режим <ServerGarbageCollection>true</ServerGarbageCollection>. Одна строка в главном .csproj-файле исправляет проблему резервирования лишней памяти. Подробнее о настройках сборщика мусора можно почитать в официальной документации, например здесь, здесь и здесь.
После переключения режима GC картина значительно меняется. Большую часть памяти занимает поколение 0, а поколение 2 заполняется незначительно только после сборки мусора. Скорость потребления памяти частично снижается.
Немного эндорфинов к нашему столу! Наконец, картина улучшается, и микросервис ест существенно меньше памяти из пода. Но всё еще делает это постоянно и со временем перезапускается. Немного отпразднуем и идем дальше.
Расследование: проверка внешних зависимостей
После очередной неудачи я решил подойти к проблеме с другой стороны. Задался вопросом «Что объединяет методы, которые я вызывал при поиске проблемы?» и стал проверять их детальнее.
Покажу упрощенную версию — так будет понятнее. Допустим, есть два метода в контроллере:
Один из них вызывает математическую операцию, другой получает документ из базы. Смотрим, как влияет вызов каждого на наполнение памяти через профилировщик.
Есть две точки:
- Точка 1 — вызов
api/test/2. Он незначительно влияет на память. - Точка 2 — вызов
/{id}. А тут после вызова поколение 0 увеличивается значительнее и далее продолжает расти.
Я предположил, что может быть виноват вызов монги, и идем с ним дальше.
Расследование: разбор библиотеки монги
Анамнез собран, пораженный участок почти найден.
Что может увеличивать память при работе с монгой? А давайте спросим у нейросети!
Дело в том, что для микросервисов мы в команде используем отдельный фреймворк, который объединяет все используемые инструменты, среди них и обертка над Mongo.Driver. Она инкапсулирует в себе регистрацию драйвера, резолв коллекций, парсинг BsonDocument в типы .net, контексты и т. п.
Сразу отбрасываю сериализацию и большие документы, получается, что виноват драйвер монги. Давайте посмотрим на то, как он хранится в ConcurrentDictionary, где ключом является класс MongoClientSettings.
internal static class MongoClientStorage
{
private static readonly ConcurrentDictionary<MongoClientSettings, Lazy<MongoClient>> Clients =
new();
internal static MongoClient GetOrCreateMongoClient(MongoClientSettings settings)
{
return Clients.GetOrAdd(settings, static newSettings =>
new Lazy<MongoClient>(() => new MongoClient(newSettings))).Value;
}
}
Чтобы корректно представлять ключ, мы должны уметь их сравнивать, а для этого в C# присутствует интерфейс IEquatable<T> с одним-единственным методом Equals. «И в чём тут проблема?» — спросите вы. А дело в том, что при дебаге видно, что на КАЖДЫЙ вызов в монгу создаётся отдельный клиент. Значит, дело может быть в сравнении ключей, поэтому зайдем еще дальше — в сам фреймворк монги.
Как видим, класс MongoClientSettings реализует интерфейс IEquatable<MongoClientSettings>.
public class MongoClientSettings : IEquatable<MongoClientSettings>, IInheritableMongoClientSettings
Спускаемся ниже, к имплементации метода Equals (большая часть метода вырезана).
Тут сравниваются все без исключения поля методом Equals или ==, выглядит не очень Clean Code. Даже сложные вложенные поля сравниваются таким же образом.
public override bool Equals(object obj)
{
if (object.ReferenceEquals(obj, null) || GetType() != obj.GetType()) { return false; }
var rhs = (MongoClientSettings)obj; return
_allowInsecureTls == rhs._allowInsecureTls &&
_applicationName == rhs._applicationName &&
...
object.Equals(_libraryInfo, rhs._libraryInfo) &&
_replicaSetName == rhs._replicaSetName &&
_retryReads == rhs._retryReads &&
...
_serverMonitoringMode == rhs._serverMonitoringMode &&
_serverSelectionTimeout == rhs._serverSelectionTimeout &&
_socketTimeout == rhs._socketTimeout &&
...
object.Equals(_writeConcern, rhs._writeConcern)
}
Всё бы ничего, но дальше сравниваются делегаты Action<T> по ссылке:
private Action<ClusterBuilder> _clusterConfigurator;
...
public override bool Equals(object obj)
{
...
object.ReferenceEquals(_clusterConfigurator, rhs._clusterConfigurator)
...
}
А перед запросом MongoClient мы каждый раз заново заполняем MongoClientSettings значениями из строки подключения из appsettings.
Получается, код написан в целом неплохо, с оглядкой на то, что драйвер монги должен быть Singleton-объектом. Но сама реализация Equals в библиотеке Mongo.Driver ломает наш код: каждый раз когда мы делаем запрос на чтение/запись, нам нужно получить существующий в памяти драйвер по настройкам. Но сервис, отдающий драйвер, зарегистрирован как Scoped-сервис и создается на каждый запрос. Именно поэтому сложные поля Action<ClusterBuilder> ClusterConfigurator и LocalCertificateSelectionCallback ClientCertificateSelectionCallback тоже создаются каждый раз и имеют собственную ссылку в памяти. Значит, Equals возвращает False, и вместо получения существующего драйвера мы создаем новый, а старый продолжает храниться в памяти до перезагрузки приложения.
Исправление проблемы
Когда причина ясна, исправление кажется совсем легким занятием. Я увидел два варианта:
- Изменить подход к хранению настроек драйвера монги: хранить их в одном месте, а не создавать снова каждый раз.
- Изменить ключ, по которому хранится драйвер.
Но почему просто не хранить один драйвер — и всё? Всё просто: у нас может быть несколько кластеров монги с разными документами, поэтому драйверов может быть один, два или даже три в редких случаях.
Для фикса выбираю второй вариант и начинаю переписывать код хранения драйверов монги.
Главным изменением будет ключ хранения, я решил использовать имя кластера. Это изменение позволит избежать разночтений при получении клиента по ключу.
internal class MongoDbClientHolder : IMongoDbClientHolder
{
private readonly ConcurrentDictionary<string, Lazy<MongoClient>> _mongoClients
= new();
public MongoClient GetOrCreateMongoClient(string cluster, MongoClientSettings settings)
{
return _mongoClients.GetOrAdd( cluster,
_ => new Lazy<MongoClient>(() => new MongoClient(settings)))
.Value;
}
}
Теперь вызывающий код может просто передать название кластера из конфигурации или другого источника вместе с настройками и однозначно получить существующий клиент без дублей.
var client = _clientHolder.GetOrCreateMongoClient("Main", mainClientSettings);
На этом всё.
Заключение
Это было несколько тяжелых дней непростого расследования ошибки (с которыми в разработке приходится нередко встречаться). Мы с командой нашли брешь в коде собственного фреймворка, разобрались в нюансах реализации интерфейса IEquatable<T>, а также потренировались считать метрики и строить дашборды.
Какие выводы я сделал:
- не скупитесь на логи и метрики;
- пишите тесты всех уровней на библиотеки;
- проводите ревью кода, лучше, если это будут делать несколько человек;
- не бойтесь нейросетей;
- пейте магний (так спокойнее).
До новых встреч!
