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

  • Tutorial
Приветствую, Хабр!
Немного лирики
Сегодня, 2015-03-21, я решил сделать пол-дела, и всё-таки начать писать статью о том, как же всё-таки начать понимать, что же делать с OOM, да и вообще научиться ковырять heap-dump'ы (буду называть их просто дампами, для простоты речи. Также я постараюсь избегать англицизмов, где это возможно).
Задуманный мной объём «работ» по написанию этой статьи кажется мне не однодневным, а посему статья должна появиться лишь через пару недель спустя день.

В этой статье я постараюсь разжевать, что делать с дампами в 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.
Детальнее о том, почему нельзя закидывать Resource в файл /conf/context.xml томкета
На каждую подпапку внутри папки /webapps поднимается своя копия /conf/context.xml, а значит то количество Resource, которые там есть, следует умножать на количество приложений, чтобы получить общее количество пулов, поднятых в памяти томкета. На вопрос «что в этом случае делать?» ответ будет таким: нужно вынести все объявления Resource из /conf/context.xml в файл /conf/server.xml, внутрь тега GlobalNamingResources. Там Вы можете найти один, имеющийся по умолчанию, Resource name=«UserDatabase», вот под ним и размещайте свои пулы. Далее необходимо воспользоваться тегом ResourceLink, его желательно поместить в приложение, в проекте, внутрь файла /META-INF/context.xml — это так называемый «per-app context», то есть контекст, который содержит объявления компонентов, которые будут доступны только для разворачиваемого приложения. У ResourceLink параметры name и global могут содержать одинаковые значения.
Для примера:
<ResourceLink name="jdbc/MyDB" global="jdbc/MyDB" type="javax.sql.DataSource"/>

Эта ссылка будет выхватывать из глобально объявленных ресурсов DataSource с именем «jdbc/MyDB», и ресурс станет доступен приложению.
ResourceLink можно (но не нужно) разместить и в /conf/context.xml, но в этом случае доступ к ресурсам, объявленным глобально, будет у всех приложений, пусть даже и не будет столько копий DataSource в памяти.
Ознакомиться с деталями можно вот тут: GlobalNamingResources — http://tomcat.apache.org/tomcat-7.0-doc/config/globalresources.html#Environment_Entries, ResourceLink — http://tomcat.apache.org/tomcat-7.0-doc/config/globalresources.html#Resource_Links, также можно просмотреть эту страницу: tomcat.apache.org/tomcat-7.0-doc/config/context.html.
Для TC8 эти же страницы: http://tomcat.apache.org/tomcat-8.0-doc/config/globalresources.html и http://tomcat.apache.org/tomcat-8.0-doc/config/context.html .

После этого всё стало ясно: 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:\install\PSTools\PsExec.exe» -s «C:\Program Files\Java\jdk1.7.0_55\bin\jmap.exe» -dump:live,format=b,file=C:\dump.hprof 3440
последний параметр — это PID java-процесса. Приложение PsExec из набора PSTools позволяет запускать другие приложения с правами системы, для этого служит ключ "-s". Опция live полезна, чтобы перед сохранением дампа вызвать GC, очистив память от мусора. В случае, когда возникает OOM, чистить память незачем, там уже не осталось мусора, так что не ищите, как можно установить опцию live в случае возникновения OOM.

UPD2 (2015-10-28) | Случай номер два три
(Было принято решение дописать это сюда как апдейт, а не пилить новую статью о том же самом):
Ещё один интересный случай, но уже с Оракловой базой.
Один из проектов использует фичу с XML, проводит поиски по содержимому сохранённого XML-документа. В общем, этот проект иногда давал о себе знать тем, что вдруг внезапно один из инстансов переставал подавать признаки жизни.
Почуяв «хороший» случай потренироваться на кошках, я решил посмотреть его дампы памяти.

Первое, что я увидел, было «у вас тут много коннектов в памяти осталось». 21к!!! И какой-то интересный oracle.xdb.XMLType тоже давал жару. «Но это же Оракл!», вертелось у меня в голове. Забегая вперёд скажу что таки да, он виноват.

Итак, видим кучу T4CConnection, которые лежат в HashMap$Entry. Обратил внимание сразу, что вроде бы и SoftHashMap, что, вроде как, должно означать, что оно не должно вырастать до таких размеров. Но результат видите и сами — 50-60 килобайт в коннекте, и их реально МНОГО.

Посмотрев, что собой представляют HashMap$Entry — увидел, что примерно картина одинакова, всё связано с SoftHashMap, с Оракловыми коннектами.

