DTrace

[Rubik]

15.03.2011

 Филипп Торчинский, признанный эксперт в администрировании Unix-систем, раскрывает секреты приложений с помощью DTrace.

 Технология DTrace и подходящие инструменты для ее использования появились в 2005 году, но несмотря на это, DTrace еще малоизвестна в широких кругах разработчиков и сисадминов. Это тем более удивительно, что за пять с половиной лет, прошедших с выхода системы Solaris 10, в которой она впервые появилась, так и не было придумано более совершенной технологии наблюдения за операционной системой и приложениями.

 DTrace была разработана в компании Sun Microsystems, и открытый код всех ее компонентов был опубликован в том же 2005 году. С тех пор DTrace была перенесена в Mac OS X, QNX и FreeBSD, и появилась также во всех дистрибутивах, унаследовавших код ядра Solaris: Belenix, Korona, Nexenta, OpenIndiana и Milax. Разумеется, в Solaris технология DTrace тоже осталась и даже развилась - датчиков стало больше. В настоящее время DTrace доступна в самой свежей версии Solaris 11 Express, равно как и в Solaris 10.

 По сравнению с другими средствами сбора информации о системе и отладки приложений, DTrace обладает рядом уникальных свойств:

 [list=1]

• накапливает информацию о системе, работающей под максимальной нагрузкой - с низкими накладными расходами на сбор информации;
• собирает любую информацию из любых уголков системы, позволяя наблюдать как за работой приложений, так и за работой самого ядра системы;
• может показать, какие аргументы передаются от одной функции к другой, независимо от того, доступен ли исходный код функций;
• собирает информацию о том, как долго исполняются вызываемые функции, какой процент времени занимает исполнение каждой из них, сколько раз каждая из них была вызвана;
• фильтрует информацию любым заданным образом - например, позволяет ограничить область наблюдения одним приложением, одним потоком команд, или определенной областью (скажем, измерять время выполнения только конкретного системного вызова, а об остальном не заботиться);
• может реагировать на определенные события (ввод-вывод, вызов заданных функций, завершение программы, запуск нового потока и пр.);
• имеет как средства низкоуровнего наблюдения (можно изучать ход работы драйвера устройства), так и средства высокоуровневые, например, позволяет отслеживать определенные события при исполнении скриптов на PHP или вызов методов в приложении, написанном на Java;
• позволяет выполнять трассировку вызовов, с одновременным отслеживанием любых параметров - времени выполнения, переданных аргументов и пр.

Основным компонентом DTrace является модуль ядра, обеспечивающий функционирование подсистемы DTrace, а основным инструментом - приложение dtrace, которое воспринимает скрипты, написанные на языке D, созданном специально для работы с DTrace. В этой заметке мы не будем вдаваться в детали реализации DTrace; тем, кто в них заинтересован, я могу посоветовать найти их описание в Google, а также в главах 27 и 28 второго издания книги «Операционная система Solaris», написанной мной в соавторстве с Евгением Ильиным в 2009 году. Кроме того, наблюдение, профилирование и трассировка работы приложений с помощью DTrace подробно рассмотрены в одной из лекций по курсу «Системное администрирование ОС Solaris 10».

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

 Однажды на конференции OSDevCon в Дрездене Чад Минхир (Chad Mynhier) вел мастер-класс по DTrace. Интерес к нему был огромный, и вот почему. Чад работает в компании Forsythe, зарабатывающей миллионы долларов в месяц на оптимизации банковских приложений. Как-то раз у одного из заказчиков он триумфально ускорил работу приложения в тысячу раз, заодно побив рекорд скорости зарабатывания гонорара.

 Дело в том, что одно из основных банковских приложений, функциональность которого вполне удовлетворяла всех раньше, стало работать значительно медленнее с ростом нагрузки. Так как банк планировал еще больший рост нагрузки, опасное замедление становилось неприемлемым. Анализ приложения с помощью DTrace вначале не выявил ничего особенного, однако распределение функций по частоте вызовов показалось Чаду настораживающим: чаще всех вызывалась функция gettimeofday(), возвращающая текущее системное время. При работе с базами данных в вызове этой функции нет ничего подозрительного, так как в БД часто записывается время, в которое произошла транзакция, но эта функция отчего-то доминировала в вызовах... С помощью DTrace было локализовано место в приложении, где эта функция вызывалась чаще всего. Оказалось, что по недосмотру разработчика она вызывалась в цикле, который, как назло, тоже был задействован почти в каждой операции приложения.

 Не исключено, что вызов gettimeofday() остался от какого-то отладочного вывода или был помещен внутрь цикла по ошибке, но так или иначе, отловить эту ошибку на этапе тестирования не удалось, и всплыла она только тогда, когда нагрузка на приложение превысила определенный уровень. До того мощный компьютер легко справлялся с сотнями тысяч вызовов gettimeofday() в секунду.

 Cкрипт, выдающий количество функций, написать легко. В качестве затравки рассмотрим несколько вариантов, а затем перейдем к синтаксису скриптов. Например, вот такой скрипт выдает количество вызовов любых функций при работе программы ls (вначале на экран будет выдан результат ее работы, а потом - список функций с количеством вызовов для каждой в порядке возрастания):

