Тихо и незаметно закончилсь на прошлой неделе крупнейшая конференция Java-разработчиков JavaOne 2009, и по сети начали распространяться некоторые слайды. Я, волею судеб, оказался специалистом по производительности Java SE, и бОльшую часть времени работал в павильоне на стенде "Java SE Platform: Performance, Java HotSpot VM Internals, and Diagnostics". Подавляющее большинство вопросов, заданных мне, сводилось к нескольким: <ol> <li>Как узнать "горячие места" в коде?</li> <li>Как узнать, сколько занимает и что делает GC? </li> <li>Как узнать, что происходит с памятью и где она "течёт"?</li> </ol> Добрых три-четыре десятка раз я отвечал одно и то же, и каждый раз удивлялся, что мои собеседники не владеют, как мне казалось, элементарным набором инструментов. Поэтому хочу зафиксировать это знание здесь, чтобы впредь не повторяться :)

<habracut text="дальше много картинок, на 1.5 Мб" /> Итак, в стародавние времена в составе JDK было несколько хороших инструментов для диагностики JVM: jps, jinfo, jstack, jstat, jmap, jhat, и т.п. Все они консольные, и тем или иным образом были удобны. До настоящего времени единственным включённым в состав JDK мониторинговым GUI-инструментом был jconsole. У jconsole, однако, есть один очень большой минус: она не предоставляет никаких возможностей профилировки.

Однако в NetBeans есть отличный профайлер! Кроме того, платформа NetBeans достаточно модульная, чтобы можно было выделить профайлер в отдельный инструмент и распространять его в составе JDK. А если ещё прикрутить туда сбор всей информации, доступной в jconsole, то получится универсальный инструмент для мониторинга, профилировки и диагностики Java-приложений.

Инженеры Sun это сделали, и так родился <img src="http://habrastorage.org/getpro/habr/post_images/f52/39d/7bf/f5239d7bf8da6a24d904cd5a7bf0f07e.png">

Подразумевается, что интерфейс VisualVM интуитивно понятен, поэтому подробно разбирать его я не буду. Постараюсь вместо этого рассказать о философии, стоящей за этим инструментом. В качестве тестируемого приложения я выбрал свободно распространяемый набор бенчмарок <a href="http://dacapobench.org/">DaCapo</a>, конкретно тест lusearch, который внутри гоняет тест производительности на Apache Lucene. Цель данного топика — показать возможности VisualVM, а не поведение конкретной виртуальной машины на конкретном оборудовании в конкретных условиях.

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

<code>$JAVA_HOME/bin/jvisualvm</code>

Если у вас стоит Sun JDK 6u7 и выше, то VisualVM у вас уже есть, и она доступна как и мне, из каталога с JRE. Если у вас более старая машина, то лучше проапгрейдиться :) Но можно скачать VisualVM <a href="http://visualvm.dev.java.net">отдельно</a>.

Вот так выглядит этот притаившийся зверь <img src="http://habrastorage.org/getpro/habr/post_images/541/ea5/5a0/541ea55a0fb66726aae9e6b9ac5aded1.png">

В меню "Tools → Plug-ins" установил VisualGC <img src="http://habrastorage.org/getpro/habr/post_images/635/a41/65c/635a4165cd5eb2208f1269a22c68cd42.png">

Всё готово! Время опробовать его в действии. Я запустил фоном DaCapo:lusearch <code>/opt/jdk1.6.0_14/bin/java -server -jar dacapo-2006-10-MR2.jar -n 100 lusearch</code> и отправился в VisualVM. Нашёл в дереве слева интересующий меня java-процесс (можно увидеть, что там торчат ещё сам VisualVM и мой Eclipse), сделал на нём Open и попал в Overview моего процесса: <img src="http://habrastorage.org/getpro/habr/post_images/58d/8fe/98f/58d8fe98f157d5f7b1e3af49c122c8ff.png">

Здесь не так интересно, поэтому я поспешил перейти на вкладку Monitor и посмотреть на высокоуровневую статистику: <img src="http://habrastorage.org/getpro/habr/post_images/5cb/60f/b04/5cb60fb046e052cd9a0836a314fa7ee9.png"> На скриншоте легко можно увидеть графики утилизации CPU (включая активность GC), количество загруженных классов и созданных нитей, состояние памяти.

Можно получить информацию о памяти чуть детальнее, здесь нам и пригодится VisualGC: <img src="http://habrastorage.org/getpro/habr/post_images/4b3/fb3/cc9/4b3fb3cc942f3561f93638ea91a1dca7.png"> То, что здесь происходит, будет понятно тем, кто знает, как устроен сборщик мусора. Конкретно на этом скриншоте можно увидеть три пространства для объектов: постоянное, старое и молодое. Последнее разбито на ещё на три подпространства: эдем и два пространства под выжившие объекты. Данные обновляются вживую, а графики справа показывают, что происходило за последнее время. По этому скриншоту можно оценить, правильно ли GC работает на конкретном приложении. Здесь я вижу, что часть объектов перемещается в old space, а потом всё-таки убирается полным GC: может, стоит покрутить promotion thresholds? Или попробовать другой GC?

Вернёмся пока к закладкам. На закладке Threads можно увидеть подробную статистику по нитям. Там есть несколько режимов просмотра, оставляю их любопытному читателю :) <img src="http://habrastorage.org/getpro/habr/post_images/dbe/530/63e/dbe53063ec323c5ac0eab1ace9a7daf7.png">

Как и в старой доброй jconsole, можно посмотреть на MBeans: <img src="http://habrastorage.org/getpro/habr/post_images/b63/ffb/e64/b63ffbe645365435e0cc17bf9c22b62e.png">