Что, собственно, подтверждалось такой картинкой. HashMap$Entry было просто море, и они более-менее сакуммулировались внутри oracle.xdb.SoftHashMap.
В следующем дампе картина была примерно такой же. По Dominator Tree было видно, что внутри каждого Entry находится тяжёлый такой BinXmlProcessorImpl.

-=-=-
Если учесть, что я в тот момент был не силён в том, что такое xdb, и как он связан с XML, то, несколько растерявшись, я решил, что надо бы погуглить, быть может кто-то уже в курсе, что со всем этим нужно делать. И чутьё не обмануло, по запросу «oracle.xdb.SoftHashMap T4CConnection» нашлось
раз piotr.bzdyl.net/2014/07/memory-leak-in-oracle-softhashmap.html
и два leakfromjavaheap.blogspot.com/2014/02/memory-leak-detection-in-real-life.html
Утвердившись, что тут всё-таки косяк у Оракла, дело оставалось за малым.
Попросил администратора БД посмотреть информацию по обнаруженной проблеме:
xxx: Ключевые слова: SoftHashMap XMLType
yyy: Bug 17537657 Memory leak from XDB in oracle.xdb.SoftHashMap
yyy: The fix for 17537657 is first included in
12.2 (Future Release)
12.1.0.2 (Server Patch Set)
12.1.0.1.4 Database Patch Set Update
12.1.0.1 Patch 11 on Windows Platforms
yyy: нда. Описание
Description
When calling either getDocument() using the thin driver, or getBinXMLStream()
using any driver, memory leaks occur in the oracle.xdb.SoftHashMap class.
BinXMLProcessorImpl classes accumulate in this SoftHashMap, but are never
removed.
xxx: Всё так и есть :)


Вот описание фикса: updates.oracle.com/Orion/Services/download?type=readme&aru=18629243 (для доступа требуется учётка в Оракл).
-=-=-
После применения фикса инстансы нашего приложения живут уже месяц, и пока без эксцессов. *постучал по дереву* *поплевал через левое плечо*
Успехов Вам в поисках!
AdBlock has stolen the banner, but banners are not teeth — they will be back

More
Ads

