Как бороться с OutOfMemoryError на практике, или ох уж мне эти базы данных

Приветствую!

В этой статье я постараюсь разжевать, что делать с дампами в Java, как понять причину или приблизиться к причине возникновения OOM, посмотреть на инструменты для анализа дампов, инструмент (один, да) для мониторинга хипа, и вообще вникнуть в это дело для общего развития. Исследуются такие инструменты, как JVisualVM (рассмотрю некоторые плагины к нему и OQL Console), Eclipse Memory Analyzing Tool.
Очень много понаписал, но надеюсь, что всё только по делу :)

Предыстория

Для начала нужно понять, как возникает OOM. Кому-то это может быть ещё неизвестно.
Представьте себе, что есть какой-то верхний предел занимаемой оперативки для приложения. Пусть это будет гигабайт ОЗУ.
Само по себе возникновение OOM в каком-то из потоков ещё не означает, что именно этот поток «выжрал» всю свободную память, да и вообще не означает, что именно тот кусок кода, который привёл к OOM, виноват в этом.
Вполне нормальна ситуация, когда какой-то поток чем-то занимался, поедая память, «дозанимался» этим до состояния «ещё немного, и я лопну», и завершил выполнение, приостановившись. А в это время какой-то другой поток решил запросить для своей маленькой работы ещё немного памяти, сборщик мусора попыжылся, конечно, но мусора уже в памяти не нашёл. В этом случае как раз и возникает OOM, не связанный с источником проблемы, когда стектрейс покажет совсем не того виновника падения приложения.

Есть и другой вариант. Около недели я исследовал, как улучшить жизнь парочки наших приложений, чтобы они перестали себя нестабильно вести. И ещё недельку-две потратил на то, чтобы привести их в порядок. В общей сложности пара недель времени, которые растянулись на полтора месяца, ведь занимался я не только этими проблемами.
Из найденного: сторонняя библиотека, и, конечно же, некоторые неучтённые вещи в вызовах хранимых процедур.
В одном приложении симптомы были следующие: в зависимости от нагрузки на сервис, оно могло упасть через сутки, а могло через двое. Если помониторить состояние памяти, то было видно, что приложение постепенно набирало «размер», и в определённый момент просто ложилось.
С другим приложением несколько интереснее. Оно может вести себя хорошо длительный срок, а могло перестать отвечать минут через 10 после перезагрузки, или вдруг внезапно упасть, сожрав всю свободную память (это я уже сейчас вижу, наблюдая за ним). А после обновления версии, когда была изменена и версия Tomcat с 7й до 8й, и JRE, оно вдруг в одну из пятниц (проработав вменяемо до этого ни много ни мало — 2 недели) начало творить такие вещи, что стыдно признаваться в этом. :)

В обоих историях очень полезны оказались дампы, благодаря им удалось отыскать все причины падений, подружившись с такими инструментами, как JVisualVM (буду называть его JVVM), Eclipse Memory Analyzing Tool (MAT) и языком OQL (может быть я не умею его правильно готовить в MAT, но мне оказалось легче подружиться с реализацией OQL именно в JVVM).
Ещё вам понадобится свободная оперативка для того, чтобы было куда загружать дампы. Её объём должен быть соизмерим с размером открываемого дампа.

Начало

Итак, начну потихоньку раскрывать карты, и начну именно с JVVM.

Этот инструмент в соединении с jstatd и jmx позволяет удалённо наблюдать за жизнью приложения на сервере: Heap, процессор, PermGen, количество потоков и классов, активность потоков, позволяет проводить профилирование.
Также JVVM расширяем, и я не преминул воспользоваться этой возможностью, установив некоторые плагины, которые позволили куда больше вещей, например, следить и взаимодействать с MBean'ами, наблюдать за деталями хипа, вести длительное наблюдение за приложением, держа в «голове» куда больший период метрик, чем предоставляемый вкладкой Monitor час.

Вот так выглядит набор установленных плагинов.
Visual GC (VGC) позволяет видеть метрики, связанные с хипом.

