Розповідь про те, як я за допомогою логів знайшов «пожирача» пам'яті

Розповідь про те, як я за допомогою логів знайшов «пожирача» пам'яті

Хочу поділитися простим, але, на мій погляд, цікавим способом пошуку місць породження пожирачів пам'яті при використанні мінімального набору інструментів, які завжди доступні під рукою - логи і 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! (не знаєш мови простих запитів - краще не виходь на вулицю баз даних). І друге - щоб вирішити на перших погляд складну задачу, зовсім не обов'язково мати «наворочені» інструменти.

Image