Наблюдение, профилирование и трассировка работы приложений и системы. Концепция DTrace

Почти магия – провайдер pid

Это, пожалуй, самый мощный и самый таинственный провайдер в DTrace. Он позволяет отслеживать входы и выходы из почти всех функций любого приложения, причём без каких-либо дополнительных манипуляций. Датчики для этого провайдера создаются динамически, поэтому, чтобы посмотреть список, одной лишь опцией '-l' вы не обойдётесь. Необходимо будет указать ещё и приложение, которое будет трассироваться, например, таким образом:

#dtrace -P pid'$target' -c dtrace -l

Вывод этой команды даст множество датчиков, которые впоследствии могут быть использованы для написания скриптов. Надо сказать, что этот провайдер полезен в первую очередь для разработчиков приложений, но и для системных администраторов он тоже пригодится, так как даёт возможность увидеть, каким образом происходит взаимодействие приложений со стандартными библиотеками. К примеру, запустив скрипт libfunc.d:

#!/usr/sbin/dtrace -s
pid$target:$1::entry
{
@func[probefunc] = count();
}

командой dtrace -s libfunc.d -c tar libcmd, мы увидим, сколько раз и какие функции вызываются из динамической библиотеки libcmd.so.1 при запуске утилиты tar без аргументов.

Не менее интересный трюк, который можно проделать при помощи этого провайдера – поиск возможных утечек памяти. Допустим, что в Вашем приложении выделение и освобождение памяти происходит только при помощи стандартных вызовов malloc() и free(). Тогда при помощи примерно такого скрипта:

#!/usr/sbin/dtrace -s
pid$target:libc:malloc:entry
{
ustack();
}
pid$target:libc:malloc:return
{
printf("alloc: %x\n", arg1);
@memu[ arg1 ] = count();
}
pid$target:libc:free:entry
{
printf("free: %x\n", arg0);
@memu[ arg0 ] = count();
}
END
{
printa(@par);
}

можно отследить, какие выделенные вызовом malloc() участки памяти не были впоследствии освобождены при помощи вызова free(). Действие ustack() на входе в malloc позволяет увидеть стек вызовов на момент выделения памяти:

malloc: 8069f60
libc.so.1'malloc
libc.so.1'_real_gettext_u+0x82
libc.so.1'gettext+0x5a
tar'0x8052f3e
tar'main+0x44
tar'0x80522d6

