Рассказ о том, как я с помощью логов нашел «пожирателя» памяти

в 9:17, , рубрики: java, утечки памяти

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

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

Вариант профилирования памяти провалился – слишком много объектов создается в системе, и снять снапшот профилировщика за осмысленное время просто не удается. Снятие нескольких heap dump и их ручное сравнение дало зацепку – в системе находится неожиданно большое количество экземпляров одной и той же сущности Hibernate (чуть более миллиона). Здорово! Но как узнать, где порождается такое большое количество объектов? Искать по коду? Не вариант, придется делать поиск по всей системе, а времени в обрез – заказчик уже весь синеет.

На ум пришло следующее решение: почему бы не вставить в конструктор класса сущности логирование стека вызовов? Идея интересная… Был создан конструктор со следующим кодом:

...
protected static final Logger LOGGER = Logger.getLogger(Payment.class);

public Payment()
{
	// TODO : УБРАТЬ! ТОЛЬКО ДЛЯ ПОИСКА УТЕЧКИ ПАМЯТИ!
	StringBuilder stringBuilder = new StringBuilder();
	stringBuilder.append("MEMLEAK_TEST:Payment()n");
	StackTraceElement[] stackTraceElements = Thread.currentThread().getStackTrace();
	for (StackTraceElement stackTraceElement : stackTraceElements )
	{
		stringBuilder.append("   at "
				+ stackTraceElement.getClassName()
				+ "." + stackTraceElement.getMethodName()
				+ "(" + stackTraceElement.getFileName() + ":" + stackTraceElement.getLineNumber() + "n");
	}
	LOGGER.info(stringBuilder.toString());
}
...

Обновили промышленную систему и оставили на ночь. Наутро получили внушительные логи размеров в ~40 Гб. Ну что ж, приступим.

Для начала пришлось распилить логи на куски по 200 Мб, т.к. иначе такой объем просто не открыть. Беглый пробег по логам сразу позволил выделить стек вызовов, который встречается очень часто. По стеку вызов нашли класс, вызывающий функции Hibernate, и вот оно! Вот он — наш злополучный класс. В одном из его методов вытягивается список всех записей из таблицы (а количество записей в ней перевалило за 2 млн.) – а это и есть создание экземпляров нашей сущности. Далее код идет еще ужаснее: весь этот список перебирается в цикле и сравнивается по одному полю – этакая реализация фильтра. Конечно же, код был сразу же переписан (путем вставки условия в where HQL-запроса), а его автор был тут же расчленен наказ. Вот и все – таким вот «дедовским» методом была решена весьма «пикантная» проблема.

В качестве вывода: если сел писать код для работы с базой данных, учи SQL! (не знаешь языка простых запросов – лучше не выходи на улицу баз данных). И второе – чтобы решить на первых взгляд сложную задачу, вовсе не обязательно иметь «навороченные» инструменты.

Автор: TYSDEV

Источник

* - обязательные к заполнению поля


https://ajax.googleapis.com/ajax/libs/jquery/3.4.1/jquery.min.js