SystemTap был разработан прежде всего для упрощения отладки и трассировки ядерных функций Linux (kernel space). Однако, с появлением в ядре механизма uprobes (в мэйнстриме ядра он присутствует начиная с версии 3.5, а в системах, связанных с Red Hat, таких как Fedora, CentOS и RHEL, он уже существует на протяжении нескольких лет), SystemTap можно использовать и для трассировки в пространстве пользователя (user space). На этой странице можно найти огромное количество примеров скриптов для SystemTap, которые дают представление о мощи этого инструмента. Я взял за основу один из них (уже не помню какой) и значительно переделал, чтобы показать, как работает SystemTap в пространстве пользователя.
Мы не станем запускать SystemTap от имени суперпользователя, а для этого нам придется кое-что подготовить. Во-первых, необходимо установить пакет с серверной частью SystemTap. В моей системе Fedora 20 это делается так:
yum install systemtap-server
Затем нужно добавить вашу учетную запись в группу stapusr и запустить сервер.
usermod -a -G stapusr your-username
service stap-server start
Зачем такие сложности. Дело в том, что SystemTap при запуске нового скрипта строит и устанавливает в ядро Linux новый временный модуль, который задействует механизм uprobes для установки в интересующие нас точки программы интересующих нас обработчиков событий. По завершении работы SystemTap удаляет временный модуль из ядра. Очевидно, что для этого нужны привилегии суперпользователя, которыми обладает stap-server.
Итак, перейдем к примеру. Возьмем простое приложение, написанное на C++ (файл test.cc).
#include <iostream>
#include <unistd.h>
namespace
{
void print( const char * lbl )
{
std::cout << lbl << std::endl;
}
}
class A
{
public:
virtual void print( void ) const
{
::print( "A" );
}
};
class B : public A
{
public:
void print( void ) const
{
::print( "B" );
}
};
namespace
{
void cycle( const A * a, const A * b, int i )
{
if ( i % 3 )
a->print();
else
b->print();
sleep( i / 2 );
}
}
int main( void )
{
A * a( new A );
A * b( new B );
for ( int i( 0 ); i < 10; ++i )
cycle( a, b, i );
delete a;
delete b;
return 0;
}
Имеются два класса: A и его наследник B. В классе A определена виртуальная фукция print(), которая с помощью свободной функции print(), объявленной в анонимном пространстве имен, выводит на экран строку A. В классе B виртуальная функция print() переопределена: она выводит на экран строку B с помощью той же свободной функции print(). В функции main() создаются два полиморфных объекта a и b типов A и B соответственно. Затем в цикле от 1 до 10 эти объекты передаются в свободную функцию cycle(), которая вызывает виртуальный метод print() попеременно для a и b в зависимости от номера цикла, причем общее число вызовов a->print() будет превышать число вызовов b->print() в два раза. Кроме этого, функция cycle() умеет зависать, причем чем больше номер цикла, тем дольше длительность зависания.
Все эти сложности я ввел с той целью, чтобы показать, как будет работать типичный сценарий SystemTap. Итак, давайте посмотрим, сколько раз будет вызвана виртуальная функция A::print(), сколько времени займут эти вызовы (мы соберем статистику и даже выведем гистограмму!), а также будем фиксировать зависания функции cycle() выше заданного порога.
Для написания скрипта нам понадобятся имена функций, которые в C++ обычно не соответствуют именам, объявленным в исходном коде. Чтобы выяснить их значения, можно просто скомпилировать программу test.
g++ -o test test.cc
Заметьте, что мы скомпилировали программу без отладочной информации — SystemTap она не нужна!
Теперь, с помощью SystemTap, можно вывести значения имен функций.
stap -l 'process("./test").function("*")' -c ./test
process("/home/lyokha/tmp/stap-example/test").function("_GLOBAL__sub_I_main")
process("/home/lyokha/tmp/stap-example/test").function("_Z41__static_initialization_and_destruction_0ii")
process("/home/lyokha/tmp/stap-example/test").function("_ZN12_GLOBAL__N_15cycleEPK1AS2_i")
process("/home/lyokha/tmp/stap-example/test").function("_ZN12_GLOBAL__N_15printEPKc")
process("/home/lyokha/tmp/stap-example/test").function("_ZN1AC2Ev")
process("/home/lyokha/tmp/stap-example/test").function("_ZN1BC1Ev")
process("/home/lyokha/tmp/stap-example/test").function("_ZNK1A5printEv")
process("/home/lyokha/tmp/stap-example/test").function("_ZNK1B5printEv")
process("/home/lyokha/tmp/stap-example/test").function("_ZNSt8ios_base4InitD1Ev@@GLIBCXX_3.4")
process("/home/lyokha/tmp/stap-example/test").function("_ZSt4endlIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_@@GLIBCXX_3.4")
process("/home/lyokha/tmp/stap-example/test").function("_ZdlPv@@GLIBCXX_3.4")
process("/home/lyokha/tmp/stap-example/test").function("__do_global_dtors_aux")
process("/home/lyokha/tmp/stap-example/test").function("__libc_csu_fini")
process("/home/lyokha/tmp/stap-example/test").function("__libc_csu_init")
process("/home/lyokha/tmp/stap-example/test").function("_fini")
process("/home/lyokha/tmp/stap-example/test").function("_init")
process("/home/lyokha/tmp/stap-example/test").function("_start")
process("/home/lyokha/tmp/stap-example/test").function("deregister_tm_clones")
process("/home/lyokha/tmp/stap-example/test").function("frame_dummy")
process("/home/lyokha/tmp/stap-example/test").function("main")
process("/home/lyokha/tmp/stap-example/test").function("register_tm_clones")
Отлично, функции _ZNK1A5printEv и _ZNK1B5printEv — это и есть наши A::print() и B::print(), а функция _ZN12_GLOBAL__N_15cycleEPK1AS2_i — это свободная функция cycle() из анонимного пространства имен.
Вот исходный код скрипта (файл test.stp, объяснения ниже).
#!/usr/bin/env stap
global startA, startCycle, intervals, hdr = "<---> "
probe process(@1).function("_ZNK1A5printEv")
{
startA[tid()] = gettimeofday_us()
}
probe process(@1).function("_ZNK1A5printEv").return
{
t = gettimeofday_us()
old_t = startA[tid()]
if (old_t) intervals <<< t - old_t
delete startA[tid()]
}
probe process(@1).function("_ZN12_GLOBAL__N_15cycleEPK1AS2_i")
{
startCycle[tid()] = gettimeofday_us()
}
probe process(@1).function("_ZN12_GLOBAL__N_15cycleEPK1AS2_i").return
{
delete startCycle[tid()]
}
function dump_intervals(print_hist)
{
if (@count(intervals))
{
printf("%s Intervals min:%dus avg:%dus max:%dus count:%d\n", hdr,
@min(intervals), @avg(intervals), @max(intervals),
@count(intervals))
if (print_hist)
{
print(@hist_log(intervals))
}
}
}
probe timer.s(2)
{
foreach (tid in startCycle)
{
old_t = startCycle[tid]
if (old_t > 0)
{
t = gettimeofday_us()
if (t - old_t > $2 * 1000000)
{
printf("%s Pending call detected: %dus (tid %d)\n", hdr, t - old_t, tid)
}
}
}
dump_intervals(0)
}
probe end
{
println()
dump_intervals(1)
}
Первая строка — shebang — понятно. Далее идет объявление четырех глобальных переменных: startA, startCycle, intervals и hdr, которые будут доступны из всех объявлений probe и function в скрипте. Переменная startA — это массив, параметризованный значениями идентификаторов программного потока, возвращаемыми встроенной функцией tid(). Мы будем использовать startA как временну́ю метку входа в функцию A::print() в соответствующем программном потоке. На самом деле, в программе всего лишь один поток, а параметризация переменных-массивов startA и startCycle по идентификаторам потоков сделана просто для обобщения подхода. Переменная startCycle — тоже временна́я метка входа в функцию cycle(). Кстати, как SystemTap определяет, что переменные startA и startCycle являются массивами? Ведь в их объявлении это никак не указано. Дело в том, что парсер SystemTap способен выводить (infer) тип переменной при ее первом использовании.
В переменной intervals мы будем собирать временну́ю статистику пребывания внутри функции A::print(). Переменная hdr — простой префикс для строк, выводимых SystemTap, она инициализируется в месте объявления.
Итак, первое объявление probe process(@1).function("_ZNK1A5printEv") читается так: для имени процесса, переданного SystemTap в первом аргументе командной строки, при входе в функцию _ZNK1A5printEv, выполнить тело данного probe, которое находится ниже, внутри фигурных скобок. Мы уже применяли подобные объявления, когда выводили список функций в программе test. Тогда это было process("./test").function("*"), то есть мы использовали имя процесса ./test. Поскольку опция -l не требовала использования сервера SystemTap, мы просто указали в имени процесса текущую директорию. Однако, когда мы запустим наш скрипт, сервер должен будет знать полный путь к программе test, поэтому мы передадим его через аргумент командной строки @1 (в SystemTap есть переменные вида $N, где N — некоторое число, которое, в отличие от bash, может превышать 9 — они подставляют N-ый аргумент командной строки как есть, и @1 — они оборачивают N-ый аргумент командной строки в двойные кавычки).
Внутри probe process(@1).function("_ZNK1A5printEv") мы присваиваем элементу массива startA[tid()] значение gettimeofday_us(), которое соответствует числу микросекунд, прошедших с начала Эпохи UNIX.
В свою очередь, probe process(@1).function("_ZNK1A5printEv").return устанавливает обработчик на выходе из A::print(). В нем, при помощи оператора <<<, в массив intervals добавляется новый элемент, равный разности между текущим значением gettimeofday_us() и значением startA[tid()]. Оператор <<< можно рассматривать как аналог оператора вывода в поток << из C++. На выходе из обработчика элемент startA[tid()] удаляется.
Следующие два probe соответствуют входу и выходу в/из cycle(): они, соответственно, устанавливают и удаляют элемент массива startCycle[tid()]. В probe timer.s(2) каждые 2 секунды осуществляется проход по элементам startCycle и в случае, если разность между текущим значением gettimeofday_us() и значением данного элемента превышает значение в секундах, заданное во втором аргументе командной строки ($2), на экран выводится предупреждающее сообщение, в котором указано время пребывания внутри функции cycle() (собственно, эта разность) и идентификатор потока. В конце данного обработчика вызывается function dump_intervals(print_hist), которая выводит статистику, накопленную в intervals, на экран. В случае, когда аргумент print_hist не нулевой, на экран выводится гистограмма распределения событий из intervals. Мы не собираемся выводить гистограмму каждые две секунды, мы ее выведем в завершающем обработчике probe end.
Итак, запускаем программу test под SystemTap.
stap test.stp -c ./test `pwd`/test 3
B
A
A
B
<---> Intervals min:6us avg:7us max:8us count:2
A
<---> Intervals min:6us avg:14us max:28us count:3
A
<---> Intervals min:6us avg:17us max:28us count:4
B
<---> Intervals min:6us avg:17us max:28us count:4
A
<---> Intervals min:6us avg:21us max:37us count:5
<---> Intervals min:6us avg:21us max:37us count:5
A
<---> Intervals min:6us avg:21us max:37us count:6
<---> Pending call detected: 3977735us (tid 4949)
<---> Intervals min:6us avg:21us max:37us count:6
B
<---> Intervals min:6us avg:21us max:37us count:6
<---> Pending call detected: 3977592us (tid 4949)
<---> Intervals min:6us avg:21us max:37us count:6
<---> Intervals min:6us avg:21us max:37us count:6
value |-------------------------------------------------- count
1 | 0
2 | 0
4 |@ 1
8 |@ 1
16 |@@@ 3
32 |@ 1
64 | 0
128 | 0
Опция -c ./test говорит о том, что SystemTap должен запустить отдельный процесс и выполнить в нем программу test. (SystemTap также поддерживает опцию -x PID, которая позволяет прикрепиться к уже существующему процессу: такой механизм лучше подходит для трассировки в продакшн системе, но я не буду на этом останавливаться.) Первый свободный аргумент командной строки — `pwd`/test — это полный путь к исполняемому файлу test, второй свободный аргумент — таймаут пребывания внутри тела функции cycle(). Вывод программы не принес неожиданностей: функция A::print() вызывалась 6 раз, B::print() — 4 раза, это видно из вывода собственно программы test. SystemTap выводил статистику по intervals каждые 2 секунды, в завершении была выведена соответствующая гистограмма распределения времен пребывания внутри функции A::print() в микросекундах. Кроме того, обработка функции cycle() два раза превышала установленный предел в 3 секунды и SystemTap вывел соответствующие сообщения.
Давайте усложним задачу. Теперь нас дополнительно будет интересовать количество вызовов свободной функции print() из A::print() (их должно оказаться 6), а также значение переменной i на входе в функцию cycle(). Первая задача подразумевает использование механизма process().function().callee() (эта запись условна, так как формально во всех круглых скобках нужно указывать какие-либо строковые значения). Механизм callee требует, чтобы программа test содержала символы DWARF, то есть была скомпилирована с опцией -g. Да и вторая задача тоже требует DWARF.
Вот какие изменения нужно внести в test.stp.
...
global startA, startCycle, intervals, printcalls = 0, hdr = "<---> "
...
probe process(@1).function("_ZN12_GLOBAL__N_15cycleEPK1AS2_i")
{
startCycle[tid()] = gettimeofday_us()
if (@defined($i))
{
printf("%s Stack variable i = %d\n", hdr, $i)
}
}
...
probe process(@1).function("_ZNK1A5printEv").callee("*print*") ?
{
printcalls += 1
}
...
probe end
{
println()
dump_intervals(1)
printf("%s Function print() was called from A %d times\n", hdr, printcalls)
}
Добавлена новая глобальная переменная printcalls, которая будет увеличиваться на единицу при вызове функции print() из A::print(): за это будет отвечать новый обработчик process(@1).function("_ZNK1A5printEv").callee("*print*") ?. Вопросительный знак в конце имени обработчика говорит о том, что он опционален: мы хотим использовать новый скрипт в том числе и когда программа test не будет содержать отладочной информации. Я не стал записывать полное имя функции в значение аргумента callee, а ограничился глоб-паттерном: они прекрасно работают в скриптах SystemTap. В обработчик входа в функцию cycle() добавлен вывод значения стековой переменной i, а в probe end — вывод значения printcalls.
Компилируем с опцией -g и запускаем SystemTap.
g++ -g -o test test.cc
stap test.stp -c ./test `pwd`/test 3
B
A
A
B
<---> Intervals min:8us avg:9us max:10us count:2
A
<---> Intervals min:8us avg:14us max:25us count:3
A
<---> Intervals min:8us avg:17us max:26us count:4
B
<---> Intervals min:8us avg:17us max:26us count:4
A
<---> Intervals min:8us avg:20us max:32us count:5
<---> Intervals min:8us avg:20us max:32us count:5
A
<---> Intervals min:8us avg:21us max:32us count:6
<---> Pending call detected: 3977681us (tid 1682)
<---> Intervals min:8us avg:21us max:32us count:6
B
<---> Intervals min:8us avg:21us max:32us count:6
<---> Pending call detected: 3977528us (tid 1682)
<---> Intervals min:8us avg:21us max:32us count:6
<---> Intervals min:8us avg:21us max:32us count:6
value |-------------------------------------------------- count
2 | 0
4 | 0
8 |@@ 2
16 |@@@ 3
32 |@ 1
64 | 0
128 | 0
<---> Function print() was called from A 0 times
Сообщения о переменной i не выводятся, printcalls не увеличивается. Что-то не так. Посмотрим как теперь называются наши функции.
stap -l 'process("./test").function("*")' -c ./test
process("/home/lyokha/tmp/stap-example/test").function("A@/home/lyokha/tmp/stap-example/test.cc:30")
process("/home/lyokha/tmp/stap-example/test").function("B@/home/lyokha/tmp/stap-example/test.cc:39")
process("/home/lyokha/tmp/stap-example/test").function("_GLOBAL__sub_I_main@<unknown source>")
process("/home/lyokha/tmp/stap-example/test").function("_ZNSt8ios_base4InitD1Ev@@GLIBCXX_3.4")
process("/home/lyokha/tmp/stap-example/test").function("_ZSt4endlIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_@@GLIBCXX_3.4")
process("/home/lyokha/tmp/stap-example/test").function("_ZdlPv@@GLIBCXX_3.4")
process("/home/lyokha/tmp/stap-example/test").function("__do_global_dtors_aux")
process("/home/lyokha/tmp/stap-example/test").function("__libc_csu_fini")
process("/home/lyokha/tmp/stap-example/test").function("__libc_csu_init")
process("/home/lyokha/tmp/stap-example/test").function("__static_initialization_and_destruction_0@<unknown source>")
process("/home/lyokha/tmp/stap-example/test").function("_fini")
process("/home/lyokha/tmp/stap-example/test").function("_init")
process("/home/lyokha/tmp/stap-example/test").function("_start")
process("/home/lyokha/tmp/stap-example/test").function("cycle@/home/lyokha/tmp/stap-example/test.cc:50")
process("/home/lyokha/tmp/stap-example/test").function("deregister_tm_clones")
process("/home/lyokha/tmp/stap-example/test").function("frame_dummy")
process("/home/lyokha/tmp/stap-example/test").function("main@/home/lyokha/tmp/stap-example/test.cc:61")
process("/home/lyokha/tmp/stap-example/test").function("print@/home/lyokha/tmp/stap-example/test.cc:24")
process("/home/lyokha/tmp/stap-example/test").function("print@/home/lyokha/tmp/stap-example/test.cc:33")
process("/home/lyokha/tmp/stap-example/test").function("print@/home/lyokha/tmp/stap-example/test.cc:42")
process("/home/lyokha/tmp/stap-example/test").function("register_tm_clones")
Ага, функции стали называться иначе. Давайте я сразу приведу готовый скрипт с учетом всех переименований и возможностью запуска с отладочными символами в программе test и без них.
#!/usr/bin/env stap
global startA, startCycle, intervals, printcalls = 0, hdr = "<---> "
probe process(@1).function("_ZNK1A5printEv")
{
startA[tid()] = gettimeofday_us()
}
probe process(@1).function("_ZNK1A5printEv").return
{
t = gettimeofday_us()
old_t = startA[tid()]
if (old_t) intervals <<< t - old_t
delete startA[tid()]
}
probe process(@1).function("_ZN12_GLOBAL__N_15cycleEPK1AS2_i") ?
{
startCycle[tid()] = gettimeofday_us()
}
probe process(@1).function("_ZN12_GLOBAL__N_15cycleEPK1AS2_i").return ?
{
delete startCycle[tid()]
}
probe process(@1).function("cycle") ?
{
startCycle[tid()] = gettimeofday_us()
if (@defined($i))
{
printf("%s Stack variable i = %d\n", hdr, $i)
}
}
probe process(@1).function("cycle").return ?
{
delete startCycle[tid()]
}
probe process(@1).function("print@*test.cc:33").callee("*print*") ?
{
printcalls += 1
}
function dump_intervals(print_hist)
{
if (@count(intervals))
{
printf("%s Intervals min:%dus avg:%dus max:%dus count:%d\n", hdr,
@min(intervals), @avg(intervals), @max(intervals),
@count(intervals))
if (print_hist)
{
print(@hist_log(intervals))
}
}
}
probe timer.s(2)
{
foreach (tid in startCycle)
{
old_t = startCycle[tid]
if (old_t > 0)
{
t = gettimeofday_us()
if (t - old_t > $2 * 1000000)
{
printf("%s Pending call detected: %dus (tid %d)\n", hdr, t - old_t, tid)
}
}
}
dump_intervals(0)
}
probe end
{
println()
dump_intervals(1)
printf("%s Function print() was called from A %d times\n", hdr, printcalls)
}
Я добавил опциональные probe с function(“cycle”) и function(“print@*test.cc:33”). Поскольку существует единственная функция cycle(), уточнение адреса не требуется. Другое дело — имя print, которое соответствует сразу трем функциям. Для разрешения адреса функции A::print() я воспользовался глоб-паттерном print@*test.cc:33. Важно отметить, что имена функций в случае введения отладочной информации могут сильно зависеть как от опций оптимизации gcc, так и от его версии. Ситуация осложняется наличием багов (например, вот этот), возможностью встраивания функций при оптимизации (inlining) и другими подобными факторами. В общем, правильно определить имя функции для использования в скрипте SystemTap и в итоге получить нужную трассировку может оказаться непростой задачей.
Запустим скрипт test.stp снова.
stap test.stp -c ./test `pwd`/test 3
WARNING: For probing a particular line, use a .statement() probe, not .function(): keyword at test.stp:36:1
source: probe process(@1).function("print@*test.cc:33").callee("*print*") ?
^
B
A
A
<---> Stack variable i = 0
<---> Stack variable i = 1
<---> Stack variable i = 2
B
<---> Stack variable i = 3
<---> Intervals min:12us avg:13us max:14us count:2
A
<---> Stack variable i = 4
<---> Intervals min:12us avg:17us max:27us count:3
A
<---> Stack variable i = 5
<---> Intervals min:12us avg:19us max:27us count:4
B
<---> Stack variable i = 6
<---> Intervals min:12us avg:19us max:27us count:4
A
<---> Stack variable i = 7
<---> Intervals min:12us avg:21us max:28us count:5
<---> Intervals min:12us avg:21us max:28us count:5
A
<---> Stack variable i = 8
<---> Intervals min:12us avg:21us max:28us count:6
<---> Pending call detected: 3977342us (tid 32523)
<---> Intervals min:12us avg:21us max:28us count:6
B
<---> Stack variable i = 9
<---> Intervals min:12us avg:21us max:28us count:6
<---> Pending call detected: 3977157us (tid 32523)
<---> Intervals min:12us avg:21us max:28us count:6
<---> Intervals min:12us avg:21us max:28us count:6
value |-------------------------------------------------- count
2 | 0
4 | 0
8 |@@ 2
16 |@@@@ 4
32 | 0
64 | 0
<---> Function print() was called from A 6 times
Прикольно. Сам выводил print@…test.cc:33 как имя функции, а теперь говорит используйте .statement(). В данном случае мы не можем использовать statement, поскольку callee можно присоединить только к function. Ну да это просто предупреждение. Главное, все заработало! Мы стали получать значение переменной i и printcalls оказалась равной 6, как мы и ожидали.
