OpenQuality.ru

Филипп Торчинский, признанный эксперт в администрировании 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 обладает рядом уникальных свойств:

Основным компонентом 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 (вначале на экран будет выдан результат ее работы, а потом – список функций с количеством вызовов для каждой в порядке возрастания):

pfexec dtrace -n 'pid$target:::entry {@funсtions[probefunc]=count();}' -c ls

А вот таким скриптом можно посчитать количество функций, вызванных конкретным процессом с PID=2355; для получения результата надо прервать выполнение скрипта с помощью Ctrl-C:

pfexec dtrace -n 'pid2355:::entry {@funсtions[probefunc]=count();}'

А вот так можно посчитать количество системных вызовов в том же процессе:

pfexec dtrace -n 'syscall:::entry /pid==2355/ {@funсtions[probefunc]=count();}'

Итак, в скриптах на языке D всегда используется следующий синтаксис:

провайдер:модуль:функция:датчик
/условие/
{
действия
}

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

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

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

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

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

 /execname == top/

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

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

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

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

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

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 в домашнем каталоге:

rm /export/home/filip/.printers

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

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

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

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

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

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

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

#!/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);
}

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

$ 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 можно найти в следующих источниках:

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