Comments 31

    +1
    Как бы банально не звучало, но — Спасибо за статью! У нас как раз в пятницу WebLogic падал с OOM. Так что статья вовремя — завтра будем её использовать. Кстати, по повду jmap, для дампа целевое приложение не нужно запускать с какими то параметрами? Т.е. вот работает приложение в проде без опций heap dump и можно ли с помощью jmap сделать дамп памяти это приложения?
      +2
      Пожалуйста, я буду рад, если поможет.
      Если я правильно разобрался в проблемной области, то jmap требуется запускать от того же пользователя, под которым запущено приложение. Отсюда танцы с бубном вокруг PsExec под виндой, ведь томкет в ней запускается от системы в случае, если устанавливался как служба.
      Да, jmap не связан никак с опцей автоматической генерации дампа.
      +2
      Самое коварное — это когда память течет и заканчивается потихоньку. В этом случае потоки еще не падают с ООМ, но все большую часть процессорного времени начинает отжирать GC. В результате сервер «встает колом» — ошибок нет, но все повисает, пользователи отваливаются, система фактически перестает реагировать на внешние раздражители. Дамп памяти «наживую» создать при этом невозможно, штатно завершить работу сервера — тоже. То есть если не мониторить heap, то выглядит это как повисание сервера намертво через несколько дней работы…
        +2
        Дамп памяти «наживую» создать при этом невозможно

        Ну, может помочь ключ -F для jmap ;) http://docs.oracle.com/javase/7/docs/technotes/tools/share/jmap.html
        В этом случае игнорируется параметр live.
          +2
          Если память течёт совсем медленно, мы обычно создаём на живую два дампа с помощью jmap с некоторым интервалом времени, потом внимательно смотрим разницу.
          0
          Начиная с седьмой версии tomcat в него впилили новый connection pool — tomcat.apache.org/tomcat-7.0-doc/jdbc-pool.html, не пробовали? Пользуемся им давно, нареканий пока не было.
            0
            Отвечаю, что использовать не пробовали, но спасибо, что подсказали, когда появится время — надо бы посмотреть, что он из себя представляет.
            Скажу лишь, что под капотом DBCP 2.0 уже располагается commons-pool2, это было причиной переименования параметров.
            В pom'нике в ветке trunk проекта commons-dbcp2 сейчас наблюдается строчка
            <commons.pool.version>2.3</commons.pool.version>
            Если прогуляться в класс http://svn.apache.org/viewvc/commons/proper/pool/tags/POOL_2_3/src/main/java/org/apache/commons/pool2/impl/GenericObjectPool.java?view=markup, то в строке 1132 можно увидеть строчку
            private final LinkedBlockingDeque<PooledObject<T>> idleObjects;
            Ну и в методе «public T borrowObject(long borrowMaxWaitMillis)» (строка 411) эта очередь активно используется.
            Думаю, что DBCP 2 должен быть быстрее, чем 1.4, и у меня даже есть желание перейти на DBCP 2+.
            Надо бы посмотреть содержимое и попробовать провести бенчмарк, который предоставляет разработчик HikariCP, чтобы понять, каков этот коэффициент ускорения.
            По предоставленной Вами ссылке так и написано в первых двух пунктах, что мол «Note that this does not apply to Commons DBCP 2.x.».
            0
            Есть один неочевидный и коварный аспект Out of Memory ошибок, который может натворить много бед в продакшене и о котором стоит сказать. Суть в том, что в зависимости от реализации приложение в полумертвом OOM-состоянии может нормально отвечать на запросы внешнего мониторинга (например, отдавать страницу 200 ОК или возвращать утвердительный ответ о работоспособности иным способом, например по JMS), при этом де-факто уже не являясь работоспособным.

            Поэтому если речь идет о mission-critical задачах, может быть уместно устанавливать дефолтный эксепшн хендлер (см. Thread.setDefaultUncaughtExceptionHandler()) и вызывать System.exit() как только прилетает упоминание OutOfMemoryError.
              +3
              А чем поможет System.exit в таком случае? С полуживого приложения проще собрать диагностику и понять, что случилось, чем с завершившегося.
                0
                Тем, что мониторинг обнаружит неработоспособность приложения сразу, а не через несколько часов например.
                  0
                  Более правильным вариантом будет всё же натравить тот же Zabbix, например, на слежение за логфайлом, в который пишется OOM, чтобы он сигнализировал как-то об этом событии, и админы уже могли и дампы снять, и перевалить приложение. Плюс никто не запрещает автоматизировать процесс, мне кажется.
                  Вдобавок можно также следить за какими-то критическими вещами, типа слова Abandoned в том-же логе.
                    +1
                    Как именно обрабатывать событие в обработчике Thread.UncaughtExceptionHandler – вопрос второй, можно конечно и в лог писать а потом эти логи парсить. Если конечно есть уверенность в том, что OOM точно не поломает логгинг.

                    Речь здесь скорее про то, что а) для ловли/логгирования таких ошибок удобно использовать Thread.UncaughtExceptionHandler б) при планировании мониторинга нужно предусматривать кейсы, когда приложение полуживое, но находится в состоянии Out of Memory.
              0
              Не подскажете, как использовать приведенные в статье инструменты для анализа OOM в GUI приложении под Windows?
              К примеру, я попытался снять дамп памяти, установил -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=.
              Поймал OOM, но дампа не появилось.
                +1
                Сначала отвечу на Ваш вопрос:
                Начну, пожалуй, с примеров кода...
                Тестовый класс
                import java.io.BufferedReader;
                import java.io.IOException;
                import java.io.InputStreamReader;
                
                public class TestOOM {
                    public static void main(String[] args) throws IOException {
                        BufferedReader rdr = new BufferedReader(new InputStreamReader(System.in, "UTF-8"));
                        System.out.println("Press Enter to make OOM...");
                        rdr.readLine();
                        StringBuilder stringBuilder = new StringBuilder();
                        while (true) {
                            stringBuilder.append("foobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobar");
                        }
                    }
                }
                Запускаем это дело
                $ ls
                TestOOM.class

                $ java -Xmx256m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=. TestOOM
                Press Enter to make OOM…

                java.lang.OutOfMemoryError: Java heap space
                Dumping heap to ./java_pid15967.hprof…
                Heap dump file created [85330696 bytes in 0,401 secs]
                Exception in thread «main» java.lang.OutOfMemoryError: Java heap space
                at java.util.Arrays.copyOf(Arrays.java:2367)
                at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:130)
                at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:114)
                at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:415)
                at java.lang.StringBuilder.append(StringBuilder.java:132)
                at TestOOM.main(TestOOM.java:16)
                В примере выше я указал -Xmx256m, чтобы оно не генерировало дамп памяти на 5 гиг.
                В результате в папке, в которой я запускал «приложение», рядом с класс-файлом появился файл java_pid15967.hprof.
                В качестве рекомендаций могу посоветовать проверить, что перед параметром HeapDumpOnOutOfMemoryError стоит знак плюс, "-XX:+HeapDumpOnOutOfMemoryError", если будет минус ("-XX:-HeapDumpOnOutOfMemoryError"), то это наоборот, «выключить» (надо, кстати, об этом ещё кое-куда написать, а то чувствую, насоветовал я там человеку...).
                К тому же, если есть возможность «подключиться» к процессу, который запущен, с помощью JVVM, то там будет видно, включена ли опция, на вкладке «Overview» будет чёрным по серому написано «Heap dump on OOME: enabled».
                Вот, как-то так обстоят дела.
                  0
                  Спасибо за ответ.
                  Ключи я указал правильно. Дело еще в том, что приложение не мое и исходников у меня сейчас нет. Возможно там OOME перехватыватеся и как-то обрабатывается. Это может повлиять на создание дампа? Правда в консоли и в логе стектрейс с OOME появляется.
                    0
                    Да, его можно перехватить, выдать в лог, и не пропустить дальше. В консоль и лог OOM в этом случае попадёт, но JVM о нём вроде как не узнает.
                    Почему перехват Throwable нужно делать с полным знанием дела
                    import java.io.BufferedReader;
                    import java.io.IOException;
                    import java.io.InputStreamReader;
                    import java.util.logging.Level;
                    import java.util.logging.Logger;
                    
                    public class TestOOM {
                        private static final Logger LOGGER = Logger.getLogger(TestOOM.class.getName());
                    
                        public static void main(String[] args) throws IOException {
                            BufferedReader rdr = new BufferedReader(new InputStreamReader(System.in, "UTF-8"));
                            LOGGER.info("Press Enter to make OOM...");
                            rdr.readLine();
                            StringBuilder stringBuilder = new StringBuilder();
                            try {
                                while (true) {
                                    stringBuilder.append("foobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobarfoobar");
                                }
                            } catch (Throwable thr) {
                                LOGGER.log(Level.SEVERE, "Here is a some Throwable, printing it and ignoring.", thr);
                            }
                            LOGGER.info("I am still alive! Press Enter to quit...");
                            rdr.readLine();
                        }
                    }
                      0
                      Хотя нет, я соврал, я пропустил заветную строчку «Dumping heap to ./java_pid6902.hprof ...». Однако приложение всё равно «выживает». Возможно, такие конструкции с перехватом Throwable как раз и являются причиной варианта «приложение всё ещё живое, но не отвечает».
                      Заголовок спойлера
                      $ java -Xmx256m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=. TestOOM
                      мар 23, 2015 5:26:35 PM TestOOM main
                      INFO: Press Enter to make OOM...
                      
                      java.lang.OutOfMemoryError: Java heap space
                      Dumping heap to ./java_pid6902.hprof ...
                      Heap dump file created [85808247 bytes in 0,406 secs]
                      мар 23, 2015 5:26:36 PM TestOOM main
                      SEVERE: Here is an some Throwable, printing it and ignoring.
                      java.lang.OutOfMemoryError: Java heap space
                              at java.util.Arrays.copyOf(Arrays.java:2367)
                              at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:130)
                              at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:114)
                              at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:415)
                              at java.lang.StringBuilder.append(StringBuilder.java:132)
                              at TestOOM.main(TestOOM.java:17)
                      
                      мар 23, 2015 5:26:36 PM TestOOM main
                      INFO: I am still alive! Press Enter to quit...
                +3
                В MAT OQL тоже можно пользоваться. Он немного мутный, но работает. А ещё там есть полезные вещи типа Merge shortest paths to GC roots. Ну и подсчёт retained size. Довольно магическая штука, не всегда работает как ожидается, но порой выручает.

                В одном из приложений мы в обёртку к SQL-соединениям добавили текстовое поле с текстом последнего запроса, выполнявшегося в этом соединении. Исключительно для того, чтобы в дампе памяти его можно было легко найти.
                  0
                  Спасибо автору за стать
                  но вот что меня заинтересовало:

                  at наш.пакет.СуперКласс.getConnection(СуперКласс.java:100500)
                  at наш.пакет.СуперКласс.плохойПлохойМетод(СуперКласс.java:100800)


                  это реальные цифры? это сгенерированный код? мне очень трудно представить как иначе класс мог бы разрастись до столь не вменяемых размеров
                    +2
                    Нет, класс вполне обычный, я просто скрыл содержимое стектрейса, а в качестве номеров строк указал сие магическое число, это просто отсылка к мему "Стопицот".
                    Я даже сомневаюсь, что во всём проекте столько строк наберётся.
                    +6
                    Еще стоит посмотреть доклад Володи Ситникова — Анализ дампов памяти Java приложений


                    Там и про jvisualvm, и про MAT, и про OQL и прикрученный Володей SQL движок к MAT'у, так, что можно писать куда более интересные запросы.
                      +1
                      Отлично, как раз то, что хотелось узнать про MAT. Благодарю!
                      +2
                      Замечательная статья!

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

                      Около 40% приложений с OOM падают с message «Java Heap Space». Около 20% падают с «GC overhead limit exceeded». Около 20% падают с «PermGen space».

                      Больше 50% приложений имеют только один OOM за всё время жизни процессы, 90% приложений имеют 14 OOM или меньше. Остальные могут кидать их сотнями, некоторые даже сотнями тысяч. Weblogic в этом плане бьёт все рекорды со своим catch(Throwable t). Пара-тройка OOM для одной JVM это нормально при нескольких активно аллоцирующих потоках.

                      Около 90% приложений завершается в течение 10 минут после OOM, около 70% погибают в течение минуты. Остальные могут жить днями, неделями и даже месяцами (хотя зачастую помимо бросания OOM ничего толкового и не делают).

                      Около 50% приложений с OOM получают его в первые полчаса своей работы. Около 10% вылетают прямо при старте.

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

                      Также могу порекомендовать handbook по разным типам OOM (не сочтите за пиар :) )
                        +1
                        Эти проценты от общего числа упавших приложений или от общего числа протестированных? А тесты на какой версии Java проводились? Теоретически с седьмой количество PermGen space ошибко должно уменьшиться (а в восьмой и вовсе исчезнуть).

                        Иногда разумно продолжить работу приложения с помощью логирования catch Throwable. Есть шансы, что именно в этом try-блоке было выделено очень много памяти и при проваливании в catch она освободится.

                        Я стараюсь писать catch Throwable где-нибудь на самом верху — общий try-catch для фоновых задач, например. Тогда при OOM умрёт поток с фоновой задачей, но есть шансы, что выживет приложение. Обычно catch Throwable направлен на ловлю других ошибок — например, корявый деплой привёл к несоответствию версий библиотек и выпало что-нибудь вроде NoSuchMethodError. В современном мире такая ошибка не хуже NullPointerException. Ну то есть это откровенный баг и скорее всего какая-то подсистема полностью не функционирует, но не повод из-за него класть весь сервер. Или StackOverflowError — его тоже можно пережить. Возможно, стоит подходить более дифференцировано к Error-исключениям и обрабатывать OOM по особенному. Слать СМС-ку админу, например :-)
                          +2
                          Это проценты от запусков приложений, в которых мы задетектили OOM. Приложения и среды самые разные. Java 8 среди них действительно не очень много.

                          Согласен, что иногда может быть полезно. Однако в общем случае продолжать работу при OOM — дело опасное. Даже если всю память отожрал именно конкретный try-блок, схватить OOM при этом могут и совершенно не связанные с ним места, оставшись в некорректном состоянии.

                          Насчёт NoSuchMethodError согласен. Насчёт слать смску — есть много весьма умных систем мониторинга, да :)
                        +1
                        //Добавлен UPD2.
                          +2
                          // Хозяйке на заметку
                          С помощью ключа -XX:OnOutOfMemoryError=«kill -9 %p» можно повесить на OutOfMemory ошибку определенные действия, например jstack, jsmap и kill, упакованные в shell-скрипт.

                          Кавычки конечно должны быть не елочки, а самые обыкновенные :)
                            0
                            Тот же apache solr с 5 версии так и делает. OOM там может и не повлиять на доступность на чтение, в отличии от доступности на запись.
                            0
                            UPD 3: markt в мейлинг-листе томкета отвечал на вопрос, какого чёрта в томкете два коннекшн-пула одновременно (tomcat-jdbc и одновременно DBCP, и почему внезапно в восьмом томкете DBCP стал выгоднее): http://mail-archives.apache.org/mod_mbox/tomcat-users/201506.mbox/%3C556EC74A.5040306%40apache.org%3E.
                            0
                            objid: «0x» + parseInt(objectid(x)).toString(16)

                            Only users with full accounts can post comments. Log in, please.