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

Краткое введение в язык D

Как уже говорилось ранее, каноническим потребителем, предоставляющим универсальный доступ ко всем средствам, является dtrace(1M). Универсальность достигается благодаря языку D, на котором программируются предикаты и действия. Программа на языке D выглядит как последовательность компонент ( clauses ) вида

дескриптор-датчика, [дескриптор-датчика...]
[ /предикат/ ]
{
действие; [действие; ...]
}

Как можно догадаться, дескриптор-датчика, он же индентификатор датчика, – это та самая четвёрка <провайдер, модуль, функция, имя>. В синтаксисе языка D она в общем виде выглядит следующим образом:

probeprov:probemod:probefunc:probename

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

tick-1s
syscall::read:entry
::exec*:entry

Предикат – это условное выражение. Если он отсутствует в компоненте, то в этом случае считается, что предикат есть и его условие всегда удовлетворено. Действия – это, собственно, то, что будет выполнятся, когда датчик сработал и удовлетворено условие предиката. Кстати, понимая, как порождаются ЕCB блоки, и учитывая, что каждый новый ECB блок становится в хвост списка ECB блоков датчика, мы видим, что последовательность выполняемых компонентами действий определяется порядком их появления в D скрипте и временем, когда происходит модификация кода инструментальными средствами.

Поскольку язык D создавался с оглядкой на С, в нем поддерживаются все встроенные типы языка С, typedef, а также возможность определять типы struct, union и enum. Имеются также собственные встроенные скалярные типы ( string ), ассоциативные массивы и агрегации. Последний тип представляет из собой именованную структуру, хранящую результат некоторой агрегирующей функции, которая индексируется кортежами (n-ками). К примеру, такой скрипт

syscall::write:entry
{
@count[execname]=count();
}

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

bash-3.00# cat aggr.d  dtrace -qs aggr.d
syscall::write:entry
{
@count[execname,uid]=count(); printf( "." );
}
...............................^C
dtrace 1234 5
dtrace 0 7
init 0 8
dtgreet 0 13

Запустив команду, нужно подождать некоторое время, после чего нажать Ctrl-C. Приведенный выше пример также демонстрирует использование действия printf() (оно, кстати, полностью повторяет реализацию функции printf() в языке C) и встроенных переменных execname и uid, определённых в языке D, которые часто встречаются в предикатах и действиях скриптов на D. Также довольно часто применяются и следующие встроенные переменные:

Про последний массив надо сказать, что его элементы определяются провайдером по своему усмотрению. Так, для провайдера syscall на датчике entry в массиве arg[0..n] будут представлены аргументы системного вызова, а на датчике return в массиве arg[0..1] – коды возврата. А вот для провайдера io в arg[0] будет указатель на структуру bufinfo. Значения аргументов для всех провайдеров приведены в спецификации "Dynamic Tracing Guide".

Последнее, что следует сказать про переменные,– это рассказать об их областях видимости. Глобальные переменные декларируются с использованием синтаксиса языка С либо могут быть объявлены неявно при присваивании. В последнем случае такой переменной назначается тип выражения в правой части присваивания. Помимо глобальных переменных, которые видны всем компонентам (clauses) скрипта на D, можно создавать thread-local и clause-local переменные любого типа. Доступ к таким переменным осуществляется при помощи префиксов self-> и this-> соответственно. Префиксы служат как для того, чтобы разделить пространство имён для переменных, так и для того, чтобы без предварительной декларации использовать их в выражениях присваивания. Clause-local переменные содержатся в области памяти, которая используется повторно при исполнении данной компоненты и сродни автоматическим переменным в языке C. Thread-local переменные привязывают каждый индентификатор переменной к отдельным областям памяти для каждого потока команд в операционной системе.

Провайдеры

Mы уже знаем, что модификацию системы инструментальным кодом осуществляют провайдеры, и поскольку они формально отделены от ядра подсистемы трассировки, это значит, что в DTrace возможно использовать неоднородные методологии внедрения кода инструментальных средств. Более того, количество методов со временем увеличивается, поскольку новые методы очень легко встроить в существующую реализацию DTrace. Но хотя провайдеры применяют разные методы внедрения инструментального кода, их объединяет тот факт, что все они не влияют на работу системы, если датчики находятся в выключенном состоянии.

