DTrace, динамическая среда трассировки в Solaris (см. Dtrace (1m) ), является ценным и чрезвычайно простым в использовании инструментом, если вы анализируете проблемы производительности Java в Solaris. Хотя имеется много информации о DTrace (см. DTrace Wiki , которая включает в себя подробное руководство пользователя), меньше информации об использовании DTrace, в частности, с приложениями Java. Моя мотивация в этом посте — сосредоточиться на профилировании приложений Java с помощью DTrace.
Быстрый Тур
Если вы совсем не знакомы с DTrace, обратитесь к разделу « Начало работы » в руководстве пользователя. Короче говоря, DTrace позволяет вам указать набор действий, которые вы хотели бы выполнить в интересующем вас месте (в ядре или в приложении). Местоположение интереса упоминается как исследование . В дополнение к числовому идентификатору каждый зонд идентифицируется следующими четырьмя частями информации:
- Имя провайдера зонда
- Модуль зонда
- Название функции, в которой находится зонд
- Название для зонда, разработанного для удобства чтения
(Кстати, если у вас нет среды Solaris, но вы все еще хотите следовать ей, вы можете установить VirtualBox , затем получить образ ISO для OpenSolaris , а затем следовать руководству VirtualBox, чтобы начать работу с OpenSolaris).
Какие зонды доступны? Ну очень много. В моей среде OpenSolaris (2009.06) подсчет (с использованием pfexec dtrace -l | wc -l ) дает 60068 проб! (Примечание: это включает в себя некоторые специфичные для Java-6 зонды; подробнее об этом позже). Большинство из них являются довольно низкоуровневыми зондами с точки зрения профилировщика Java, но давайте возьмем один и посмотрим, что мы можем с ним сделать.
Используя DTrace, мы можем выполнять действия при вводе системного вызова read , используя следующее:
pfexec dtrace -n syscall::read:entry
Если вы введете это, вы начнете видеть вывод, такой как следующее:
0 57922 read:entry
0 57922 read:entry
0 57922 read:entry
0 57922 read:entry
0 57922 read:entry
Обратите внимание, это не говорит вам много; вы не знаете PID процессов, выполняющих вызовы, и так далее. DTrace имеет ряд встроенных функций и переменных, которые можно использовать для обеспечения значимого вывода в этих местах. Я не буду вдаваться в подробности, потому что по ссылкам, упомянутым выше, имеется большой объем информации по этим темам. Это просто очень быстрый обзор, посвященный специфическим для Java зондам.
На этом этапе, прежде чем идти дальше, вы начинаете помещать свои объявления и логику в файл. DTrace понимает язык программирования D, язык, который будет знаком большинству разработчиков (особенно разработчикам C). Приведенный выше пример syscall :: read: entry , помещенный в файл и расширенный до 1), применяется только к указанному PID, и 2) распечатывает имя процесса, следующим образом:
syscall::read:entry
/pid == $1/
{
printf("'%s' (PID: %d): entered syscall:read", execname, pid);
}
Поместите следующий текст в файл с именем blogExample.d , затем найдите процесс для мониторинга (я выбрал Firefox) и введите следующее, заменив PID процесса по вашему выбору:
pfexec dtrace -s blogExample.d 697
и вы должны увидеть вывод, похожий на следующий:
0 57922 read:entry 'firefox-bin' (PID: 697): entered syscall:read
0 57922 read:entry 'firefox-bin' (PID: 697): entered syscall:read
0 57922 read:entry 'firefox-bin' (PID: 697): entered syscall:read
0 57922 read:entry 'firefox-bin' (PID: 697): entered syscall:read
Обратите внимание на предикат ( / pid == $ 1 / ) в примере, который ограничивает действия, которые должны выполняться, только когда pid (встроенная переменная DTrace) равен первому аргументу, предоставленному в командной строке ( $ 1 ). Чтобы подавить все выходные данные, кроме указанного в вашем вызове printf () , добавьте параметр -q («quiet») (вам нужно будет добавить новую строку в конце спецификации printf () также как «quiet») режим не обеспечивает один):
pfexec dtrace -q -s blogExample.d 697
и вы должны увидеть вывод, похожий на следующий:
'firefox-bin' (PID: 697): entered syscall:read
'firefox-bin' (PID: 697): entered syscall:read
'firefox-bin' (PID: 697): entered syscall:read
'firefox-bin' (PID: 697): entered syscall:read
'firefox-bin' (PID: 697): entered syscall:read
Это завершает быстрый тур по DTrace. Теперь перейдем к нашей главной теме!
Поддержка DTrace в Java
Java SE 6 теперь поддерживает DTrace в виде пары провайдеров (специфично для JVM HotSpot):
- горячая точка
- hotspot_jni
Для получения дополнительной информации см. DTrace Probes в HotSpot VM . В этом посте мы сосредоточимся на провайдере точек доступа . Обычно вы ожидаете найти провайдера с помощью команды dtrace -l , который ищет « горячую точку ». Такой подход помогает вам пройти большую часть пути; на самом деле, провайдеры работают на основе JVM, и их идентифицируют, добавляя PID к имени « горячая точка ». Так, например, если у вас запущен Java-процесс, а его PID равен 1234, тогда будет поставщик DTrace с именем « hotspot1234 ». Это соглашение об именах является причиной того, что вы увидите ссылки на » горячую точку $ 1«в примере сценариев на языке D — автор ожидает PID в командной строке и использует его для создания имени провайдера. Это соглашение также избавляет нас от необходимости ограничивать наши действия зонда определенным PID, поскольку ограничение встроенный по выбору провайдера.
Вернемся к специфическим для Java зондам. Введите следующую команду в оболочке:
pfexec dtrace -l | grep hotspot
и вы должны увидеть список всех зондов hotspot и hotspot_jni . В моей системе у меня было 499 проб с одним запущенным Java-процессом; Обратите внимание, что для каждой JVM будет полный набор. У меня 26 зондов » hotspot » и 473 зонда » hotspot_jni «. Я буду только смотреть на зонды » горячей точки » в этом посте. Вы также можете получить список этих проб и их аргументы в разделе « Справка » DTrace Probes в HotSpot VM .
Несколько примеров
Мониторинг потоков
Обратите внимание на следующие два исследования, связанные с деятельностью потока:
probe thread-start(char* thread_name, uintptr_t thread_name_length,
uintptr_t java_thread_id, uintptr_t native_thread_id, bool is_daemon);
probe thread-stop(char* thread_name, uintptr_t thread_name_length,
uintptr_t java_thread_id, uintptr_t native_thread_id, bool is_daemon);
Одна интересная деталь, которую следует отметить со строковыми аргументами в DTrace, состоит в том, что они идут парами, где первый элемент — это указатель на неоконченную строку, а второй элемент — это длина строки. Из-за этого соглашения в примере кода вы часто будете видеть следующую конструкцию, которая строит строку с нулевым символом в конце из предоставленной информации:
self->str_ptr = (char*) copyin(arg0, arg1+1);
self->str_ptr[arg1] = '\0';
self->stringVariable = (string) self->str_ptr;
Обратите внимание, что приведенный выше фрагмент может быть использован для создания имени потока из приведенных выше тестов запуска потока .
Чтобы увидеть, как легко использовать DTrace для создания простого профилировщика потоков в Java 6, откройте файл в текстовом редакторе и введите следующее:
hotspot$1:::thread-start
{
self->ptr = (char*) copyin(arg0, arg1+1);
self->ptr[arg1] = '\0';
self->threadname = (string) self->ptr;
printf("thread-start: '%s' (thread ID = %d; native thread ID = %d; is_daemon? %d)\n",
self->threadname, arg2, arg3, arg4);
}
hotspot$1:::thread-stop
{
self->ptr = (char*) copyin(arg0, arg1+1);
self->ptr[arg1] = '\0';
self->threadname = (string) self->ptr;
printf("thread-stop: '%s' (thread ID = %d; native thread ID = %d; is_daemon? %d)\n",
self->threadname, arg2, arg3, arg4);
}
Обратите внимание, как упоминалось ранее, макрос-переменная $ 1 , представляющая идентификатор процесса JVM, который вы будете передавать в командной строке. В этом сценарии мы выводим все, что получаем от этих двух зондов, а именно: имя потока, идентификатор, собственный идентификатор и логическое значение « is_daemon» . Сохраните этот файл как threadWatcher.d и введите следующее:
pfexec dtrace -q -s threadWatcher.d pid
замена идентификатора процесса работающей JVM. В моем тестовом Java-приложении я открыл средство выбора файлов и получил следующий вывод от DTrace:
thread-start: 'Basic L&F File Loading Thread' (thread ID = 42; native thread ID = 42; is_daemon? 0)
thread-stop: 'Basic L&F File Loading Thread' (thread ID = 42; native thread ID = 42; is_daemon? 0)
thread-start: 'Basic L&F File Loading Thread' (thread ID = 43; native thread ID = 43; is_daemon? 0)
thread-start: 'Basic L&F File Loading Thread' (thread ID = 41; native thread ID = 41; is_daemon? 0)
thread-stop: 'Basic L&F File Loading Thread' (thread ID = 41; native thread ID = 41; is_daemon? 0)
thread-stop: 'Basic L&F File Loading Thread' (thread ID = 43; native thread ID = 43; is_daemon? 0)
Вывоз мусора
Обратите внимание на следующие датчики, относящиеся к сбору мусора:
probe gc-begin(bool is_full);
probe gc-end();
probe mem-pool-gc-begin(
char* mgr_name, uintptr_t mgr_name_len, char* pool_name, uintptr_t pool_name_len,
uintptr_t initial_size, uintptr_t used, uintptr_t committed, uintptr_t max_size);
probe mem-pool-gc-end(
char* mgr_name, uintptr_t mgr_name_len, char* pool_name, uintptr_t pool_name_len,
uintptr_t initial_size, uintptr_t used, uintptr_t committed, uintptr_t max_size);
Первые два зонда предоставляют общую информацию о запуске и остановке сборки мусора, а два последних предоставляют более подробную информацию. Мы выведем информацию из обоих для сравнения. Обратите внимание, что имя менеджера и имя пула предоставляются с теми же парами указатель / длина данных, которые мы видели ранее.
Откройте файл с именем gcWatcher.d в текстовом редакторе и введите следующее:
hotspot$1:::gc-begin
{
printf("gc-begin: is_full = %d\n", arg1);
}
hotspot$1:::gc-end
{
printf("gc-end:\n");
}
hotspot$1:::mem-pool-gc-begin
{
self->ptr1 = (char*) copyin(arg0, arg1+1);
self->ptr1[arg1] = '\0';
self->mgr_name = (string) self->ptr1;
self->ptr2 = (char*) copyin(arg2, arg3+1);
self->ptr2[arg3] = '\0';
self->pool_name = (string) self->ptr2;
printf("mem-pool-gc-begin: mgr: '%s'; pool: '%s'; initial: %d; used: %d; committed: %d; max: %d\n",
self->mgr_name, self->pool_name, arg4, arg5, arg6, arg7);
}
hotspot$1:::mem-pool-gc-end
{
self->ptr1 = (char*) copyin(arg0, arg1+1);
self->ptr1[arg1] = '\0';
self->mgr_name = (string) self->ptr1;
self->ptr2 = (char*) copyin(arg2, arg3+1);
self->ptr2[arg3] = '\0';
self->pool_name = (string) self->ptr2;
printf("mem-pool-gc-end: mgr: '%s'; pool: '%s'; initial: %d; used: %d; committed: %d; max: %d\n",
self->mgr_name, self->pool_name, arg4, arg5, arg6, arg7);
}
Сохраните файл, затем проследите свое Java-приложение следующим образом:
pfexec dtrace -q -s gcWatcher.d pid
Для моего примера, после небольшой активности в моем приложении, я увидел несколько небольших коллекций; вот вывод одного из них:
gc-begin: is_full = 0 mem-pool-gc-begin: mgr: 'Copy'; pool: 'Code Cache'; initial: 163840; used: 1751360; committed: 1769472; max: 33554432 mem-pool-gc-begin: mgr: 'Copy'; pool: 'Eden Space'; initial: 917504; used: 917504; committed: 917504; max: 4194304 mem-pool-gc-begin: mgr: 'Copy'; pool: 'Survivor Space'; initial: 65536; used: 58904; committed: 65536; max: 458752 mem-pool-gc-begin: mgr: 'Copy'; pool: 'Tenured Gen'; initial: 4194304; used: 1406096; committed: 4194304; max: 61997056 mem-pool-gc-begin: mgr: 'Copy'; pool: 'Perm Gen'; initial: 12582912; used: 1144824; committed: 12582912; max: 67108864 mem-pool-gc-begin: mgr: 'Copy'; pool: 'Perm Gen [shared-ro]'; initial: 8388608; used: 6733248; committed: 8388608; max: 8388608 mem-pool-gc-begin: mgr: 'Copy'; pool: 'Perm Gen [shared-rw]'; initial: 12582912; used: 7676960; committed: 12582912; max: 12582912 mem-pool-gc-end: mgr: 'Copy'; pool: 'Code Cache'; initial: 163840; used: 1751360; committed: 1769472; max: 33554432 mem-pool-gc-end: mgr: 'Copy'; pool: 'Eden Space'; initial: 917504; used: 0; committed: 917504; max: 4194304 mem-pool-gc-end: mgr: 'Copy'; pool: 'Survivor Space'; initial: 65536; used: 29648; committed: 65536; max: 458752 mem-pool-gc-end: mgr: 'Copy'; pool: 'Tenured Gen'; initial: 4194304; used: 1458336; committed: 4194304; max: 61997056 mem-pool-gc-end: mgr: 'Copy'; pool: 'Perm Gen'; initial: 12582912; used: 1144824; committed: 12582912; max: 67108864 mem-pool-gc-end: mgr: 'Copy'; pool: 'Perm Gen [shared-ro]'; initial: 8388608; used: 6733248; committed: 8388608; max: 8388608 mem-pool-gc-end: mgr: 'Copy'; pool: 'Perm Gen [shared-rw]'; initial: 12582912; used: 7676960; committed: 12582912; max: 12582912 gc-end:
Обратите внимание , что не очень много информации доступно от родовой сборки мусора
начать и
конец зонда, а гораздо больше информации можно получить из
мем-пул зондов.
Конечно, вы можете сделать гораздо больше, чем просто распечатать значения аргументов зонда; см. справочные документы для получения дополнительной информации. Например, вы можете подсчитать и вывести количество потоков, созданных за период времени, собрать статистику по среднему времени жизни потока, вывести среднее количество памяти, восстановленной во время сборки мусора, и так далее.
Другие соображения
Один вопрос, который у вас может возникнуть: «Насколько дороги эти операции?» Это зависит от операции. Зонды, которые мы рассмотрели выше, относительно недороги. Другие зонды, такие как зонды входа-метода и метода-выхода или те, которые занимаются распределением объектов мониторинга, намного дороже и действительно имеют значительную стоимость при включении, даже когда они не используются.
По этой причине существует опция JVM — -XX: + ExtendedDTraceProbes — которая при наличии включает эти и некоторые другие дорогостоящие пробники. Для получения дополнительной информации см. Раздел «Эффект от использования DTrace с программами Java» в статье Observability Using Java Platform, Standard Edition 6 и Solaris OS . Если эта опция не включена, DTrace будет игнорировать любые из вышеупомянутых зондов в вашем приложении профилирования, избавляя вас от непреднамеренного замедления работы чьего-либо рабочего сервера.
Это конец этого быстрого тура. Как я упоминал ранее, в DTrace доступно множество ресурсов, в частности руководство пользователя в DTrace wiki (см. Ссылку «Документация» или перейдите непосредственно по этой ссылке ).