Практическое применение DTrace

Вглубь Java

Мы уже знаем, что с помощью DTrace можно выяснить, какие конкретно функции вызываются, в каком порядке, какие аргументы передаются и сколько времени потрачено на их выполнение. Все это могло вдохновить системных администраторов и разработчиков на языках С и С++, а интересы программистов на Java оставались в стороне. В этой статье мы рассмотрим, как можно использовать DTrace для отладки приложений на Java.

Для предоставления такой возможности Sun Microsystems встроила в код JVM (начиная с JDK 6.0) датчики двух провайдеров – hotspot и hotspot_jni. В JDK 5.0 был провайдер dvm. Для тех, кто привык им пользоваться, есть хорошая новость – датчики провайдера hotspot носят такие же имена, как и датчики провайдера dvm.

Провайдер hotspot имеет ряд датчиков, с помощью которых можно отслеживать запуск и работу сборщика мусора в JVM (garbage collector). Если количество запусков сборщика мусора растет (особенно, если быстро растет) во время работы приложения или время работы постоянно увеличивается – это верный признак утечки памяти в приложении.

Провайдер hotspot_jni требуется для отслеживания событий, связанных с обращениями через JNI (Java native interface – интерфейс Java с машинным кодом, т.е. ранее написанными и скомпилированными методами, реализованными на языке С). Строго говоря, это может быть программа не только на языке С, ибо JNI описывает интерфейс между программой на Java и машинным кодом, и в нем не указано, компилятор с какого языка должен создать этот код.

Уже было упомянуто, что провайдеры hotspot и hotspot_jni основаны на провайдере sdt и на их датчики можно ссылаться только с упоминанием идентификатора процесса самой машины Java (JVM). Вот пример скрипта, который показывает частоту вызова GC:

hotspot$target:::gc-begin
{
printf("GC called at %Y\n", walltimestamp);
}

Если запустить выполнение программы на java, скажем, демонстрационный пример /usr/jdk/instances/jdk1.6.0/demo/jfc/Java2D/Java2Demo.jar, а затем этот скрипт, то он покажет, в какие моменты запускался сборщик мусора:

# java -jar /usr/jdk/instances/jdk1.6.0/demo/jfc/Java2D/Java2Demo.jar 
[1] 1147
# dtrace -qn 'hotspot$target:::gc-begin
{
printf("GC called at %Y\n", walltimestamp);
}' -p 1147
GC called at 2008 Feb 7 01:50:15
GC called at 2008 Feb 7 01:50:16
GC called at 2008 Feb 7 01:50:17
GC called at 2008 Feb 7 01:50:18
GC called at 2008 Feb 7 01:50:19
GC called at 2008 Feb 7 01:50:20
GC called at 2008 Feb 7 01:50:21
GC called at 2008 Feb 7 01:50:25

А что, если нам надо выяснить, какие методы вызываются в приложении Java? Возьмем вот такое приложение:

# cat Greeting.java
public class Greeting {
public void greet() {
System.out.println("Hello DTrace!");
}
}
# cat TestGreeting.java
public class TestGreeting {
public static void main(String[] args) {
Greeting hello = new Greeting();
while (true) {
hello.greet();
try {
Thread.currentThread().sleep(1000);
} catch (InterruptedException e) {
}
}
}
}

Скомпилируем его:

javac TestGreeting.java

Теперь надо запустить получившееся приложение (мирно лежащее в TestGreeting.class ). Однако прежде надо разобраться, как включать датчики в Java SE 6. По умолчанию в виртуальной машине Java доступен лишь небольшой набор датчиков – тех, которые практически не влияют на производительность. Эти датчики позволяют отследить не все события: сборку мусора, компиляцию методов, создание нового потока команд и загрузку класса.

Вызов метода, например, в этот список не входит, потому что соответствующий датчик оказывает значимое влияние на производительность и оттого по умолчанию недоступен. К таким датчикам, кроме датчиков вызова методов, также относятся датчики создания объектов и датчики событий, связанных с мониторами Java. Чтобы сделать такой датчик доступным и "видимым" для dtrace, надо запускать java с ключами, разрешающими использование этих датчиков, или (если JVM уже запущена) использовать команду jinfo для управления JVM.

Доступны следующие ключи при запуске java:

-XX:+DTraceAllocProbes
-XX:+DTraceMethodProbes
-XX:+DTraceMonitorProbes
-XX:+ExtendedDTraceProbes

