1054 читателя, 114 поста
Администрация
Модераторы
JAVA для веба и не только
VisualVM: мониторинг, профилировка и диагностика Java-приложений
Тихо и незаметно закончилсь на прошлой неделе крупнейшая конференция Java-разработчиков JavaOne 2009, и по сети начали распространяться некоторые слайды. Я, волею судеб, оказался специалистом по производительности Java SE, и бОльшую часть времени работал в павильоне на стенде «Java SE Platform: Performance, Java HotSpot VM Internals, and Diagnostics». Подавляющее большинство вопросов, заданных мне, сводилось к нескольким:
Добрых три-четыре десятка раз я отвечал одно и то же, и каждый раз удивлялся, что мои собеседники не владеют, как мне казалось, элементарным набором инструментов. Поэтому хочу зафиксировать это знание здесь, чтобы впредь не повторяться :)
Итак, в стародавние времена в составе JDK было несколько хороших инструментов для диагностики JVM: jps, jinfo, jstack, jstat, jmap, jhat, и т.п. Все они консольные, и тем или иным образом были удобны. До настоящего времени единственным включённым в состав JDK мониторинговым GUI-инструментом был jconsole. У jconsole, однако, есть один очень большой минус: она не предоставляет никаких возможностей профилировки.
Однако в NetBeans есть отличный профайлер! Кроме того, платформа NetBeans достаточно модульная, чтобы можно было выделить профайлер в отдельный инструмент и распространять его в составе JDK. А если ещё прикрутить туда сбор всей информации, доступной в jconsole, то получится универсальный инструмент для мониторинга, профилировки и диагностики Java-приложений.
Инженеры Sun это сделали, и так родился
Подразумевается, что интерфейс VisualVM интуитивно понятен, поэтому подробно разбирать его я не буду. Постараюсь вместо этого рассказать о философии, стоящей за этим инструментом. В качестве тестируемого приложения я выбрал свободно распространяемый набор бенчмарок DaCapo, конкретно тест lusearch, который внутри гоняет тест производительности на Apache Lucene. Цель данного топика — показать возможности VisualVM, а не поведение конкретной виртуальной машины на конкретном оборудовании в конкретных условиях.
Перед тем, как начать саму демонстрацию, я скачал и установил несколько дополнений к VisualVM, которые покажу ниже. Для этого я запустил VisualVM:
Если у вас стоит Sun JDK 6u7 и выше, то VisualVM у вас уже есть, и она доступна как и мне, из каталога с JRE. Если у вас более старая машина, то лучше проапгрейдиться :) Но можно скачать VisualVM отдельно.
Вот так выглядит этот притаившийся зверь
В меню «Tools -> Plug-ins» установил VisualGC
Всё готово! Время опробовать его в действии. Я запустил фоном DaCapo:lusearch
и отправился в VisualVM. Нашёл в дереве слева интересующий меня java-процесс (можно увидеть, что там торчат ещё сам VisualVM и мой Eclipse), сделал на нём Open и попал в Overview моего процесса:
Здесь не так интересно, поэтому я поспешил перейти на вкладку Monitor и посмотреть на высокоуровневую статистику:
На скриншоте легко можно увидеть графики утилизации CPU (включая активность GC), количество загруженных классов и созданных нитей, состояние памяти.
Можно получить информацию о памяти чуть детальнее, здесь нам и пригодится VisualGC:
То, что здесь происходит, будет понятно тем, кто знает, как устроен сборщик мусора. Конкретно на этом скриншоте можно увидеть три пространства для объектов: постоянное, старое и молодое. Последнее разбито на ещё на три подпространства: эдем и два пространства под выжившие объекты. Данные обновляются вживую, а графики справа показывают, что происходило за последнее время. По этому скриншоту можно оценить, правильно ли GC работает на конкретном приложении. Здесь я вижу, что часть объектов перемещается в old space, а потом всё-таки убирается полным GC: может, стоит покрутить promotion thresholds? Или попробовать другой GC?
Вернёмся пока к закладкам. На закладке Threads можно увидеть подробную статистику по нитям. Там есть несколько режимов просмотра, оставляю их любопытному читателю :)
Как и в старой доброй jconsole, можно посмотреть на MBeans:
И наконец! Самое вкусное в этом посте: профайлер.
У профайлера есть два режима: CPU и Memory. Первый профилирует методы с точки зрения проведённого в них времени, второй — с точки зрения созданных и уничтоженных объектов. Попробуем для начала CPU. Для этого прямо здесь и сейчас нажимаем кнопку «CPU»:
Интересная и полезная особенность состоит в том, что приложение всё ещё работает, профайлер инструментировал приложение на лету. Вот и первые результаты, видно, какой метод занимает больше всего времени. Но это только часть всего дела: неясно ведь, откуда его зовут.
Поэтому мы делаем snapshot при помощи соответствующей кнопки, и открываем его:
Это — все нитки, которые были пойманы профайлером.
Развернём одну из них:
Видно, что исполнение началось с вызова метода QueryThread.run() и дальше оно разбилось на две стадии: QueryParser.parse(...) и Searcher.search(...). Кажется, это правильно.
Пойдём глубже:
Видно всю глубокую цепочку вызовов, а так же конечных бойцов, которые светятся своим Self time'ом: IndexInput.readV*(). Если бы это было моё приложение, я бы начал задумываться, а нельзя ли на этих методах сэкономить, или как-нибудь их оптимизировать :)
А где же наши горячие места в этом стеке? Перейдём на combined view и выберем первый горячий метод:
Вон он где.
На этом с CPU профайлером закончим: мы уже узнали, где приложение проводит бОльшую часть своего времени. Попробуем Memory профайлер. Для этого на вкладке Profiler я нажимаю кнопку «Stop», жду когда CPU профайлер отменит инструментацию, а потом жму «Memory». Через некоторое время мы видим это:
Ага, кажется, у нас преобладают массивы char[]. Неудивительно для Lucene. Однако, я хочу бОльшего: сейчас я смотрю на статистику живых объектов, а хочу узнать, какие объекты вообще создавались за время всего профилирования. Для этого я иду в Settings и прошу учитывать только аллокации объектов:
(вместе с этим я включил запись стеков для аллокаций)
Вот что у нас в длинном профиле доминирует:
Те же самые парни. Ну что ж, теперь я хочу увидеть, откуда они взялись. Выбираю интересующий меня класс, и прошу показать мне stack trace.
Вот и он! Видно, что подавляющая часть аллокаций происходит внутри Lucene, в методе FastCharStream.refill(). Интересно, в Lucene дубликатный класс в разных пакетах?
Откуда эти методы зовутся? Отсюда:
Несмотря на то, что Memory профайлер не делает статического анализа на предмет того, правильно ли вы обращаетесь с памятью, он даёт вам ценную информацию, а что же у вас в памяти творится. Сняв такой профиль в экстремальном режиме работы приложения, когда вот-вот будет OOME (кстати, VisualVM умеет это событие перехватывать), можно одним махом увидеть, какие и откуда объекты пришли.
Потом — классический heap dump.
Продолжал бы и дальше, но «поля здесь слишком узки» (с).
Напомню, что этот чудесный инструмент доступен большинству практически мгновенно (в $JAVA_HOME/bin/jvisualvm), а остальной части сообщества — с небольшими телодвижениями. Надеюсь, теперь, когда отпрофилировать приложение будет так просто, культура performance-wise программирования привьётся куда лучше :)
Да, и помните завет Кнута: «Premature optimization is the root of all evil».
- Как узнать «горячие места» в коде?
- Как узнать, сколько занимает и что делает GC?
- Как узнать, что происходит с памятью и где она «течёт»?
Добрых три-четыре десятка раз я отвечал одно и то же, и каждый раз удивлялся, что мои собеседники не владеют, как мне казалось, элементарным набором инструментов. Поэтому хочу зафиксировать это знание здесь, чтобы впредь не повторяться :)
Итак, в стародавние времена в составе JDK было несколько хороших инструментов для диагностики JVM: jps, jinfo, jstack, jstat, jmap, jhat, и т.п. Все они консольные, и тем или иным образом были удобны. До настоящего времени единственным включённым в состав JDK мониторинговым GUI-инструментом был jconsole. У jconsole, однако, есть один очень большой минус: она не предоставляет никаких возможностей профилировки.
Однако в NetBeans есть отличный профайлер! Кроме того, платформа NetBeans достаточно модульная, чтобы можно было выделить профайлер в отдельный инструмент и распространять его в составе JDK. А если ещё прикрутить туда сбор всей информации, доступной в jconsole, то получится универсальный инструмент для мониторинга, профилировки и диагностики Java-приложений.
Инженеры Sun это сделали, и так родился
Подразумевается, что интерфейс VisualVM интуитивно понятен, поэтому подробно разбирать его я не буду. Постараюсь вместо этого рассказать о философии, стоящей за этим инструментом. В качестве тестируемого приложения я выбрал свободно распространяемый набор бенчмарок DaCapo, конкретно тест lusearch, который внутри гоняет тест производительности на Apache Lucene. Цель данного топика — показать возможности VisualVM, а не поведение конкретной виртуальной машины на конкретном оборудовании в конкретных условиях.
Перед тем, как начать саму демонстрацию, я скачал и установил несколько дополнений к VisualVM, которые покажу ниже. Для этого я запустил VisualVM:
$JAVA_HOME/bin/jvisualvmЕсли у вас стоит Sun JDK 6u7 и выше, то VisualVM у вас уже есть, и она доступна как и мне, из каталога с JRE. Если у вас более старая машина, то лучше проапгрейдиться :) Но можно скачать VisualVM отдельно.
Вот так выглядит этот притаившийся зверь
В меню «Tools -> Plug-ins» установил VisualGC
Всё готово! Время опробовать его в действии. Я запустил фоном DaCapo:lusearch
/opt/jdk1.6.0_14/bin/java -server -jar dacapo-2006-10-MR2.jar -n 100 lusearchи отправился в VisualVM. Нашёл в дереве слева интересующий меня java-процесс (можно увидеть, что там торчат ещё сам VisualVM и мой Eclipse), сделал на нём Open и попал в Overview моего процесса:
Здесь не так интересно, поэтому я поспешил перейти на вкладку Monitor и посмотреть на высокоуровневую статистику:
На скриншоте легко можно увидеть графики утилизации CPU (включая активность GC), количество загруженных классов и созданных нитей, состояние памяти.
Можно получить информацию о памяти чуть детальнее, здесь нам и пригодится VisualGC:
То, что здесь происходит, будет понятно тем, кто знает, как устроен сборщик мусора. Конкретно на этом скриншоте можно увидеть три пространства для объектов: постоянное, старое и молодое. Последнее разбито на ещё на три подпространства: эдем и два пространства под выжившие объекты. Данные обновляются вживую, а графики справа показывают, что происходило за последнее время. По этому скриншоту можно оценить, правильно ли GC работает на конкретном приложении. Здесь я вижу, что часть объектов перемещается в old space, а потом всё-таки убирается полным GC: может, стоит покрутить promotion thresholds? Или попробовать другой GC?
Вернёмся пока к закладкам. На закладке Threads можно увидеть подробную статистику по нитям. Там есть несколько режимов просмотра, оставляю их любопытному читателю :)
Как и в старой доброй jconsole, можно посмотреть на MBeans:
И наконец! Самое вкусное в этом посте: профайлер.
У профайлера есть два режима: CPU и Memory. Первый профилирует методы с точки зрения проведённого в них времени, второй — с точки зрения созданных и уничтоженных объектов. Попробуем для начала CPU. Для этого прямо здесь и сейчас нажимаем кнопку «CPU»:
Интересная и полезная особенность состоит в том, что приложение всё ещё работает, профайлер инструментировал приложение на лету. Вот и первые результаты, видно, какой метод занимает больше всего времени. Но это только часть всего дела: неясно ведь, откуда его зовут.
Поэтому мы делаем snapshot при помощи соответствующей кнопки, и открываем его:
Это — все нитки, которые были пойманы профайлером.
Развернём одну из них:
Видно, что исполнение началось с вызова метода QueryThread.run() и дальше оно разбилось на две стадии: QueryParser.parse(...) и Searcher.search(...). Кажется, это правильно.
Пойдём глубже:
Видно всю глубокую цепочку вызовов, а так же конечных бойцов, которые светятся своим Self time'ом: IndexInput.readV*(). Если бы это было моё приложение, я бы начал задумываться, а нельзя ли на этих методах сэкономить, или как-нибудь их оптимизировать :)
А где же наши горячие места в этом стеке? Перейдём на combined view и выберем первый горячий метод:
Вон он где.
На этом с CPU профайлером закончим: мы уже узнали, где приложение проводит бОльшую часть своего времени. Попробуем Memory профайлер. Для этого на вкладке Profiler я нажимаю кнопку «Stop», жду когда CPU профайлер отменит инструментацию, а потом жму «Memory». Через некоторое время мы видим это:
Ага, кажется, у нас преобладают массивы char[]. Неудивительно для Lucene. Однако, я хочу бОльшего: сейчас я смотрю на статистику живых объектов, а хочу узнать, какие объекты вообще создавались за время всего профилирования. Для этого я иду в Settings и прошу учитывать только аллокации объектов:
(вместе с этим я включил запись стеков для аллокаций)
Вот что у нас в длинном профиле доминирует:
Те же самые парни. Ну что ж, теперь я хочу увидеть, откуда они взялись. Выбираю интересующий меня класс, и прошу показать мне stack trace.
Вот и он! Видно, что подавляющая часть аллокаций происходит внутри Lucene, в методе FastCharStream.refill(). Интересно, в Lucene дубликатный класс в разных пакетах?
Откуда эти методы зовутся? Отсюда:
Несмотря на то, что Memory профайлер не делает статического анализа на предмет того, правильно ли вы обращаетесь с памятью, он даёт вам ценную информацию, а что же у вас в памяти творится. Сняв такой профиль в экстремальном режиме работы приложения, когда вот-вот будет OOME (кстати, VisualVM умеет это событие перехватывать), можно одним махом увидеть, какие и откуда объекты пришли.
Потом — классический heap dump.
Продолжал бы и дальше, но «поля здесь слишком узки» (с).
Напомню, что этот чудесный инструмент доступен большинству практически мгновенно (в $JAVA_HOME/bin/jvisualvm), а остальной части сообщества — с небольшими телодвижениями. Надеюсь, теперь, когда отпрофилировать приложение будет так просто, культура performance-wise программирования привьётся куда лучше :)
Да, и помните завет Кнута: «Premature optimization is the root of all evil».
комментарии (27)
В большинстве вещей они пересекаются, в том большинстве, которое требуется рядовому пользователю/разработчику. Поэтому, учитывая распространённость и бесплатность VisualVM… К тому же, performance-семплирование в VisualVM неофициально заявлено, а memory-семплирование уже доступно в виде плагина.
Раньше пользовался связкой JProfiler и YourKit (там лучше средства для поиска тонких мест). Сейчас перешел на NetBeans profiler + изредка YourKit.
$ ps aux | grep java | grep agent
shade 18323 83.1 1.5 668672 32564 pts/1 Sl+ 14:22 0:05 /opt/sun-jdk-1.6.0.13/jre/bin/java -agentpath:/home/shade/tools/yjp-8.0.9/bin/linux-x86-32/libyjpagent.so=port=58295,cpu=times -cp classes Intersection
Я правильно понимаю, что я могу просматривать какие объекты созданы, но не могу узнать, кем они были созданы?
P.S. Может быть вы напишете статью про плагины VisualVM? Думаю, это многим бы было интересно.
теперь не нужен jprofiler!
Жаль не работает с Java5.
Мне просто интересно, а что Вас ещё держит на Java5? У вас appserver, сертифицированный под конкретную версию JRE? Почему бы не переехать на Java6?
Переход на новый Jboss вместе с Java6, запланирован на ближайшие мажорные релизы.
Инструментирующие профайлеры имеют достаточно большие накладные расходы, но зато дают самые аккуратные результаты. Работа такого профайлера сильно искажает работу приложения, но накладные расходы в теории равномерно размазываются по всем методам. Семплирующие профайлеры имеют практически нулевые накладные расходы, но зато требуют бОльшего времени накопления результатов.
Как я уже писал выше, в VisualVM сейчас реализованы инструментирующие профайлеры, в то время как в пресловутом YourKit реализованы семплирующие. В VisualVM можно ограничить набор классов, подлежащих инструментации, таким образом снизив накладные расходы. Для Memory-профайлера можно увеличить количество объектов, подлежащих учёту. В настоящее время в VisualVM ведутся разработки как раз семплирующего профайлера.
Обычно при полной инструментации, включая java.*, я наблюдаю снижение производительности примерно в два раза. Если профилировать только пользовательский код, снижение гораздо меньше.
можешь подскажешь — где я могу почитать все про память в java?
что такое PermGen и т.д. и т.п.
Навскидку угадаете, где в какой платформе вообще был в первый раз разработан и применён GC?
java.sun.com/docs/hotspot/gc5.0/gc_tuning_5.html
blogs.sun.com/vmrobot/entry/основы_сборки_мусора_в_hotspot