SystemTap: пример трассировки в пространстве пользователя

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, как мы и ожидали.