Как можно увидеть в этом выводе, у некоторых функций вместо имени указан некоторый адрес памяти. Настало время немного поговорить о медотологии инструментовки этого провайдера. Имена функций, очевидно, берутся из заголовка ELF файлов (точнее, из символических таблиц разделов .symtab и .dynsym ). Следовательно, если после сборки исполняемый файл был почищен утилитой strip, некоторые имена могут навсегда кануть в Лету. Однако, если сборка производилась при помощи последних версий компиляторов Sun Studio, которые создают специальную секцию .SUNW_ldynsym в заголовке ELF файла, то последствия запуска будут не так катастрофичны для наблюдаемости (если интересны дальнейшие подробности – http://blogs.sun.com/ali/entry/what_is_sunw_ldynsym). Далее, для того, чтобы показать имена функций, адреса на стеке отображаются соответствующими символами из заголовка ELF.

Сказанного уже достаточно, чтобы осознать тот факт, что использование этого провайдера довольно накладно с точки зрения дополнительной нагрузки на систему, особенно если мы имеем дело с большим приложением, в котором количество функций измеряется тысячами. Одно лишь динамическое создание датчиков может забрать существенное количество системных ресурсов и привести к дестабильности системы. Для того, чтобы избежать отказа от обслуживания (denial of service), количество датчиков, создаваемых провайдером pid, ограничено.

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

Лирическое отступление №2. О DTrace, DRM и шапке-невидимке

Одним из авторов и ведущих разработчиков DTrace является Адам Левенталь (Adam Leventhal, http://blogs.sun.com/ahl). Во второй половине января он опубликовал заметку о некоторых особенностях реализации DTrace в Mac OS X – "Mac OS X and the missing probes", которая получила очень большое количество откликов, потому что затронула тему, актуальную и для DTrace, и для Open Source сообщества.

Адам уже писал о реализации DTrace на Mac OS X в заметках на своём блоге (к примеру, http://blogs.sun.com/ahl/entry/dtrace_firefox_leopard). Дадим волю воображению и представим, как солнечным калифорнийским утром он наконец-то выкроил время, запустил iTunes, поставил любимую музыку и приступил к более пристальному изучению реализации своего детища на Mac OS X. В процессе экспериментов Адам обратил внимание на некоторые очень странные результаты. Запустив на двухядерном МacBook Pro скрипт следующего содержания:

profile-1000
{
@ = count();
}
tick-1s
{
printa(@);
clear(@);
}

он с удивлением обнаружил, что profile-1000 срабатывает существенно меньшее количество раз вместо ожидаемых 2000 на процессоре с двумя ядрами. В попытке пролить свет на это загадочное явление, он вывел список всех работающих приложений при помощи команды

# dtrace -n profile-997'{ @[execname] = count(); }'

В данных, которые были выведены в результате работы команды, не оказалось ничего подозрительного. За исключением одной небольшой детали: iTunes не оказалось в списке, а в наушниках продолжала играть музыка, как ни в чём не бывало!

Это навело его на мысль, что некоторые приложения каким-то образом могут быть "спрятаны" от ока DTrace. Разобраться можно было, только посмотрев исходный код, и вот какой примечательный отрывок был обнаружен в теле функции dtrace_probe():

#if defined(__APPLE__)
/*
* If the thread on which this probe has fired belongs to a
* process marked P_LNOATTACH then this enabling is not
* permitted to observe it. Move along, nothing to see here.
*/
if (ISSET(current_proc()->p_lflag, P_LNOATTACH)) {
continue;
}
#endif /* __APPLE__ */

То есть процессы, которые помечены флагом P_LNOATTACH, явным образом выводятся из-под наблюдения.

Понятно, что этот код был вставлен для того, чтобы дать возможность тем, кто продаёт музыку или видео, возможность защищать свои права. Беда в другом: способ, которым это было реализовано, слишком сильно затрагивает корневые механизмы средства трассировки. Настолько, что полученные в итоге результаты уже не являются полностью объективным отображением происходящего в системе. Наверное, возможны другие реализации, которые могут и защитить права продавцов, и не повлиять на объективность получаемых результатов. Что поделаешь – дополнительные граничные условия у задач встречаются, увы, довольно часто.

Немного о поиске швейных принадлежностей в больших кучах высушенной травы

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

Понятно, что надо трассировать все события, которые могут представлять интерес, как и понятно то, что надо постараться ограничить вывод только теми данными, которые представляют непосредственный интерес для дальнейшей отладки. DTrace, а точнее его архитектура и выразительные средства языка D, предоставляют несколько механизмов ограничения возможного вывода. Первый из них – это, несомненно, предикаты, о которых мы говорили в начале лекции. Вкупе с thread-local переменными, о которых тоже уже была речь, предикаты предоставляют довольно хороший способ фильтрации вывода.

Но допустим, что мы имеем дело с ситуацией, когда некоторый системный вызов время от времени не срабатывает, выдавая вместо ожидаемого результата код какой-либо из стандартных ошибок ( EIO или EINVAL ). Причём по совершенно непонятной причине, зависящей не то от фаз луны, не то от направления или силы ветра в данный момент. И, скажем для примера, что соотношение корректных отработок вызова к ошибочном находятся в соотношении двести к одному. В подобных случаях имеет смысл рассмотреть с чувством, толком и расстановкой стек вызовов функций между входом и выходом из системного вызова. Это один из классических вариантов анализа, который позволяет выявить условия возникновения ошибки.

Каким образом это можно сделать при помощи DTrace? Для большей наглядности давайте попробуем смоделировать ситуацию поломки физического устройства ввода-вывода. Поскольку под рукой оказался DVD с последним OpenSolaris Express Community Edition, то эксперимент будем проводить на нём. Вставим диск, подождём, пока он подмонтируется, и сымитируем сбой диска следующей последовательностью команд:

#ls /media/SOL_11_X86/* & (sleep 1 && eject -f cdrom)

Если у вас есть внешний диск под управлением ZFS и немного смелости (ZFS более устойчива к сбоям, которые могут возникнуть в процессе брутальных экспериментов, но если смелости в избытке, то можно рискнуть данными на флешке под FAT), можно прибавить реализма, аккуратно выдернув шнур USB в процессе чтения с диска. В первой части статьи приводился пример использования провайдера fbt, который как раз и пригодится для анализа подобной ситуации. Немного модифицируем его. Во-первых, заменим системный вызов ioctl на open в первой версии скрипта; во-вторых, при помощи предиката ограничим вывод только теми событиями, которые связаны с запуском команды ls, а в-третьих, выделим вывод при возникновении ошибки:

#!/usr/bin/dtrace -s
#pragma D option flowindent
syscall::open:entry
/ execname == "ls" /
{
self->follow = 1;
printf( "open (%s)\n ", copyinstr(arg0) );
}
fbt:::
/self->follow/
{ }
syscall::open:return
/self->follow && errno == 0/
{
self->follow = 0;
}
syscall::open:return
/self->follow && errno != 0/
{
self->follow = 0;
printf( "ERROR" )
exit(0);
}

Данная программа на D, скорей всего, выдаст многокилобайтовый отчёт, в котором интересующий нас стек вызовов будет в самом конце. Хорошо, если нам повезёт и та единственная причина, по которой происходит ошибка, будет выявлена сразу. А что делать, если окажется, что причина не одна, и последний стек вызовов будет каждый раз отличаться от предыдущего? И кто знает, может, причины возникновения сбоя имеют регулярный характер по времени или количеству вызовов. Тогда ничего не останется, как убрать действие exit(0) и анализировать ещё более длинный вывод. Неплохой способ, в таких случаях говорят, что grep и less в помощь, а также флаг и палки от барабана.

Если вы запустите этот скрипт на D, то увидите, что выполнение остановится очень быстро и, скорей всего, это произойдет так же быстро, как и на той системе, где проверялись примеры для этой статьи. Дело в том, что команда ls использует динамически подключаемые библиотеки. Следовательно, при запуске команды начинает работу динамический линковщик, который смотрит некий стандартный набор файлов, где могут храниться параметры его конфигурации. Одно из таких мест в файловой системе – это /var/ld/ld.config. Такового может не оказаться в системе, и поэтому в итоге хоть и получаем ошибку при исполнении системного вызова (попытка открыть несуществующий файл), но это вполне штатный случай, который ничего не расскажет о том, что же на самом деле произошло.

Немного отвлекаясь от темы, в качестве упражнения для тех, кто только начинает изучать Solaris и DTrace, хочу предложить такую задачку: попробуйте модифицировать предложенный скрипт так, чтобы он мог трассировать не только системный вызов open, но и остальные системные вызовы тоже. Вывод имён открываемых файлов должен остаться. Получившийся в итоге скрипт позволит вам увидеть, что происходит на уровне системных вызовов при неполадках с устройствами ввода-вывода.

Какие ещё могут быть методы поиска иголки в стоге сена? Можно добавить в компоненту датчика fbt код, который будет сохранять в предопределённых динамических массивах информацию о вызовах и выводить её только в том случае, когда сам системный вызов отработает с ошибкой. Это тоже хороший способ, но и в этом случае и флаг, и палки от барабана лишними не окажутся, потому что, как минимум, не избежать дополнительной работы с форматированием вывода. Да и стоит ли изобретать велосипед, если DTrace обладает штатным механизмом, который называется – спекулятивная трассировка.