Код [Выделить] Expand

pfexec dtrace -n 'pid$target:::entry {@funсtions[probefunc]=count();}' -c ls
А вот таким скриптом можно посчитать количество функций, вызванных конкретным процессом с PID=2355; для получения результата надо прервать выполнение скрипта с помощью Ctrl-C:

Код [Выделить] Expand

pfexec dtrace -n 'pid2355:::entry {@funсtions[probefunc]=count();}'
А вот так можно посчитать количество системных вызовов в том же процессе:

Код [Выделить] Expand

pfexec dtrace -n 'syscall:::entry /pid==2355/ {@funсtions[probefunc]=count();}'
Итак, в скриптах на языке D всегда используется следующий синтаксис:

Код [Выделить] Expand

провайдер:модуль:функция:датчик
/условие/
{
действия
}
Провайдер - это модуль ядра или модуль приложения, обеспечивающий регистрацию своих датчиков DTrace в системе. Например, провайдер syscall регистрирует датчики, расположенные в системных вызовах, провайдер mysql - датчики, встроенные в сервер MySQL.

 Модуль - это название модуля или библиотеки, например, libc.

 Функция - имя функции, датчик в которой нам интересен, например, fopen.

 Датчик - название датчика (во многих случаях датчик называется entry или return).

 Условие задает ситуацию, когда следует выполнить действие при срабатывании датчика. Например, надо выполнить его только тогда, когда датчик сработал в приложении top. Тогда условие выглядит так:

Код [Выделить] Expand

