NLog. Memory Leak.

Вчера вечером один из наших сервисов перешёл в странное состояние. Занял всю свободную память (около 5 Гб), но еще продолжал работать. При этом обычное потребление  составляло 200-300 Мб. В общем, проблему решили традиционным для утечек памяти способом – сделали дамп памяти через Process Explorer, и перезапустили сервис.

Анализ дампа через WinDebug показал огромное количество объектов типа LogEventInfo, и сопутствующих ему объектов. Если коротко – то во всём виноват NLog. Почему такое произошло было непонятно, но решили посмотреть как будет развиваться ситуация. Весь вечер ничего подозрительного не происходило. Однако утром сервис скушал уже около 1Гб памяти, и потихоньку продолжал набивать себя байтами. Надо было что-то срочно менять.

Для начала я просмотрел все файлы логов, и обнаружил - один из них отстаёт от жизни на 8 минут. Остальные шли строго по графику. Нагрузки на диск тоже не наблюдалось. Тогда исследовал конфигурацию проблемного логгера:

	<target
	name="ServiceLog"
	xsi:type="AsyncWrapper"
	overflowAction="Grow"
	timeToSleepBetweenBatches="500">
	<target
	xsi:type="File"
	fileName="${rootfolder}\ServiceLog.${date:format=yyyy-MM-dd}.log"
	layout="${detailedLayout}"/>
	</target>
	</target>

view raw nlog-orig.xml hosted with ❤ by GitHub

На таких конфигурациях работало 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, увеличил размер буфера записи. В итоге получилась такая конфигурация:

	<target
	name="ServiceLog"
	xsi:type="AsyncWrapper"
	overflowAction="Grow"
	timeToSleepBetweenBatches="500"
	batchSize="10000">
	<target
	xsi:type="File"
	fileName="${rootfolder}\ServiceLog.${date:format=yyyy-MM-dd}.log"
	layout="${detailedLayout}"
	bufferSize="1048576"/>
	</target>
	</target>

view raw NLog-fixed.xml hosted with ❤ by GitHub

Через полминуты сервис вернулся к своему обычному состоянию. Мораль - внимательно изучайте возможности своих инструментов!