Детальнее о том, из чего состоит хип в этой нашей Java

Вот два скриншота вкладки VGC, которые показывают, как ведут себя два разных приложения.
Слева Вы можете увидеть такие разделы хипа, как Perm Gen, Old Gen, Survivor 0, Survivor 1, и Eden Space.
Все эти составляющие — участки в оперативке, в которую и складываются объекты.
PermGen — Permanent Generation — область памяти в JVM, предназначенная для хранения описания классов Java и некоторых дополнительных данных.
Old Gen — это область памяти для достаточно старых объектов, которые пережили несколько перекладываний с места на место в Survivor-областях, и в момент какого-то очередного переливания попадают в область «старых» объектов.
Survivor 0 и 1 — это области, в которые попадают объекты, которые после создания объекта в Eden Space пережили его чистку, то есть не стали мусором на момент, когда Eden Space начал чиститься Garbage Collector'ом (GC). При каждом запуске чистки Eden Space объекты из активного в текущий момент Survivor'а перекладываются в пассивный, плюс добавляются новые, и после этого Survivor'ы меняются статусами, пассивный становится активным, а активный — пассивным.
Eden Space — область памяти, в которой новые объекты порождаются. При нехватке памяти в этой области запускается цикл GC.

Каждая из этих областей может быть отрегулирована по размеру в процессе работы приложения самой виртуальной машиной.
Если вы указываете -Xmx в 2 гигабайта, например, то это не означает, что все 2 гигабайта будут сразу же заняты (если не запускать сразу что-то активно кушающее память, конечно же). Виртуальная машина сначала постарается держать себя «в узде».
На третьем скриншоте видно неактивную стадию приложения, которое не используется на выходных — Eden растёт равномерно, Survivor'ы перекладываются через равные промежутки времени, Old практически не растёт. Приложение проработало больше 90 часов, и в принципе JVM считает, что приложению требуется не так уж и много, около 540 МБ.

Бывают пиковые ситуации, когда виртуальная машина даже выделяет под хип гораздо больше памяти, но я думаю, что это какие-то ещё «неучтёнки», о которых я расскажу детальнее ниже по тексту, а может просто виртуальная машина выделила больше памяти под Eden, например, чтобы объекты в нём успевали стать мусором до следующего цикла очистки.

Участки, которые на следующем скриншоте я обозначил красным — это как раз возрастание Old, когда некоторые объекты не успевают стать мусором, чтобы быть удалёнными из памяти ранее, и всё-таки попадают в Old. Синий участок — исключение. На протяжении красных участков можно видеть гребёнку — это Eden так себя ведёт.

На протяжении синего участка скорее всего виртуальная машина решила, что нужно увеличить размер Eden-области, потому как при увеличении масштаба в Tracer'е видно, что GC перестал «частить» и таких мелких колебаний, как ранее, теперь нет, колебания стали медленными и редкими.

Перейдём ко второму приложению:

В нём Eden напоминает мне какой-то уровень из Mortal Kombat, арену с шипами. Была такая, кажется… А График GC — шипы из NFS Hot Pursuit, вот те вот, плоские ещё.
Числа справа от названий областей указывают:
1) что Eden имеет размер в 50 мегабайт, и то, что нарисовано в конце графика, последнее из значений на текущий момент — занято 25 мегабайт. Всего он может вырости до 546 мегабайт.
2) что Old может вырасти до 1,333 гига, сейчас занимает 405 МБ, и забит на 145,5 МБ.
Так же для Survivor-областей и Perm Gen.
Для сравнения — вот Вам Tracer-график за 75 часов работы второго приложения, думаю, кое-какие выводы вы сможете сделать из него. Например, что активная фаза у этого приложения — с 8:30 до 17:30 в рабочие дни, и что даже на выходных оно тоже работает :)

Если вы вдруг увидели в своём приложении, что Old-область заполнена — попробуйте просто подождать, когда она переполнится, скорее всего она заполнена уже мусором.

