Вчера вечером один из наших сервисов перешёл в странное состояние. Занял всю свободную память (около 5 Гб), но еще продолжал работать. При этом обычное потребление составляло 200-300 Мб. В общем, проблему решили традиционным для утечек памяти способом – сделали дамп памяти через Process Explorer, и перезапустили сервис.
Анализ дампа через WinDebug показал огромное количество объектов типа LogEventInfo, и сопутствующих ему объектов. Если коротко – то во всём виноват NLog. Почему такое произошло было непонятно, но решили посмотреть как будет развиваться ситуация. Весь вечер ничего подозрительного не происходило. Однако утром сервис скушал уже около 1Гб памяти, и потихоньку продолжал набивать себя байтами. Надо было что-то срочно менять.
Для начала я просмотрел все файлы логов, и обнаружил - один из них отстаёт от жизни на 8 минут. Остальные шли строго по графику. Нагрузки на диск тоже не наблюдалось. Тогда исследовал конфигурацию проблемного логгера:
На таких конфигурациях работало 7 target'ов. Но сломался только один, нагрузка на который была особенно интенсивной (8-10 ГБ в сутки). Изучение документации на AsyncWrapper показало наличие интересного параметра batchSize:
batchSize - Number of log events that should be processed in a batch by the lazy writer thread. Integer Default: 100
Т.е. в нашем случае AsyncWrapper сбрасывал не более 100 событий за один раз. При этом параметр timeToSleepBetweenBatches равен 500 мс (значение по-умолчанию 50 мс приводило к очень серьёзной загрузке ЦП, поэтому мы брали больший интервал). Итого NLog записывал на диск не более 200 записей в секунду. Очевидно, надо было попробовать увеличить количество записей. Кроме того, проконсультировавшись с документаций на FileTarget, увеличил размер буфера записи. В итоге получилась такая конфигурация:
Через полминуты сервис вернулся к своему обычному состоянию. Мораль - внимательно изучайте возможности своих инструментов!
Комментариев нет:
Отправить комментарий