<b>И наконец!</b> Самое вкусное в этом посте: профайлер. <img src="http://habrastorage.org/getpro/habr/post_images/7c0/672/12a/7c067212ac6e03b7000eab3a50d47acf.png">

У профайлера есть два режима: CPU и Memory. Первый профилирует методы с точки зрения проведённого в них времени, второй — с точки зрения созданных и уничтоженных объектов. Попробуем для начала CPU. Для этого прямо здесь и сейчас нажимаем кнопку "CPU": <img src="http://habrastorage.org/getpro/habr/post_images/6c3/216/a0b/6c3216a0bd144a34feb43cbaa931a8e9.png"> Интересная и полезная особенность состоит в том, что приложение всё ещё работает, <b>профайлер инструментировал приложение на лету</b>. Вот и первые результаты, видно, какой метод занимает больше всего времени. Но это только часть всего дела: неясно ведь, откуда его зовут.

Поэтому мы делаем snapshot при помощи соответствующей кнопки, и открываем его: <img src="http://habrastorage.org/getpro/habr/post_images/e1e/350/b53/e1e350b53fb693282d8a6e469091f27d.png"> Это — все нитки, которые были пойманы профайлером.

Развернём одну из них: <img src="http://habrastorage.org/getpro/habr/post_images/49e/872/04a/49e87204ae2137cb744b0ed17e9d878c.png"> Видно, что исполнение началось с вызова метода QueryThread.run() и дальше оно разбилось на две стадии: QueryParser.parse(…​) и Searcher.search(…​). Кажется, это правильно.

Пойдём глубже: <img src="http://habrastorage.org/getpro/habr/post_images/6d6/9da/df1/6d69dadf14e7f39b60be4cbaec314e8e.png"> Видно всю глубокую цепочку вызовов, а так же конечных бойцов, которые светятся своим Self time’ом: IndexInput.readV*(). Если бы это было моё приложение, я бы начал задумываться, а нельзя ли на этих методах сэкономить, или как-нибудь их оптимизировать :)

А где же наши горячие места в этом стеке? Перейдём на combined view и выберем первый горячий метод: <img src="http://habrastorage.org/getpro/habr/post_images/35b/e07/0b6/35be070b60e9a9222296384b0cac856c.png"> Вон он где.

На этом с CPU профайлером закончим: мы уже узнали, где приложение проводит бОльшую часть своего времени. Попробуем Memory профайлер. Для этого на вкладке Profiler я нажимаю кнопку "Stop", жду когда CPU профайлер отменит инструментацию, а потом жму "Memory". Через некоторое время мы видим это: <img src="http://habrastorage.org/getpro/habr/post_images/5fa/46a/747/5fa46a747f07fdd5104db0168ea7e88a.png"> Ага, кажется, у нас преобладают массивы char[]. Неудивительно для Lucene. Однако, я хочу бОльшего: сейчас я смотрю на статистику живых объектов, а хочу узнать, какие объекты вообще создавались за время всего профилирования. Для этого я иду в Settings и прошу учитывать только аллокации объектов: <img src="http://habrastorage.org/getpro/habr/post_images/6fd/295/c2b/6fd295c2b677bbaad09a4a3e6b9a63a2.png"> (вместе с этим я включил запись стеков для аллокаций)

Вот что у нас в длинном профиле доминирует: <img src="http://habrastorage.org/getpro/habr/post_images/e4c/f7a/81a/e4cf7a81abce537ad10735e0a58923f6.png"> Те же самые парни. Ну что ж, теперь я хочу увидеть, откуда они взялись. Выбираю интересующий меня класс, и прошу показать мне stack trace.

<img src="http://habrastorage.org/getpro/habr/post_images/ede/c94/40d/edec9440dad8a2839155a41648c1dcd0.png"> Вот и он! Видно, что подавляющая часть аллокаций происходит внутри Lucene, в методе FastCharStream.refill(). Интересно, в Lucene дубликатный класс в разных пакетах?

Откуда эти методы зовутся? Отсюда: <img src="http://habrastorage.org/getpro/habr/post_images/842/79a/5e7/84279a5e7656bebd6c28f01489fe660a.png">

Несмотря на то, что Memory профайлер не делает статического анализа на предмет того, правильно ли вы обращаетесь с памятью, он даёт вам ценную информацию, а что же у вас в памяти творится. Сняв такой профиль в экстремальном режиме работы приложения, когда вот-вот будет OOME (кстати, VisualVM умеет это событие перехватывать), можно одним махом увидеть, какие и откуда объекты пришли.

Потом — классический heap dump. <img src="http://habrastorage.org/getpro/habr/post_images/545/94c/2e6/54594c2e6aa050675d0b99060526d807.png"> <img src="http://habrastorage.org/getpro/habr/post_images/ac1/9a8/cd3/ac19a8cd3d7a5f526cc620784789dfb4.png"> <img src="http://habrastorage.org/getpro/habr/post_images/324/831/8cc/3248318ccbfadc24232c5d6483bd7cba.png">

Продолжал бы и дальше, но "поля здесь слишком узки" (с).

Напомню, что этот чудесный инструмент доступен большинству практически мгновенно (в $JAVA_HOME/bin/jvisualvm), а остальной части сообщества — <a href="https://visualvm.dev.java.net/download.html">с небольшими телодвижениями</a>. Надеюсь, теперь, когда отпрофилировать приложение будет так просто, культура performance-wise программирования привьётся куда лучше :)

Да, и помните завет Кнута: <b>"Premature optimization is the root of all evil".</b><img src="http://habrastorage.org/getpro/habr/post_images/2be/09c/f5a/2be09cf5aa913e9ed12eb9a2cd17dee4.png" width=1 height=1>