Мусор — это объекты, на которые нет активных ссылок из других объектов, или целые комплексы таких объектов (например, какое-то «облако» взаимосвязанных оъектов может стать мусором, если набор ссылок указывает только на объекты внутри этого «облака», и ни на один объект в этом «облаке» ничто не ссылается «снаружи»).

Это был краткий пересказ того, что я узнал про структуру хипа за время, пока гуглил.

Предпосылки

Итак, случилось сразу две вещи:
1) после перехода на более новые библиотеки/томкеты/джавы в одну из пятниц приложение, которое я уже долгое время веду, вдруг стало вести себя из рук вон плохо спустя две недели после выставления.
2) мне на рефакторинг отдали проект, который тоже вёл себя до некоторого времени не очень хорошо.

Я уже не помню, в каком точно порядке произошли эти события, но после «чёрной пятницы» я решил наконец-то разобраться с дампами памяти детальнее, чтобы это более не было для меня чёрным ящиком. Предупреждаю, что какие-то детали я мог уже запамятовать.

По первому случаю симптомы были такие: все потоки, отвественные за обработку запросов, выжраны, на базу данных открыто всего 11 коннектов, и те не сказать, что используются, база говорила, что они в состоянии recv sleep, то есть ожидают, когда же их начнут использовать.
После перезагрузки приложение оживало, но прожить могло недолго, вечером той же пятницы жило дольше всего, но уже после окончания рабочего дня таки снова свалилось. Картина всегда была одинаковой: 11 коннектов к базе, и лишь один, вроде бы, что-то делает.
Память, кстати, была на минимуме. Сказать, что OOM привёл меня к поиску причин, не могу, однако полученные знания при поиске причин позволили начать активную борьбу с OOM.

Когда я открыл хип в JVVM, из него было сложно что-либо понять.

Подсознание подсказывало, что причина где-то в работе с базой.
Поиск среди классов сказал мне, что в памяти аж 29 DataSource, хотя должно быть всего 7.

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

OQL

Сидеть переклацывать в просмотровщике все эти объекты было некогда, и моё внимание наконец-то привлекла вкладка OQL Console, я подумал, что вот он, момент истины — я или начну использовать её на полную катушку, или так и забью на всё это.

Прежде, чем начать, конечно же был задан вопрос гуглу, и он любезно предоставил шпаргалку (cheat sheet) по использованию OQL в JVVM: http://visualvm.java.net/oqlhelp.html

Сначала обилие сжатой информации привело меня в уныние, но после применения гугл-фу на свет таки появился вот такой OQL-запрос:

select {instance: x, uri: x.url.toString(), connPool: x.connectionPool}
from org.apache.tomcat.dbcp.dbcp2.BasicDataSource x
where x.url != null
&& x.url.toString() == "jdbc:sybase:Tds:айпишник:порт/базаДанных"

Это уже исправленная и дополненная, финальная версия этого запроса :)
Результат можно увидеть на скриншоте:

После нажатия на BasicDataSource#7 мы попадаем на нужный объект во вкладке Instances:

Через некоторое время до меня дошло, что есть одно несхождение с конфигурацией, указанной в теге Resource в томкете, в файле /conf/context.xml. Ведь в дампе параметр maxTotal имеет значение 8, в то время, как мы указывали maxActive равным 20…

Тут-то до меня и начало доходить, что приложение жило с неправильной конфигурацией пула коннектов все эти две недели!
Для краткости напишу тут, что в случае, если вы используете Tomcat и в качестве пула коннектов — DBCP, то в 7м томкете используется DBCP версии 1.4, а в 8м томкете — уже DBCP 2.0, в котором, как я потом выяснил, решили переименовать некоторые параметры! А про maxTotal вообще на главной странице сайта написано :)
http://commons.apache.org/proper/commons-dbcp/
«Users should also be aware that some configuration options (e.g. maxActive to maxTotal) have been renamed to align them with the new names used by Commons Pool 2.»

Причины