/execname == top/
 Действия - это то, что обеспечивает сбор информации и вывод ее на экран. Из примеров ниже будет ясно, какими они бывают.

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

 Простой пример того, как я использую DTrace в повседневной жизни: после переноса пользовательских настроек с одного компьютера на другой система на не захотела работать с принтером, как раньше. Было ясно, что какой-то из файлов настроек отчего-то не скопирован. Но какой именно? Их же сотни... Банальные /etc/printers и /etc/lp/* были проверены и разгадки не дали. Тогда пришлось задействовать DTrace. Простой скрипт дает возможность заглянуть в недра программы lpstat (наиболее безвредная программа из тех, что работает с принтером) и посмотреть, какие файлы она пытается открыть:

Код [Выделить] Expand

lpstat -s
scheduler is running
system default printer: eaqvap21
aqvap21: unknown printer
aqvap21: unknown printer

Чтобы запустить программу и подсунуть ее PID скрипту на DTrace надо использовать ключ -c :

Код [Выделить] Expand

dtrace -n 'pid$target::fopen:entry {printf("%s",copyinstr(arg0));}' -c "lpstat -s" dtrace: description 'pid$target::fopen:entry ' matched 1 probe
scheduler is running
system default printer: eaqvap21
aqvap21: unknown printer
aqvap21: unknown printer
dtrace: pid 11156 has exited
CPU ID FUNCTION:NAME
 0 59882 fopen:entry /etc/default/init
 0 59882 fopen:entry /etc/lp/ppd/eaqvap21.ppd
 0 59882 fopen:entry /export/home/filip/.printers
 0 59882 fopen:entry /export/home/filip/.printers
 0 59882 fopen:entry /export/home/filip/.printers
 0 59882 fopen:entry /etc/printers.conf
 0 59882 fopen:entry /export/home/filip/.printers
 0 59882 fopen:entry /etc/printers.conf
 1 59882 fopen:entry /etc/nsswitch.conf
 1 59882 fopen:entry /export/home/filip/.printers
 1 59882 fopen:entry /export/home/filip/.printers
 1 59882 fopen:entry /etc/printers.conf

 Вот и все: я забыл, что надо почистить файл .printers в домашнем каталоге:

Код [Выделить] Expand

rm /export/home/filip/.printers

 Готово! Все работает на ура!

 Замечание: подсовывать PID программы скрипту надо потому, что провайдер pid требует указания PID изучаемого с помощью DTrace процесса, а знакомый нам всем вызов fopen как раз относится к этому провайдеру DTrace.

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

Код [Выделить] Expand

pfexec dtrace -n 'syscall::open*:entry {printf("%s\n",copyinstr(arg0));}'

Этот скрипт валит в кучу данные от всех системных вызовов, имена которых начинаются на open, что неудобно, но зато его легче всего вспомнить и проще всего применить к уже запущенным приложениям, а полученной информации может хватить для анализа.

 Наконец, для тех, кто отлаживает веб-приложения, может пригодиться скрипт, который вылавливает SQL-операторы из сервера БД перед тем, как сервер их запустит. Это позволяет выяснить, какие именно операторы исполняются; такая информация поможет, если кажется, что скрипт, работающий с БД, все делает верно, а база данных возвращает неожиданный результат: может оказаться, что либо SQL-выражение формируется неверно, либо соединние происходит не с той базой данных, что надо, либо какой-то параметр передается СУБД без должного оформления (например, без кавычек или с лишними кавычками).

 Вот этот скрипт:

Код [Выделить] Expand

#!/usr/sbin/dtrace -s
#pragma D option quiet
dtrace:::BEGIN
{
 printf("%-20s %-20s %-40s %-9s\n", "Who", "Database", "Query", "Time(ms)");
}
mysql*:::query-start
{
 self->query = copyinstr(arg0);
 self->connid = arg1;
 self->db = copyinstr(arg2);
 self->who = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));
 self->querystart = timestamp;
}
 
mysql*:::query-done
{
 printf("%-20s %-20s %-40s %-9d\n",self->who,self->db,self->query,
 (timestamp - self->querystart) / 1000000);
}

Запустив его, можно наблюдать картину работы сервера (осторожно! там может быть очень много информации, если сервер сильно нагружен запросами!):

Код [Выделить] Expand

$ pfexec ./mysql.d
Who Database Query Time(ms)
root@localhost data SELECT DATABASE() 0
root@localhost test show tables 0
root@localhost test SELECT DATABASE() 0
root@localhost mysql select * from users 0
root@localhost mysql select * from host 0

 C помощью измерения времени между срабатываниями датчиков query-start и query-done вычисляется время исполнения SQL-оператора, и DTrace позволяет строить графики распределения времени исполнения по операторам. Так можно найти те обращения к базе данных, которые отнимают много времени при выполнении конкретных приложений. Большое преимущество DTrace в том, что все эти измерения можно производить в условиях реальной нагрузки на сервер, так как накладные расходы на работу самого DTrace минимальны и не будут мешать работе сервера.

 Замечание: время выполнения запросов меньше 1 ms, а в скрипте выполняется целочисленное деление, поэтому результат получается 0. Можно считать в микросекундах, а не в миллисекундах, тогда будет какое-то небольшое значение.


 Из приведенных примеров видно, что датчики DTrace расставлены в системе и приложениях Solaris повсюду. Изучить, какие аргументы, связанные с датчиками, можно использовать так, как показано выше, можно в документации по системе (man) и в документации по конкретным приложениям (например, по серверу MySQL на сайте mysql.com).

 Значительно больше примеров скриптов для dtrace можно найти в следующих источниках:

 

• каталог /opt/DTT/ (Solaris)
• http://blogs.sun.com...category/DTrace
• http://www.brendangr...e_oneliners.txt

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

experience.openquality.ru