Далее мы рассмотрим методологии, которые используются в некоторых популярных провайдерах. Но сперва упомяну про три датчика, которые предоставляются провайдером dtrace – BEGIN, END и ERROR. Датчик BEGIN всегда срабатывает только один раз в момент запуска скрипта прежде, чем сработает любой другой датчик. Причём до тех пор, пока не отработают все действия компоненты c идентификатором датчика BEGIN, никакой другой датчик сработать не может. Благодаря такому свойству BEGIN обеспечивает предварительную инициализацию переменных, которые могут понадобится другим компонентам программы на D. Датчик END тоже срабатывает только в единственный момент жизненного цикла программы, соответственно, в самом конце и только после того, как отработали все другие датчики. Его удобно использовать для того, чтобы обработать собранные в момент работы программы данные, отформатировать вывод и красиво показать итоговые результаты. Датчик ERROR срабатывает в случае, когда при исполнении скрипта произошла ошибка времени исполнения, скажем, попытка разыменовывания указателя NULL.

Провайдер profile

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

syscall::write:entry
{
@count[execname]=count();
}
tick-7s
{
exit(0);
}

В результате, чтобы посмотреть итоговые данные, нам больше не надо специально жать Ctrl-C, скрипт автоматически закончит работу через 7 секунд, когда сработает датчик tick-7s и сработает действие exit() с целочисленным аргументом, что вызовет срабатывание датчика END и приведёт к нормальному завершению работы. В качестве более серьёзного примера использования этого провайдера, стоит посмотреть на D-Light. Этот инструмент входит в пакет Sun Studio Express (см. меню Tools) – экпресс-релизе интегрированной среды разработки Sun Studio (google вам в помощь, чтобы скачать и посмотретьЕсли вы предпочитаете yandex.ru, который не индексирует англоязычные тексты на sun.com, просто зайдите на страницу http://developers.sun.com/sunstudio/downloads/express/index.jsp ). Там этот провайдер используется для сбора различной сэмплинговой информации на всём жизненном цикле приложения.

Провайдер syscall

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

Примером для данного провайдера будет почти детективная история, которую можно найти на блогах Sun. Дело было так: в один прекрасный день, на одном сервере, который предоставлял терминальный доступ, пользователи после ввода пары логин-пароль вместо привычного приглашения оболочки к вводу команды имели неудовольствие лицезреть, как по терминальному окну бежала последовательность строк, состоящих из "непечатных" символов. Довольно быстро выяснилось, что это безобразие происходит из-за того, что некий шутник сделал /etc/motd символической ссылкой на один из служебных файлов. После удаления этой ссылки система некоторое время работала нормально, однако с упорством, достойным лучшего применения, через какое-то время /etc/motd вновь ссылался на тот же самый файл. В системе явно работал некий злоумышленник, которого нужно было обезвредить.

Вооружившись DTrace, детектив принялся за работу. Во-первых, было очевидно, что ключ к разгадке даст трассировка системного вызова symlink(), который создаёт ссылки. Следовательно, при помощи провайдера syscall можно отловить момент вызова, а предикатом ограничить область срабатывания датчика таким образом, чтобы запуск действий происходил только при манипуляции с файлом /etc/motd. Далее остаётся вывести pid – и дело сделано. Сие было реализовано таким образом:

#!/usr/sbin/dtrace -qs
syscall::symlink:entry
/basename(copyinstr(arg1))=="motd" /
{
printf("Execname: %s, pid=%d\n", execname, pid);
}

Детектив оставил скрипт сидеть в засаде и стал ждать результатов наблюдений. Через некоторое время датчик сработал, но запуск из консоли команды ptree с выловленным pid'ом в качестве аргумента ничего не дал – такого идентификатора процесса в системе уже не было. Злодей успел сделать своё грязное дело и смылся. Поэтому следующая версия ловушки выглядела более хитроумно:

!#/usr/sbin/dtrace -wqs
syscall::symlink:entry
/basename(copyinstr(arg1))=="motd" /
{
printf("Execname: %s, pid=%d\n", execname, pid);
copyoutstr("/tmp/motd",arg1,9);
stop();
system("ptree %d",pid);
system("prun %d",pid);
system("rm /tmp/motd");
}

Что поменялось? Во-первых, исполнение процесса, на котором сработал датчик, приостанавливалось действием stop(). Во-вторых, аргумент вызова symlink подменялся на /tmp/motd вместо /etc/motd. Ну и, наконец, действием system() запускалась команда ptree на полученом pid, затем prun возобновлял прежде приостановленное выполнение процесса, и напоследок удалялась ссылка /tmp/motd. Можно было бы обойтись чуть меньшим количеством действий, но не лишенный чувства юмора детектив решил не уничтожать процесс, а позволил ему выполняться дальше, не причиняя вреда системе.

Провайдер fbt (function boundary tracing)

Провайдер трассировки границ функции ( fbt ) создаёт датчики для момента входа-в и выхода-из всех функций ядра Solaris. Хотя механизм реализации fbt сильно привязан к конкретной архитектуре набора команд, fbt присутствует и на SPARC, и на x86, и на amd64. Фактически, мы уже успели посмотреть и понять, каким образом fbt модифицирует код на архитектуре x86 в примере, где применялся mdb для дизассемблирования функции ufs_lookup(). Приведённый в том примере трюк с #lock используется по историческим соображениям, на платформе amd64 реализован более элегантый способ – при помощи вызова программного прерывания. На SPARC это реализовано ещё элегантней – при помощи команды перехода ba,a +offset, и если вы обладаете знанием ассемблера SPARC, то можете проделать абсолютно аналогичное упражнение при помощи mdb и даже продвинуться немного дальше. Если мы дизассемблируем в mdb код по адресу ufs_lookup+offset, где offset – операнд команды перехода, то увидим, как именно происходит передача управления к DTrace.

Провайдер fbt позволяет заглянуть глубже и наблюдать за тем, что происходит непосредственно в ядре. Скрипт, приведённый в качестве примера использования провайдера, показывает, какую последовательность вызовов функций ядра генерирует системный вызов ioctl:

#!/usr/bin/dtrace -s
#pragma D option flowindent
syscall::ioctl:entry
{
self->follow = 1;
}
fbt:::
/self->follow/
{ }
syscall::ioctl:return
/self->follow/
{
self->follow = 0;
exit(0);
}

Этот пример также иллюстрирует применение thread-local переменной. Здесь она используется для того, чтобы ограничить вывод только теми вызовами, которые происходят в том же потоке команд, что и сам системный вызов. Прагма flowindent служит более наглядному представлению результата. Некоторые вышеизложенные детали позволяют понять, почему срабатывание датчика не заставит себя долго ждать и на каком исполняемом файле это произойдёт с очень большой вероятностью.

Лирическое отступление №1. О преимуществах DTrace

Появившись всего несколько лет назад в Solaris, ныне DTrace "перебрался" и на другие Unix системы. Более года назад был сделан порт для FreeBSD, чуть позже – для MacOS X и совсем недавно – для QNX. Таким образом, DTrace претендует на то, чтобы стать стандартным средством трассировки для Unix.

Почему же DTrace оказался настолько привлекательным? Во-первых, подавляющее большинство аналогичных инструментов используют статический код, который, будучи "вживлен" в ключевые места кода системы, позволяет отслеживать ограниченное число событий при минимальном действии на систему. Такой подход (реализованный, к примеру, в KLogger для Linux) позволяет даже довольно точно оценивать накладные расходы, возникающие при использовании данного инструмента, но ограничивает множество системных объектов, доступных для наблюдения. DTrace позволяет существенно расширить "область видимости", применяя как статические, так и динамические методы инструментовки кода

Во-вторых, DTrace позволяет получить информацию, пожалуй, о всех составляющих системы. Скажем, утилита truss(1), как и DTrace, тоже позволяет трассировать системные вызовы и сигналы, но ничего более. Для того, чтобы посмотреть статистику использования виртуальной памяти или ядра, потребуются утилиты vmstat(1M) или kstat(1M) соответственно. DTrace же собирает все эти утилиты "под одну крышу", попутно решая ещё одну проблему. Если ранее при анализе необходимо было коррелировать вывод статистических утилит чуть ли не "вручную", то теперь это можно запрограммировать в скрипте на D.

Конечно, этими двумя пунктами список не ограничивается. Но раз уж речь зашла о truss(1), стоит упомянуть и о том, что для сбора информации эта утилита пользуется файловой системой proc(4), которая разрабатывалась для традиционных средств отладкиК коим в первую очередь относятся отладчики – например, gdb или же dbx из пакета компиляторов и средств разработки Sun Studio.. Поэтому зачастую для сбора информации исследуемый процесс останавливается, далее снимается требуемая информация о состоянии и процесс запускается заново. Если ваш сервер обслуживает биржевые операции, то я бы не советовал использовать такой метод трассировки во время торгов. Что же предлагает DTrace? Чтобы разобраться, давайте поговорим еще немного про провайдер syscall.

Секрет фокуса syscall

В начале лекции мы говорили про методологию инструментирования (модификации кода системы инструментальными средствами), которая используется в провайдере fbt. Чтобы продемонстрировать тот факт, что методология может быть различной и каждый провайдер DTrace вправе использовать свою технику для инструментирования, посмотрим, что происходит в случае использования провайдера syscall. Для этого нам опять понадобится помощь уже знакомого модульного отладчика mdb.

Метод, которым пользуется провайдер syscall, чтобы отслеживать входы в и выходы из системных вызовов – модификация таблицы системных вызовов. При помощи mdb можно "подсмотреть" за тем, как это происходит. Структура элементов таблицы системных вызовов (struct sysent, ссылка на строчку кода может "поехать" со временем) определена в http://src.opensolaris.org/source/xref/onnv/onnv-gate/usr/src/uts/common/sys/systm.h#305

Все примеры в этой лекции проверялись в Solaris 10 update 4, так что и в любой свежей версии Solaris Express они тоже сработают.

mdb -k
Loading modules: [ unix genunix specfs dtrace cpu.AuthenticAMD.15
uppc pcplusmp scsi_vhci zfs random ip hook neti sctp arp usba
s1394 qlc fctl md lofs audiosup sppp ipc ptm crypto nfs cpc fcp
fcip logindmux ufs sv nsctl sdbc ii rdc mpt ]
> ::sizeof struct sysent
sizeof (struct sysent) = 0x20
> sysent+7*0x20::array struct sysent 1 |::print struct sysent
{
sy_narg = '\0'
sy_flags = 0x1
sy_call = 0
sy_lock = 0
sy_callc = wait
}

Включаем датчик на wait (в другом терминале #dtrace -n 'syscall::wait:entry' ) и еще раз смотрим запись в таблице вызовов для wait:

> sysent+7*0x20::array struct sysent 1 |::print struct sysent
{
sy_narg = '\0'
sy_flags = 0x1
sy_call = 0
sy_lock = 0
sy_callc = dtrace_systrace_syscall
}

Замена вызова системного вызова на dtrace_systrace_syscall позволяет передать управление DTrace, который снимет необходимую для трассировки информацию до и после системного вызова, передав управление "настоящему" wait, в соответствующий момент.

Провайдер proc

Этот провайдер предназначен для трассировки системных событий, отображающих процесс исполнения кода (запуск и завершение, отправка и обработка сигналов). Казалось бы, это можно сделать при помощи провайдера syscall и соответствующих датчиков ( exec, fork и т.п.). Почему же понадобился proc? Дело в том, что управление процессами и сигналами осуществляется не только системными вызовами, а еще и функциями из стандартной библиотеки С (особенно это касается сигналов и легковесных процессов – LWP), поэтому только лишь трассировкой системных вызовов не обойтись. Да и "специализация" провайдера делает его использование более удобным при написании скриптов. К примеру, датчику create в качестве аргумента передаётся ссылка на структуру psinfo_t, которая содержит, пожалуй, всю информацию о создаваемом процессе c точки зрения операционной системы.

Провайдер содержит небольшое количество датчиков (список датчиков можно посмотреть с помощью команды dtrace -l -P proc ), из названий очевидно следует их предназначение. В качестве примера посмотрим, каким образом можно отследить цепочку запуска процессов при вызове определённой команды :

#pragma D option quiet
proc:::exec
{
self->parent = execname;
}
proc:::exec-success
/self->parent != NULL/
{
@gs[self->parent, execname] = count();
self->parent = NULL;
}
proc:::exec-failure
/self->parent != NULL/
{
@gf[self->parent, execname] = count();
self->parent = NULL;
}
END
{
printa(" %s -> %s (%@d)\n", @gs );
}

Пусть скрипт хранится в файле exec-chain.d, а в качестве подопытного возьмём команду su:

joda#dtrace -s exec-chain.d -c 'su – obi-wan'
obi-wan#exit
bash -> clear (1)
bash -> cat (1)
bash -> quota (1)
bash -> mail (1)
bash -> sed (1)
clear -> tput (1)
su -> bash (1)
bash -> stty (2)
bash -> expr (20)
joda#

Как нетрудно заметить, порядок вывода не соответствует хронологическому порядку, поскольку DTrace гарантирует регистрацию события, а порядок вывода на печать – нет, оставляя эту задачу автору. Если важно соблюсти временную последовательность, то можно воспользоваться одной из встроенных переменных для учёта времени timestamp, vtimestamp или walltimestamp. Для относительного учёта вполне подойдёт переменная timestamp, стандартный шаблон её использования: инициализация thread-local переменной в датчике

BEGIN {
self->start = timestamp;
}

и регистрация времени события относительно начального момента при помощи конструкции

timestamp-self->start

после чего нужно отсортировать список событий по времени. Допустим, exec-chain.d можно изменить, добавив в кортеж агрегации @gs последнюю приведённую конструкцию, затем добавить вывод отметки времени и передать вывод утилите sort.

Этот, прямо скажем, довольно простой пример демонстрирует очень мощный принцип: вывод скрипта может быть данными, предназначенными для последующей обработки другими утилитами. Более того, вывод скрипта на D может представлять из себя код программы на некотором языке (примеры, где скрипт на D выводит скрипт на perl, можно легко найти в Интернет). Если в примере exec-chain.d (без модификаций с timestamp ) заменить тело компоненты END на

END
{
printf( "digraph ExecGraph {\n" );
printa(" \"%s\" -> \"%s\" [weight=%@d];\n", @gs );
printa(" \"%s\" -> \"%s\" [color=red,weight=%@d];\n",@gf );
printf("}\n");

то после отработки скрипта получим описание графа на языке dot, который используется в пакете визуализации графов Graphviz (http://www.graphviz.org/About.phр). Сохранив вывод в файле graph.dot, сгенерируем дерево вызовов:

#dot -Tjpg graph.dot -o graph.jpg

Это даёт нам очень наглядную картинку запускаемых командой su процессов. Красными дугами в полученном графе будут обозначаться неудавшиеся запуски. Уверен, что, скорей всего, команда su у вас работает нормально и красных дуг на картинке не будет. Мне пришлось специально моделировать ситуацию для того, чтобы получить такой граф.

Трассировку запусков можно ещё получить совсем простой командой в одну строчку (пример взят с http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_One_Liner, где вы найдете массу полезных примеров в одну строку для различных провайдеров):

#dtrace -n 'proc:::exec-success { trace(curpsinfo->pr_psargs); }'

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

Почти магия – провайдер 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 обладает штатным механизмом, который называется – спекулятивная трассировка.

Спекулятивная трассировка

Я хочу лишний раз подчеркнуть, что оба рассмотренных метода: обработка вывода dtrace другими утилитами (например, graphviz ) и буферизация данных при помощи переменных, – не являются ущербными. И в некоторых случаях могут оказаться необходимым подспорьем. Некоторая ирония в рассказе о них вызвана тем, что, в DTrace предусмотрена возможность "припрятать" трассировочные данные до поры, до времени, чтобы позже принять решение: стоит ли отдать собранные данные в буфер трассировки или же просто выбросить. Собственно, второй из ранее рассмотренных методов, как раз и является неким доморощенным вариантом такого буфера. Однако, используя спекулятивную трассировку, получить интересующий вывод без последующей обработки и с минимальными затратами будет значительно проще.

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

speculation

Теперь опишу процесс более подробно. Функция speculation() выделяет спекулятивный буфер и возвращает его идентификатор, который должен использоваться в последующих вызовах функции speculate(). Спекулятивные буферы являются конечным ресурсом, и если при очередном вызове speculation() не окажется доступного буфера, то функция вернёт нулевой идентификатор, DTrace увеличит счёт ошибок и известит пользователя об этом факте примерно таким сообщением:

#dtrace: 2 failed speculations (no speculative buffer space available)

Нулевой идентификатор, хоть и является всегда недопустимым, может быть передан в качестве параметра функциям speculate(), commit() или discard(). Количество спекулятивных буферов по умолчанию равно единице, но может быть увеличено. Для этого надо увеличить значение параметра nspec, установив его значение в требуемое количество буферов. Это можно сделать прямо в скрипте при помощи прагмы:

#pragma D option nspec=3

speculate

Для использования спекулятивного буфера идентификатор, возвращенный вызовом функции speculation(), обязан быть передан в качестве аргумента функции speculate() до того момента, как в компоненте будут выполняться какие-либо действия, связанные с записью данных. Все последующие действия подобного характера в компоненте, содержащей вызов speculate(), будут трассироваться спекулятивно. Если же вызову speculate() в коде компоненты будут предшествовать какие-либо действия записи данных, то компилятор с языка D выдаст ошибку времени компиляции. Таким образом, компоненты могут быть предназначены либо для спекулятивной, либо для не-спекулятивной трассировки, но не для обоих видов трассировки одновременно.

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

commit

Разобрались, как происходит сбор данных; теперь о том, что с ними можно сделать в дальнейшем. Собственно, варианта всего два: либо эти данные попадут в вывод, либо будут отброшены. Для первого варианта используется функция commit(), которая копирует данные из спекулятивного буфера в главный. Если случилось так, что в спекулятивном буфере данных больше, чем места в главном буфере, то никакие данные не копируются, а соответствующий счётчик ошибок увеличивается на единицу. (В первой части статьи рассказывалось о том, что на системах с несколькими CPU для каждого из них выделяется отдельный буфер для хранения данных, полученных при трассировке, – то же самое относится и к спекулятивным буферам.) В случае, когда при спекулятивной трассировке были использованы буферы, принадлежащие нескольким CPU, незамедлительно копируются только спекулятивные данные из буфера того CPU, на котором была вызвана функция commit(), а информация из буферов других CPU – только по прошествии некоторого времени. Таким образом, данные из буфера одного из CPU и остальных будут разнесены по времени при переносе в главный, однако это время гарантированно не больше, чем значение параметра настройки DTrace, который называется cleanrate (по умолчанию cleanrate=101 ). При необходимости его можно изменить, увеличив частоту с которой происходит очистка буферов CPU. Как и в случае с nspec, это можно сделать или при помощи прагмы, или из командной строки:

ostap#dtrace -x cleanrate=303 -s speculation.d

Стоит рассказать про один подводный камень, на который можно натолкнуться при использовании спекулятивной трассировки на системе с несколькими CPU. До тех пор, пока на каждом CPU не будут переписаны данные в главный буфер из спекулятивного, последний будет недоступен для использования функциями commit(), discard() и speculate(). В этом случае вызовы этих функций тихо "завалятся". Последнее, что стоит сказать про commit() – это то, что компонента в которой присутствует вызов этой функции не может содержать действия, записывающие данные. Для того, чтобы обеспечить слияние нескольких спекулятивных буферов в одной компоненте, может быть несколько вызовов commit().

discard

Осталась последняя функция – discard(), которая предназначена для чистки спекулятивного буфера, если информация, находящаяся в данном буфере, не представляет интереса. Поскольку можно сказать, что функционально commit() – это чистка спекулятивных буферов плюс что-то еще (копирование данных), то всё, что относилось к "первому слагаемому" commit(), также справедливо и для discard(). И если, к примеру, все спекулятивные буферы заняты и discard() не успеет отработать до очередного вызова функции speculation(), то DTrace выдаст сообщение об ошибке наподобие такого:

#dtrace: 1 failed speculation (available buffer(s) still busy)

Изменяя значение параметра cleanrate, можно избавиться от этого сообщения или же сделать так, чтобы оно появлялось реже. Стоит заметить, что изменение параметров cleanrate и nspec увеличивает количество ресурсов для DTrace как приложения, увеличивая нагрузку на систему. Теперь можно вернуться к ранее приведенному скрипту и переписать его с использованием спекулятивной трассировки.

#!/usr/bin/dtrace -s
#pragma D option flowindent
syscall::open:entry
/ execname == "ls" /
{
self->spec = speculation();
printf( "open (%s)\n ", copyinstr(arg0) );
}
fbt:::
/self->spec/
{
speculate(self->spec);
}
syscall::open:return
/self->spec/
{
speculate( self->spec );
trace( errno );
}
syscall::open:return
/self->spec  errno == 0/
{
discard( self->spec );
self->spec= 0;
}
syscall::open:return
/self->spec  errno != 0/
{
commit( self->spec );
self->spec = 0;
}

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