Обозвал их по всякому, успокоился, и решил разобраться.
Как оказалось, класс BasicDataSourceFactory просто напросто получает этот самый Resource, смотрит, есть ли нужные ему параметры, и забирает их в порождаемый объект BasicDataSource, молча игнорируя напрочь всё, что его не интересует.
Так и получилось, что они переименовали самые весёлые параметры, maxActive => maxTotal, maxWait => maxWaitMillis, removeAbandoned => removeAbandonedOnBorrow & removeAbandonedOnMaintenance.
По умолчанию maxTotal, как и ранее, равен 8; removeAbandonedOnBorrow, removeAbandonedOnMaintenance = false, maxWaitMillis устанавливается в значение «ждать вечно».
Получилось, что пул оказался сконфигурирован с минимальным количеством коннектов; в случае, если заканчиваются свободные коннекты — приложение молча ждёт, когда они освободятся; и добивает всё молчанка в логах по поводу «заброшенных» коннектов — то, что могло бы сразу показать, в каком именно месте программист мудак код хватает коннект, но не отдаёт его обратно по окончанию своей работы.
Это сейчас вся мозаика сложилась быстро, а добывались эти знания дольше.

«Так быть не должно», решил я, и запилил патчик (https://issues.apache.org/jira/browse/DBCP-435, выразился в http://svn.apache.org/viewvc/commons/proper/dbcp/tags/DBCP_2_1/src/main/java/org/apache/commons/dbcp2/BasicDataSourceFactory.java?view=markup ), патч был принят и вошёл в версию DBCP 2.1. Когда и если Tomcat 8 обновит версию DBCP до 2.1+, думаю, что админам откроются многие тайны про их конфигурации Resource :)

По поводу этого происшествия мне лишь осталось рассказать ещё одну деталь — какого чёрта в дампе было аж 29 DataSource'ов вместо всего 7 штук. Разгадка кроется в банальной арифметике, 7*4=28 +1=29.

После этого всё стало ясно: 11 коннектов было потому, что в одном, активном DataSource было съедено 8 коннектов (maxTotal = 8), и ещё по minIdle=1 в трёх других неиспользуемых DataSource-копиях.

В ту пятницу мы откатились на Tomcat 7, который лежал рядышком, и ждал, когда от него избавятся, это дало время спокойно во всём разобраться.
Плюс позже, уже на TC7, обнаружилась утечка коннектов, всё благодаря removeAbandoned+logAbandoned. DBCP радостно сообщил в логфайл catalina.log о том, что

"org.apache.tomcat.dbcp.dbcp.AbandonedTrace$AbandonedObjectException: DBCP object created 2015-02-10 09:34:20 by the following code was never closed:
	at org.apache.tomcat.dbcp.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java:139)
	at org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:81)
	at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
	at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
	at наш.пакет.СуперКласс.getConnection(СуперКласс.java:100500)
	at наш.пакет.СуперКласс.плохойПлохойМетод(СуперКласс.java:100800)
	at наш.пакет.СуперКласс.вполнеВменяемыйМетод2(СуперКласс.java:100700)
	at наш.пакет.СуперКласс.вполнеВменяемыйМетод1(СуперКласс.java:100600)
	ещё куча строк..."

Вот этот вот плохойПлохойМетод имеет в сигнатуре Connection con, но внутри была конструкция «con = getConnection();», которая и стала камнем преткновения. СуперКласс вызывается редко, поэтому на него и не обращали внимания так долго. Плюс к этому, вызовы происходили, я так понимаю, не во время рабочего дня, так что даже если что-то и подвисало, то никому уже не было дела до этого. А в ТуСамуюПятницу просто звёзды сошлись, начальнику департамента заказчика понадобилось посмотреть кое-что :)

Приложение №2

Что же касается «события №2» — мне отдали приложение на рефакторинг, и оно на серверах тут же вздумало упасть.
Дампы попали уже ко мне, и я решил попробовать поковырять и их тоже.
Открыл дамп в JVVM, и «чё-то приуныл»:

Что можно понять из Object[], да ещё и в таком количестве?
( Опытный человек, конечно же, увидел уже причину, правда? :) )

Так у меня зародилась мысль «ну неужели никто ранее не занимался этим, ведь наверняка уже есть готовый инструмент!». Так я наткнулся на этот вопрос на StackOverflow: http://stackoverflow.com/questions/2064427/recommendations-for-a-heap-analysis-tool-for-java.
Посмотрев предложенные варианты, я решил остановиться на MAT, надо было попробовать хоть что-то, а это открытый проект, да ещё и с куда бОльшим количеством голосов, чем у остальных пунктов.

Eclipse Memory Analyzing Tool

Итак, MAT.
Рекомендую скачивать последнюю версию Eclipse, и устанавливать MAT туда, потому как самостоятельная версия MAT ведёт себя плохо, там какая-то чертовщина с диалогами, в них не видно содержимого в полях. Быть может кто-то подскажет в комментариях, чего ему не хватает, но я решил проблему, установив MAT в Eclipse.

Открыв дамп в MAT я запросил выполнение Leak Suspects Report.


Удивлению не было предела, честно говоря.

1.2 гига весят соединения в базу.

Каждое соединение весит от 17 до 81 мегабайта.

Ну и ещё «немного» сам пул.
Визуализировать проблему помог отчёт Dominator Tree:

Причиной всех падений оказались километры SQLWarning'ов, база настойчиво пыталась дать понять, что «010SK: Database cannot set connection option SET_READONLY_TRUE.», а пул коннектов BoneCP не вычищает SQLWarning'и после освобождения и возврата коннектов в пул (может быть это где-то можно сконфигурировать? Подскажите, если кто знает).
Гугл сказал, что такая проблема с Sybase ASE известна ещё с 2004 года: https://forum.hibernate.org/viewtopic.php?f=1&t=932731
Если вкратце, то «Sybase ASE doesn't require any optimizations, therefore setReadOnly() produces a SQLWarning.», и указанные решения всё ещё работают.
Однако это не совсем решение проблемы, потому как решение проблемы — это когда при возврате соединения в пул все уведомления базы очищаются в силу того, что они уже никогда никому не понадобятся.
И DBCP таки умеет делать это: http://svn.apache.org/viewvc/commons/proper/dbcp/tags/DBCP_1_4/src/java/org/apache/commons/dbcp/PoolableConnectionFactory.java?view=markup, метод passivateObject(Object obj), в строке 687 можно увидеть conn.clearWarnings();, этот вызов и спасает от километров SQLWarning'ов в памяти.
Об этом я узнал из тикета: https://issues.apache.org/jira/browse/DBCP-102
Также мне подсказали про вот такой тикет в багтрекере: https://issues.apache.org/jira/browse/DBCP-234, но он касается уже версии DBCP 2.0.

В итоге я перевёл приложение на DBCP (пусть и версии 1.4). Пусть нагрузка на сервис и немаленькая (от 800 до 2к запросов в минуту), но всё же приложение ведёт себя хорошо, а это главное. И правильно сделал, потому как BoneCP уже пять месяцев не поддерживается, правда, ему на смену пришёл HikariCP. Нужно будет посмотреть, как дела в его исходниках…

Сражаемся с OOM

Впечатлившись тем, как MAT мне всё разложил по полочкам, я решил не забрасывать этот действенный инструмент, и позже он мне пригодился, потому как в первом приложении ещё остались всяческие «неучтёнки» — неучтённые вещи в коде приложения или коде хранимых процедур, которые иногда приводят к тому, что приложение складывает ласты. Я их отлавливаю до сих пор.

Вооружившись обоими инструментами, я принялся ковырять каждый присланный дамп в поисках причин падения по OOM.
Как правило все OOM приводили меня к TaskThread.

И если нажать на надпись See stacktrace, то да, это будет как раз банальный случай, когда какой-то поток вдруг внезапно упал при попытке отмаршалить результат своей работы.