Первые три ключа разрешают использование датчиков создания объектов, вызова методов и датчиков событий, связанных с мониторами Java соответственно, а четвертый разрешает использование всех датчиков в JVM. Фактическое влияние включенных датчиков на производительность может быть различным в зависимости от частоты вызова кода, содержащего встроенный датчик.

Запускаем наше приложение:

# java -XX:+ExtendedDTraceProbes TestGreeting 
[1] 1448
Hello DTrace!
Hello DTrace!
Hello DTrace!
Hello DTrace!

Возьмем скрипт hs.d, вот такой:

# cat hs.d
hotspot$target:::method-entry
{
printf("%s.\%s %s\n",copyinstr(arg1,arg2),copyinstr(arg3,arg4),
copyinstr(arg5,arg6));
}
tick-5ms
{
exit(0);
}

Конструкция hotspot$target означает, что вместо $target будет подставлен аргумент, переданный с ключом p при запуске dtrace (это будет идентификатор процесса java).

Из описания датчиков провайдера hotspot (http://java.sun.com/ javase/6/docs/technotes/guides/vm/dtrace.html) известно, что аргументы датчика method-entry следующие:

Сигнатура метода – это совокупность имени функции, типа возвращаемого значения и списка аргументов с указанием порядка их следования и типов. Подробнее об обозначениях, применяемых в сигнатурах, можно прочесть, например, в разделе Type Signatures в спецификации JNI, размещенной по адресу http://java.sun.com/j2se/1.3/docs/guide/jni/spec/types.doc.html.

Наш скрипт должен при каждом срабатывании датчика methodentry, т.е. при каждом вызове любого метода в нашем приложении на Java, выводить имя класса, имя метода и подпись. Обратите внимание на использование функции copyinstr для вывода строк.

Для автоматического завершения скрипта через 5 миллисекунд добавлена конструкция tick-5ms.

Запустим скрипт в соседнем окне терминала:

# dtrace -qs hs.d -p 1448
Greeting.\greet ()V
java/io/PrintStream.\println (Ljava/lang/String;)V
java/io/PrintStream.\print (Ljava/lang/String;)V
java/io/PrintStream.\write (Ljava/lang/String;)V
java/io/PrintStream.\ensureOpen ()V
java/io/Writer.\write (Ljava/lang/String;)V
java/io/BufferedWriter.\write (Ljava/lang/String;II)V
java/io/BufferedWriter.\ensureOpen ()V
java/io/BufferedWriter.\min (II)I
java/lang/String.\getChars (II[CI)V
java/lang/System.\arraycopy (Ljava/lang/Object;ILjava/lang/Object;II)V
java/io/BufferedWriter.\flushBuffer ()V
java/io/BufferedWriter.\ensureOpen ()V
java/io/OutputStreamWriter.\write ([CII)V
sun/nio/cs/StreamEncoder.\write ([CII)V
sun/nio/cs/StreamEncoder.\ensureOpen ()V
sun/nio/cs/StreamEncoder.\implWrite ([CII)V
java/nio/CharBuffer.\wrap ([CII)Ljava/nio/CharBuffer;
java/nio/HeapCharBuffer.\<init> ([CII)V
java/nio/CharBuffer.\<init> (IIII[CI)V
java/nio/Buffer.\<init> (IIII)V
java/lang/Object.\<init> ()V

В недрах скриптов на PHP

Функциональность DTrace становится все популярнее, и ее добавляют не только в Java, но и в другие приложения. Далее мы рассмотрим изучение работы скриптов на php и СУБД, с которой они общаются, с помощью dtrace.

Как и в случае с JVM, нам потребуется php с встроенными в код датчиками. Для этого потребуется скачать и установить модуль dtrace.so для PHP. В Solaris Express Developer Edition 1/08 модуль уже есть – /usr/php5/5.2.4/modules/dtrace.so. Когда модуль уже готов к работе, надо вписать в php.ini строку

extension=dtrace.so

Проверяем, есть ли поддержка dtrace в PHP:

# /usr/php5/5.2.4/bin/php -i | grep -i dtrace
/etc/php5/5.2.4/conf.d/dtrace.ini,
dtrace
dtrace support => enabled

Теперь предположим, что у нас есть база данных, которая состоит из единственной таблицы, где хранится наша записная книжка. Чтобы облегчить задачу, предположим, что в ней записаны только имена, фамилии и телефоны наших знакомых:

CREATE TABLE notebook (
id INT AUTO_INCREMENT PRIMARY KEY,
name VARCHAR(50),
lastname VARCHAR(50),
phone VARCHAR(15)
);

Теперь напишем скрипт на php, который будет извлекать из этой таблицы сведения:

<?php
$dbname="personal";
$dbhost="localhost";
$dblogin="filip";
$dbpass="9bdx57";
$link = mysql_pconnect($dbhost, $dblogin, $dbpass);
mysql_select_db ($dbname,$link) or die ('Connection Error.');
$query = "SELECT name , lastname , phone FROM notebook";
$result = mysql_query($query) or die ('Execution error. ' .
mysql_error());
$message = '';
while ($row = mysql_fetch_array($result)) {
$message = $message . sprintf("%s %% %s %% %s
\n",$row[0],$row[1],$row[2]);
}
echo $message;
mysql_free_result($result);
?>

Пропустим здесь этап заполнения базы данных сведениями и предположим, что данные в таблице notebook уже есть. Интересно, много ли можно узнать с помощью датчиков DTrace в php? Провайдер php предоставляет два датчика, срабатывающих при вызове функции и окончании ее работы: function-entry и function-return.

Аргументы этих датчиков:

Возьмем простой скрипт для трассировки работы нашего приложения на php:

#!/usr/sbin/dtrace -Zqs
php*:::function-entry
{
printf("called %s() in %s at line %d\n",copyinstr(arg0),
copyinstr(arg1),arg2)
}

Ключ Z позволяет запустить скрипт, даже если дескриптор ( php*:::function-entry ) не соответствует ни одному датчику (а это в момент запуска скрипта будет именно так, потому что мы еще на запустили скрипт и модуль dtrace.so не загружен). В одном окне запустим наше приложение на php:

php simpledb.php
Philip % Rock % +74951110808
Ivan % Markov % +74951110808
а в другом – скрипт dtrace для отслеживания его работы:
./php-trace.d
called mysql_pconnect() in /export/home/filip/simpledb.php at line 7
called mysql_select_db() in /export/home/filip/simpledb.php at line 8
called mysql_query() in /export/home/filip/simpledb.php at line 11
called mysql_fetch_array() in /export/home/filip/simpledb.php at line 15
called sprintf() in /export/home/filip/simpledb.php at line 16
called mysql_fetch_array() in /export/home/filip/simpledb.php at line 15
called sprintf() in /export/home/filip/simpledb.php at line 16
called mysql_fetch_array() in /export/home/filip/simpledb.php at line 15
called mysql_free_result() in /export/home/filip/simpledb.php at line 20

Теперь мы знаем больше о том, как вызываются функции в нашем скрипте на php.

А еще можно выяснить, какие команды наше приложение передает серверу баз данных и сколько времени он на это тратит.

Внутри баз данных: Postgresql и MySQL

Мы рассмотрим возможности по динамическому наблюдению за сервером СУБД, которые предоставляет вживленный в MySQL и Postgresql код. По имеющимся сейчас сведениям от разработчиков MySQL провайдер mysql планируется включить в код СУБД в версии 6.0.4. Однако уже в версии 6.0 можно обнаружить предварительный вариант кода этого провайдера, и если вы хотите его попробовать уже сейчас, это можно сделать, указав при установке из исходных текстов ключ --enable-dtrace при вызове ./configure.

Более детально можно познакомиться с инструкциями по использованию DTrace в MySQL 6.0 на форуме пользователей DTrace по адресу http://www.opensolaris.org/jive/forum.jspa?forumID=7.

Здесь мы рассмотрим более хитрую методику отлова команд, переданных серверу MySQL, а затем перейдем к работе с postgresql, который уже давно поставляется с встроенными датчиками DTrace.

Дело в том, что с помощью провайдера pid мы можем получить информацию о вызове любой функции в любом приложении. Кстати, если нас больше интересует производительность ввода-вывода СУБД, то лучше обратиться к провайдеру io, но это уже предмет другой статьи.

В MySQL обработка запросов выполняется функцией mysql_parse

mysql_parse(THD *thd, char *inBuf, uint length)

Название ее второго аргумента звучит многообещающе. Попробуем следующий скрипт для того, чтобы получить список запросов, направленных серверу MySQL:

cat mysql-catch.d
pid$target::*mysql_parse*:entry
{
printf("%Y %s\n", walltimestamp, copyinstr(arg1));
}

Запустим его в одном окне

# dtrace -qs mysql-catch.d -p 1019

А в другом запустим уже знакомый скрипт на php для получения содержимого нашей записной книжки:

# php simpledb.php
Philip % Rock % +74951110808
Ivan % Markov % +74951110808

В первом окне мы получим ответ скрипта:

2008 Feb 7 22:58:35 SELECT name , lastname , phone FROM notebook

Готово!

Только придется помнить, что если на сервере запущено несколько экземпляров mysqld, надо позаботиться об указании правильного идентификатора процесса: это обязательно при работе с датчиками провайдера pid. Представленный скрипт справляется с тем, чтобы сообщить нам запрос, отправленный серверу. Может случиться так, что сервер отвергнет запрос – из-за отсутствия права доступа к данным у запрашивающего или из-за некорректности запроса.

Для анализа значения, которое возвращает функция, можно воспользоваться датчиком

pid$target::*mysql_execute_command*:return .

В arg1 у датчиков провайдера pid находится код возврата. Успешное завершение операции сервером MySQL даст код 0, и ненулевое значение — в противном случае.

Для контроля за выполнением операций достаточно добавить в скрипт mysql-catch.d еще один компонент:

pid$target::*mysql_execute_command*:return
{
printf("%Y %d \n", walltimestamp, arg1);
}

Теперь разберемся с Postgresql.

Начиная с версии postgresql 8.2 в него встроен код провайдера DTrace — posgresql.

Стало быть, для анализа запросов к этой СУБД можно использовать встроенные датчики, не исследуя исходный код сервера. Вот перечень этих датчиков:

probe transaction__start(int);
probe transaction__commit(int);
probe transaction__abort(int);
probe lwlock__acquire(int, int);
probe lwlock__release(int);
probe lwlock__startwait(int, int);
probe lwlock__endwait(int, int);
probe lwlock__condacquire(int, int);
probe lwlock__condacquire__fail(int, int);
probe lock__startwait(int, int);
probe lock__endwait(int, int);

Воспользуемся датчиками transaction-start и transaction-end для получения распределения времени транзакций:

#!/usr/sbin/dtrace -Zqs
postgresql*:::transaction-start
{
self->ts=timestamp;
@cnt[pid]=count();
}
postgresql*:::transaction-commit
{
@avg[pid]=avg(timestamp - self->ts);
}
tick-5sec
{
normalize(@avg, 1000000);
printf("%15s %30s %30s\n","PID","Total queries","Avegrage time (ms)");
printf("\t=================================================\n\n");
printa("%15d %@30d %@30d\n",@cnt,@avg);
printf("\t=================================================\n\n");
clear(@cnt);
clear(@avg);
}

Запуск этого скрипта даст нам реальную картину затрат времени на транзакции. Возможно, в вашем случае распределение будет иным – все зависит от фактической загрузки сервера:

# ./postgres_avg_query_time.d
PID Total queries Avegrage time (ms)
==========================================================
23814 46 57
23817 58 34
23816 59 32
23815 59 33
23818 75 26
==========================================================

А теперь обратимся к уже хорошо знакомому нам провайдеру pid и напишем скрипт для отслеживания запросов к СУБД (обратите внимание: имя функции в postgresql иное, нежели в mysql ):

#!/usr/sbin/dtrace -Zwqs
BEGIN
{
freopen("sql.trace");
}
pid$1::pg_parse_query:entry
{
printf("%s\n",copyinstr(arg0));
}

Обратите внимание на вызов freopen("sql.trace") – так мы перенаправим вывод скрипта с экрана в файл с указанным именем.

В этой лекции мы познакомились с тем, как использовать DTrace для анализа различных приложений, в том числе приложений на javascript, Java, PHP и SQL. Фактически, это дает нам полный набор инструментов для отладки как клиентской части приложений Web 2.0, так и серверной их части.

Мы старались показать, что даже если какое-то приложение не имеет встроенных датчиков DTrace, вы всегда можете либо добавить их в исходный код (как уже сделали разработчики PostgreSQL, например), либо использовать известные вам функции для анализа передаваемых ими аргументов и возвращаемых значений – с помощью провайдера pid.

Еще более подробную информацию о DTrace можно почерпнуть в руководстве "Dynamic Tracing Guide", где приводится подробное описание этих провайдеров. Этот документ вкупе с "DTrace User Guide" содержит полную документацию по DTrace и находится в свободном доступе на сайте http://docs.sun.com/. Также можно посоветовать страницу сообщества разработчиков DTrace на cайте opensolaris.org: http://opensolaris.org/ os/community/dtrace.