Однако здесь ничто не указывает на причину возникновения OOM, здесь лишь результат. Найти причину мне пока-что, в силу незнания всей магии OQL в MAT, помогает именно JVVM.
Загружаем дамп там, и пытаемся отыскать причину!

Искать мне следует, конечно же, именно вещи, связанные с базой данных, а посему попробуем сначала посмотреть, есть ли в памяти Statement'ы.

Два SybCallableStatement, и один SybPreparedStatement.
Думаю, что дело усложнится, если Statement'ов будет куда больше, но немного подрихтовав один из следующих запросов, указав в where нужные условия, думаю, всё у Вас получится. Плюс, конечно же, стоит хорошенько посмотреть в MAT, что за результаты пытается отмаршалить поток, какой объект, и станет понятнее, какой именно из Statement'ов необходимо искать.

select {
    instance: x,
    stmtQuery: x._query.toString(),
    params: map(x._paramMgr._params, function(obj1) {
            if (obj1 != null) {
                if (obj1._parameterAsAString != null) {
                    return '''+obj1._parameterAsAString.toString()+''';
                } else {
                    return "null";
                }
            } else {
                return "null";
            }
        })
    }
from com.sybase.jdbc4.jdbc.SybCallableStatement x
where x._query != null

Не то, это «внутренние» вызовы.

select {
    instance: x,
    stmtQuery: x._query.toString(),
    params: map(x._paramMgr._params, function(obj1) {
            if (obj1 != null) {
                if (obj1._parameterAsAString != null) {
                    return '''+obj1._parameterAsAString.toString()+''';
                } else {
                    return "null";
                }
            } else {
                return "null";
            }
        })
    }
from com.sybase.jdbc4.jdbc.SybPreparedStatement x
where x._query != null

А вот и дичь!
Для чистоты эксперимента можно кинуть такой же запрос в любимой БД-IDE, и он будет очень долго отрабатывать, а если покопаться в недрах хранимки, то будет понятно, что там просто из базы, которая нам не принадлежит, выбирается 2 миллиона строк по такому запросу с такими параметрами. Эти два миллиона даже влазят в память приложения, но вот попытка отмаршалить результат становится фатальной для приложения. Такое себе харакири. :)
При этом GC старательно убирает все улики, но не спасло его это, всё же источник остался в памяти, и он будет наказан.

Почему-то после всего этого рассказа почувствовал себя тем ещё неудачником.

Прощание

Вот и закончилось моё повествование, надеюсь, Вам понравилось :)
Хотел бы выразить благодарность своему начальнику, он дал мне время во всём этом разобраться. Считаю эти новые знания очень полезными.
Спасибо девушкам из Scorini за неизменно вкусный кофе, но они не прочтут этих слов благодарности — я даже сомневаюсь, что они знают о существовании Хабрахабра :)
Хотелось бы увидеть в комментариях ещё больше полезной инфы и дополнений, буду очень благодарен.

Думаю, самое время почитать документацию к MAT…

UPD1: Да, совсем забыл рассказать про такие полезные вещи, как создание дампов памяти.
docs.oracle.com/javase/7/docs/webnotes/tsg/TSG-VM/html/clopts.html#gbzrr
Опции
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/disk2/dumps
весьма полезны для генерации дампов в момент падения приложения по OutOfMemoryError,
а также существует возможность снять дамп памяти с приложения «наживо», посреди его работы.
Для этого существует утилита jmap.
Пример вызова для винды:
«C:installPSToolsPsExec.exe» -s «C:Program FilesJavajdk1.7.0_55binjmap.exe» -dump:live,format=b,file=C:dump.hprof 3440
последний параметр — это PID java-процесса. Приложение PsExec из набора PSTools позволяет запускать другие приложения с правами системы, для этого служит ключ "-s". Опция live полезна, чтобы перед сохранением дампа вызвать GC, очистив память от мусора. В случае, когда возникает OOM, чистить память незачем, там уже не осталось мусора, так что не ищите, как можно установить опцию live в случае возникновения OOM.

Автор: denixx

Источник