Отлаживаем ядро из командной строки с bpftrace16.02.2021 03:18

Это очередная статья из цикла «BPF для самых маленьких» (0, 1, 2) и первая из серии практических статей про трассировку Linux современными средствами.

Из нее вы узнаете о программе и языке bpftrace — самом простом способе погрузиться в мир BPF с практической точки зрения, даже если вы не знаете про BPF ровным счетом ничего. Утилита bpftrace позволяет при помощи простого языка прямо из командной строки создавать программы-обработчики и подсоединять их к огромному количеству событий ядра и пространства пользователя. Посмотрите на КПДВ ниже… поздравляю, вы уже умеете трейсить системные вызовы при помощи bpftrace!

В отличие от предыдущих статей серии, эта относительно короткая и ее основная часть написана в формате туториала, так что уже после пяти минут чтения вы сможете создавать обработчики и собирать статистику о любом событии в ядре Linux прямо из командной строки. В конце статьи рассказывается об альтернативах — ply и BCC. Минуты во фразе «после пяти минут чтения» подразумеваются меркурианские. Появление уникальных навыков после пяти минут чтения не гарантируется.


-tt0nbuuleaiqi-j3uhtesdf6vq.png


Короткая версия. Попробуйте выполнить команду sudo apt install bpftrace (скорректированную под ваш дистрибутив). Если bpftrace установился, то переходите к следующему разделу.

Длинная версия. Хотя bpftrace и доступен в качестве пакета в популярных дистрибутивах, но не во всех, а кроме этого он может быть собран криво, например, без поддержки BTF. Поэтому давайте посмотрим на то, как добыть bpftrace альтернативными средствами.

При каждом обновлении master-ветки репозитория bpftrace собирается и публикуется новый docker image с упакованным внутри bpftrace. Таким образом, мы можем просто скачать и скопировать бинарник: 

$ docker pull quay.io/iovisor/bpftrace:latest
$ cd /tmp
$ docker run -v $(pwd):/o quay.io/iovisor/bpftrace:latest /bin/bash -c "cp /usr/bin/bpftrace /o"
$ sudo ./bpftrace -V
bpftrace v0.11.4

Если bpftrace ругается на слишком старую версию glibc, то вам нужен другой docker image со старой glibc.

Проверим, что программа работает. Для этого запустим пример из КПДВ, который трейсит системный вызов execve(2) и в реальном времени показывает какие программы запускаются в системе, и кем: 

$ sudo ./bpftrace -e 'tracepoint:syscalls:sys_enter_execve { printf("%s -> %s\n", comm, str(uptr(args->filename))); }'
Attaching 1 probe...
bash -> /bin/echo
bash -> /usr/bin/ls
gnome-shell -> /bin/sh
sh -> /home/aspsk/bin/geeqie
sh -> /usr/local/sbin/geeqie
...

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

$ sudo mv /tmp/bpftrace /usr/local/bin

Если вам этого мало, то можете скачать исходники, запустить чуть больше проверок, собрать свое ядро с поддержкой BTF, а также свою версию bpftrace, при помощи docker или локально. Инструкции по самостоятельной сборке bpftrace см. в официальной документации.

Важная деталь. Если bpftrace и/или ядро собрано без поддержки BTF, то для полноценной работы нужно установить kernel headers. Если вы не знаете как это сделать, то в документации bpftrace есть универсальный дистрибутивонезависимый рецепт.

Мы не будем в этой статье подробно рассказывать про BTF, скажем только, что BTF убирает зависимость от kernel headers, позволяет писать более простые программы, а также расширяет набор событий, к которым мы можем подключиться. Если внешние обстоятельства требуют от вас изучения BTF прямо сейчас, то начните с этой статьи и продолжите этой и этой.


Вы сидите в лесу с фотоаппаратом на удобном раскладном стуле. Идет мелкий дождь, но он вам не страшен, ведь шалаш из еловых веток надежно укрывает вас как от дождя, так и от случайных взглядов. Рядом стоит термос с пуэром, йогурт и поднос с копчеными селедками. Но тут вы вдруг задумываетесь: «а зачем я сюда пришел и что я буду снимать?!» Когда вы просыпаетесь, на лице краснеет слепок клавиатуры, а в терминале написано

$ sudo apt install bpftrace
The following NEW packages will be installed:
  bpftrace
Preparing to unpack .../bpftrace_0.11.0-1_amd64.deb ...
Unpacking bpftrace (0.11.0-1) ...
Setting up bpftrace (0.11.0-1) ...
Processing triggers for man-db (2.9.3-2) ...
$

Итак, bpftrace у нас уже установлен. Какие события мы можем инструментировать? Давайте посмотрим на них по очереди, а заодно познакомимся с синтаксисом языка bpftrace. Вот спойлер-оглавление данной секции:


  • Специальные события: BEGIN, END
  • События, основанные на kprobes: kprobe, kretprobe, uprobe, uretprobe
  • События, основанные на BPF trampolines: kfunc, kretfunc
  • События, основанные на tracepoints: tracepoint
  • Статическая отладка в пространстве пользователя: usdt
  • События, основанные на подсистеме perf: software, hardware, profile, interval, watchpoint

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


Bpftrace: hello world

Язык bpftrace создавался по аналогии с языком awk и поэтому в нем есть два специальных события, BEGIN и END, которые случаются в момент запуска и выхода из bpftrace, соответственно. Вот первая простая программа: 

# bpftrace -e 'BEGIN { printf("Hello world!\n"); }'
Attaching 1 probe...
Hello world!
^C

Программа сразу после старта напечатала "Hello world!". Заметьте, что нам пришлось нажимать Ctrl-C, чтобы завершить работу bpftrace — это его поведение по умолчанию. Мы можем завершить работу bpftrace из любого события при помощи функции exit. Продемонстрируем это, а заодно добавим и обработку END: 

# bpftrace -e '
 BEGIN { printf("Hello world!\n"); exit(); }
 END { printf("So long\n"); }
 '
Attaching 2 probes...
Hello world!
So long

Kprobes — динамическая инструментация ядра

Ядро — это большая программа, функции этой программы, как водится, состоят из инструкций, а механизм ядра под названием kprobes (Kernel Probe — ядерный зонд) позволяет нам поставить точку останова практически на любой инструкции, а точнее, по началу конкретной функции или коду внутри нее. В контексте данной статьи нам, вообще говоря, не важно как именно создаются обработчики kprobes, но вы можете узнать об этом из предыдущих статей этой серии, ссылки на которые есть в конце, а также из будущих статей, в которых мы разберем все технические подробности трассировки Linux с BPF.

В качестве примера давайте посмотрим на то, как часто и кем вызывается функция schedule: 

$ sudo bpftrace -e '
    k:schedule { @[comm] = count(); }
    i:s:2 { exit();}
    END { print(@, 10); clear(@); }
'
Attaching 3 probes...
@[Timer]: 147
@[kworker/u65:0]: 147
@[kworker/7:1]: 153
@[kworker/13:1]: 158
@[IPC I/O Child]: 170
@[IPC I/O Parent]: 172
@[kworker/12:1]: 185
@[Web Content]: 229
@[Xorg]: 269
@[SCTP timer]: 1566

Мы также сказали программе выйти через две секунды и в конце напечатать только десять верхних элементов словаря @.

Много ли функций можно потрейсить при помощи кей-проб? Это легко проверить: 

$ sudo bpftrace -l 'k:*' | wc -l
61106

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


kretprobes

Для каждой kprobe мы можем создать обработчик kretprobe. Если kprobe запускается в момент входа в функцию, то kretporobe запускается в момент выхода из функции. При этом код возврата функции содержится в специальной встроенной переменной retval.

Например, вот что на отрезке в две секунды возвращала функция vfs_write на моей системе (в виде логарифмической гистограммы): 

$ sudo bpftrace -e 'kr:vfs_write { @ = hist(retval); } i:s:2 { exit(); }'
Attaching 2 probes...

@:
[1]                  606 |@@@@@@@@@@@@@@@@@@@@@@@@@                           |
[2, 4)                 0 |                                                    |
[4, 8)                 0 |                                                    |
[8, 16)             1223 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[16, 32)               0 |                                                    |
[32, 64)              25 |@                                                   |

uprobes и uretprobes

Кроме инструментации функций ядра, мы можем инструментировать каждую программу (и библиотеку), работающую в пространстве пользователя. Реализуется это при помощи тех же kprobes. Для этого в bpftrace определены события uprobes и uretprobes — вызов и возврат из функции.

Вот как мы можем подглядывать за тем, что печатают пользователи баша (в квадратных скобках печатается UID пользователя): 

$ sudo bpftrace -e 'uretprobe:/bin/bash:readline { printf("readline: [%d]: \"%s\"\n", uid, str(uptr(retval))); }'
Attaching 1 probe...
readline: [1000]: "echo "hello habr""
readline: [0]: "echo "hello from root""
^C

Динамическая инструментация ядра, версия 2

Для счастливых обладателей CONFIG_DEBUG_INFO_BTF=y в конфиге ядра существует более дешевый, по сравнению с kprobes, способ динамической инструментации ядра, основанный на bpf trampolines. Так как BTF в дистрибутивных ядрах обычно выключен, я про эти события дальше не рассказываю. Если интересно, то смотрите сюда и/или задавайте вопросы в комментариях.


Tracepoints — статическая инструментация ядра

Если что-то можно сделать динамически, то, с большой вероятностью, это же можно сделать статически чуть быстрее и удобнее. Механизм ядра под названием tracepoints предоставляет набор статических точек останова ядра для наиболее важных функций. Вы можете посмотреть на свой набор так: 

$ sudo bpftrace -l 't:*'

Их сильно меньше, чем kprobes: 

$ sudo bpftrace -l 't:*' | wc -l
1782

но самой важной особенностью tracepoints является то, что они предоставляют стабильный API: вы можете быть уверены, что tracepoint, на основе которой вы написали свой код для отладки или сбора информации, не пропадет или не поменяет семантику в самый неудобный момент. Еще одним удобным отличием является то, что bpftrace может нам рассказать о том, какие аргументы передаются в конкретный tracepoint, например: 

$ sudo bpftrace -lv tracepoint:thermal:thermal_temperature
tracepoint:thermal:thermal_temperature
    __data_loc char[] thermal_zone;
    int id;
    int temp_prev;
    int temp;

В случае kprobe, если у вас не включен BTF, вам придется читать исходники ядра, причем той версии, которую вы используете. А с BTF вы можете смотреть и на строение kprobes и kfuncs.


usdt — статическая инструментация в пространстве пользователя

Статическая инструментация программ пользователя позволяет напихать в программу статических точек останова в момент компиляции. Давайте сразу посмотрим на пример (который я стянул почти без изменений отсюда): 

#include 
#include 
#include 

int main(int argc, char **argv)
{
    struct timeval tv;

    for (;;) {
        gettimeofday(&tv, NULL);
        DTRACE_PROBE1(test, probe, tv.tv_sec);
        sleep(1);
    }
}

Мы добавили одну статическую точку останова под названием test:probe, в которую передаем один аргумент tv.tv_sec — текущее время в секундах. Чтобы скомпилировать эту программу, нужно поставить пакет systemtap-sdt-dev (или аналогичный для вашего дистрибутива). Дальше мы можем посмотреть на то, что получилось: 

$ cc /tmp/test.c -o /tmp/test
$ sudo bpftrace -l 'usdt:/tmp/test'
usdt:/tmp/test:test:probe

Запустим /tmp/test в одном терминале, а в другом скажем

$ sudo bpftrace -e 'usdt:/tmp/test:test:probe { printf("московское время %u\n", arg0); }'
Attaching 1 probe...
московское время 1612903991
московское время 1612903992
московское время 1612903993
московское время 1612903994
московское время 1612903995
...

Здесь arg0 — это значение tv.tv_sec, которое мы передаем в breakpoint.


События Perf

Программа bpftrace поддерживает множество событий, предоставляемых подсистемой ядра Perf. Мы сейчас коротко посмотрим на следующие типы событий, поддерживаемые bpftrace:


  • software: статически-сгенерированные софтверные события
  • hardware: железные PMCs
  • interval: интервальное событие
  • profile: интервальное событие для профилирования

События типа `software`

В ядре определяется несколько статических событий perf, посмотреть их список можно так: 

# bpftrace -l 's:*'
software:alignment-faults:
software:bpf-output:
software:context-switches:
software:cpu-clock:
software:cpu-migrations:
software:dummy:
software:emulation-faults:
software:major-faults:
software:minor-faults:
software:page-faults:
software:task-clock:

События такого типа могут происходить очень часто, поэтому на практике указывается количество сэмплов, например, команда

# bpftrace -e 'software:cpu-migrations:10 { @[comm] = count(); }'
Attaching 2 probes...
^C@[kworker/u65:1]: 1
@[bpftrace]: 1
@[SCTP timer]: 2
@[Xorg]: 2

Подсчитает каждое десятое событие миграции процесса с одного CPU, а другой. Значение событий из списка выше объясняется в perf_event_open(2), например, cpu-migrations, которую мы использовали выше можно найти в этой man-странице под именем PERF_COUNT_SW_CPU_MIGRATIONS.


События типа `hardware`

Ядро дает нам доступ к некоторым hardware counters, а bpftrace может вешать на них программы BPF. Точный список событий зависит от архитектуры и ядра, например: 

bpftrace -l 'h*'
hardware:backend-stalls:
hardware:branch-instructions:
hardware:branch-misses:
hardware:bus-cycles:
hardware:cache-misses:
hardware:cache-references:
hardware:cpu-cycles:
hardware:frontend-stalls:
hardware:instructions:
hardware:ref-cycles:

Посмотрим на то как мой процессор предсказывает инструкции перехода (считаем каждое стотысячное событие, см. PERF_COUNT_HW_BRANCH_MISSES): 

bpftrace -e 'hardware:branch-misses:100000 { @[tid] = count(); }'
Attaching 3 probes...
@[1055]: 4
@[3078]: 4
@[1947]: 5
@[1066]: 6
@[2551]: 6
@[0]: 29

События типа `interval` и `profile`

События типов interval и profile позволяют пользователю запускать обработчики через заданные интервалы времени. Событие первого типа запустится один раз на одном CPU, а событие второго — на каждом из CPU.

Мы уже использовали интервал раньше, чтобы выйти из программы. Давайте посмотрим на этот пример еще раз, но чуть пропатчим его: 

$ sudo bpftrace -e '
    kr:vfs_write { @ = hist(retval); }
    interval:s:2 { print(@); clear(@); }
'

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

Аналогично можно использовать и profile: 

# bpftrace -e '
  profile:hz:99 { @[kstack] = count(); }
  i:s:10 { exit(); }
  END { print(@,1); clear(@); }
'
Attaching 3 probes...
@[
    cpuidle_enter_state+202
    cpuidle_enter+46
    call_cpuidle+35
    do_idle+487
    cpu_startup_entry+32
    start_secondary+345
    secondary_startup_64+182
]: 14455

Здесь мы запускаем profile на каждом ядре 99 раз в секунду, через десять секунд выстрелит интервал и вызовет exit(), а секция END напечатает только верхний элемент словаря @ — самый часто встречающийся ядерный стек (по которому мы видим, что моя система, в основном, бездействует).



Базовые навыки

Начнем с простого, запустим bpftrace без аргументов: 

# bpftrace

Программа напечатает короткую справку о том, как ее использовать. В частности, посмотрите какие переменные окружения использует bpftrace. Заметьте, что мы запускаем bpftrace от рута. Для вывода справки это не нужно, но для любых других действий — да.

Посмотрим внимательнее на аргумент -l. Он позволяет найти события по шаблону. (Если что-то дальше не ясно, то читайте про события в предыдущем разделе, который вы пропустили.) Вот как можно искать события среди всех возможных: 

# bpftrace -l '*kill_all*'
kprobe:rfkill_alloc
kprobe:kill_all
kprobe:btrfs_kill_all_delayed_nodes

А здесь мы ищем события только среди tracepoints: 

# bpftrace -l 't:*kill*'
tracepoint:cfg80211:rdev_rfkill_poll
tracepoint:syscalls:sys_enter_kill
tracepoint:syscalls:sys_exit_kill
tracepoint:syscalls:sys_enter_tgkill
tracepoint:syscalls:sys_exit_tgkill
tracepoint:syscalls:sys_enter_tkill
tracepoint:syscalls:sys_exit_tkill

Подмножество tracepoint:syscalls, на которое мы только что наткнулись, можно использовать для самостоятельных экспериментов по изучению bpftrace. Для каждого системного вызова X определены две точки останова: 

tracepoint:syscalls:sys_enter_X
tracepoint:syscalls:sys_exit_X

Поиграемся с каким-нибудь системным вызовом, например, execve(2). Для того, чтобы посмотреть на то, как использовать какой-либо tracepoint можно использовать дополнительный аргумент -v, например: 

# bpftrace -lv 't:s*:sys_*_execve'
tracepoint:syscalls:sys_enter_execve
    int __syscall_nr;
    const char * filename;
    const char *const * argv;
    const char *const * envp;
tracepoint:syscalls:sys_exit_execve
    int __syscall_nr;
    long ret;

(заметьте как ловко мы дважды использовали *, чтобы не писать syscalls полностью и чтобы не перечислять sys_enter_execve и sys_exit_execve по отдельности). Параметры, перечисленные в выводе -lv доступны через встроенную переменную args: 

# bpftrace -e '
    t:s*:sys_enter_execve { printf("ENTER: %s\n", str(uptr(args->filename))); }
    t:s*:sys_exit_execve { printf("EXIT: %s: %d\n", comm, args->ret); }
'
Attaching 2 probes...
ENTER: /bin/ls
EXIT: ls: 0
ENTER: /bin/lss
EXIT: bash: -2

Этот короткий листинг позволяет разглядеть несколько интересных вещей.

В первом обработчике мы печатаем аргумент args->filename. Так как передается он нам как указатель, нам нужно вычитать строку при помощи встроенной функции str, но просто так ее использовать нельзя: указатель этот указывает в пространство пользователя, а значит мы должны об этом специально сказать при помощи функции uptr. Сам bpftrace постарается угадать принадлежность указателя, но он не гарантирует результат. Также, к сожалению, вызов bpftrace -lv не расскажет нам о семантике указателя, для этого придется изучать исходники, в данном случае, мы посмотрим на определение системного вызова execve (обратите внимание на квалификатор типа __user).

Во втором обработчике мы используем встроенную переменную comm, которая возвращает текущее имя потока. Код возврата системного вызова доступен через переменную args->ret. Как известно, этот системный вызов «не возвращается» в текущую программу, так как его работа заключается собственно в замене кода программы новым. Однако, в случае ошибки он-таки вернется, как мы и можем видеть в выводе выше: в первом случае я запустил /bin/ls из баша и exec запустился нормально и вернул 0 (внутри процесса ls прямо перед запуском кода /bin/ls), а во втором случае я запустил несуществующую программу /bin/lss и exec вернул -2 внутри процесса bash.

Упражнение. Возьмите ваш любимый системный вызов и напишите несколько программ, аналогичных приведенной выше. Попробуйте напечатать все аргументы системного вызова и значение, которое он возвращает. Не забудьте использовать uptr, если нужно.


Структура программ `bpftrace`

Язык bpftrace создавался по аналогии с языком awk (см. также главу 6 в книжке The AWK Programming Language) и имеет очень похожую структуру. Программы состоят из списка блоков вида

  {  }

Например, 

# bpftrace -e 'BEGIN { printf("Hello\n") } END { printf("World\n") }'

Здесь  — это BEGIN и END, а  — это printf. Поле
является опциональным и используется для фильтрации событий,
например, программа

# bpftrace -e 'p:s:1 /cpu == 0/ { printf("Привет с CPU%d\n", cpu); }'
Attaching 1 probe...
Привет с CPU0
Привет с CPU0
^C

будет передавать привет, только если запускается на CPU 0.

Упражнение. Что выведет эта команда на вашей машине, если убрать фильтр /cpu == 0/?

На практике удобно использовать для синхронизации между двумя событиями. Например, вы хотите подсчитать время выполнения системного вызова write на вашей системе. Для этого мы можем использовать пару трейспоинтов — sys_enter_write и sys_exit_write и считать время выполнения по тредам: 

# cat /tmp/write-times.bt
t:syscalls:sys_enter_write {
  @[tid] = nsecs
}

t:syscalls:sys_exit_write /@[tid]/ {
  @write[comm] = sum((nsecs - @[tid]) / 1000);
  delete(@[tid]);
}

END {
  print(@write, 10);
  clear(@write);
  clear(@);
}

Эта программа уже довольно длинная, поэтому мы записали ее в отдельный файл. Запустить ее можно так: 

# bpftrace /tmp/write-times.bt

В первом событии, sys_enter_write, мы запоминаем время запуска системного вызова write в наносекундах в словаре @, ключом к которому служит tid.

Во втором событии, sys_exit_write, мы при помощи фильтра /@[tid]/ проверяем, запускался ли обработчик первого события для данного потока. Нам нужно это делать, ведь мы могли запустить программу в тот момент, когда какой-то поток был внутри системного вызова write. Дальше мы записываем потраченное время (в микросекундах) в отдельный словарь @write и удаляем элемент @[tid].

Наконец, после того как мы нажимаем ^C, запускается секция END, в которой мы печатаем десять самых прожорливых процессов и чистим словари @write и @, чтобы bpftrace не выводил их содержимое.

Упражнение. Так что же именно может пойти не так, если убрать фильтр /@[tid]/?


Храним состояние: переменные и мапы

Внутри программ bpftrace вы можете использовать обычные для языка C конструкции, например, :?, ++, --. Вы можете использовать блоки if {} else {}. Можно составлять циклы при помощи while и экзотического unroll (который появился в то время, когда в архитектуре BPF циклы были запрещены). Содержание же во все эти конструкции добавляют переменные и структуры ядра, доступные из контекста.

Переменные бывают двух типов: локальные и глобальные. Локальные переменные начинаются со знака доллара $ и доступны в пределах заданного события, оба следующих варианта сработают: 

# bpftrace -e 'BEGIN { $x = 1; printf("%d\n", ++$x); exit(); }'
# bpftrace -e 'BEGIN { if (1) { $x = 1; } printf("%d\n", ++$x); exit(); }'

а следующее — нет: 

# bpftrace -e 'BEGIN { $x = 1; exit(); } END { printf("%d\n", $x); }'

Глобальные переменные, с которыми мы уже встречались выше, начинаются со знака @ и доступны между событиями. Вы можете использовать «безымянную» глобальную переменную @, как мы делали выше для хранения начала вызова write (@[tid]). (Глобальные переменные в bpftrace хранятся в мапах — специальных размеченных областях памяти. Они, между прочим, глобальные в более общем смысле: любая программа с рутовым доступом на системе может их читать и писать. Но для данной статьи это не так важно, смотрите предыдущие серии, если вам интересны подробности.)

И теперь, мы переходим к самому главному: зачем нам нужны переменные и что мы в них будем записывать? Каждое событие bpftrace запускается с определенным контекстом. Для kprobes нам доступны аргументы вызываемой функции, для tracepoints — аргументы, передаваемые в tracepoint, а для событий Perf, как и для других программ, — глобальные переменные. Мы уже видели как мы можем работать с tracepoints, в этой и следующих секциях мы посмотрим на kprobes, а в секции Веселые Картинки мы посмотрим на события Perf.

Аргументы kprobes доступны внутри программы как arg0, arg1, и т.д. Аргументы передаются без типа, так что вам придется к нужному типу их приводить вручную. Пример: 

#include 
#include 

k:icmp_echo {
    $skb = (struct sk_buff *) arg0;
    $iphdr = (struct iphdr *) ($skb->head + $skb->network_header);
    @pingstats[ntop($iphdr->saddr), ntop($iphdr->daddr)]++;
}

Эта программа строит статистику о том, кто пингует данный хост. Мы цепляемся к kprobe на входе в функцию icmp_echo, которая вызывается на приход ICMPv4 пакета типа echo request. Ее первый аргумент, arg0 в нашей программе, — это указатель на структуру типа sk_buff, описывающую пакет. Из этой структуры мы достаем IP адреса и увеличиваем соответствующий счетчик в глобальной переменной @pingstats. Все, теперь у нас есть полная статистика о том, кто и как часто пинговал наши IP адреса! Раньше для написания такой программы вам пришлось бы писать модуль ядра, регистрировать в нем обработчик kprobe, а также придумывать механизм взаимодействия с user space, чтобы хранить и читать статистику.

Посмотрим на нее еще раз. Вначале мы включили два хедера ядра, для этого нужно установить пакет с kernel headers. Эти хедеры нужны нам для определения структур sk_buff и iphdr, которые мы собираемся разыменовывать. (Если бы у нас был собран BTF, то нам не нужно было бы это делать — ни устанавливать пакет, ни включать хедеры.) В первой строчке программы мы приводим единственный аргумент функции icmp_echo к указателю на sk_buff и сохраняем его в локальной переменной $skb. На второй строчке мы разыменовываем $skb и находим место в памяти, где хранится сетевой заголовок, который мы, в свою очередь, приводим к указателю на iphdr. На третьей строчке мы используем сетевой заголовок и встроенную функцию ntop языка bpftrace, которая преобразует бинарный IP адрес в строку.

Упражнение. Возьмите любую интересующую вас функцию ядра и попробуйте разыменовать ее аргументы. Не забывайте про uptr и kptr. Например: возьмите функцию vfs_write ядра, ее первый аргумент — это указатель на структуру struct file, определенную в заголовке . Попробуйте напечатать интересующие вас флаги файла до и после вызова vfs_write. (Hint: как вы можете передать указатель на struct file внутрь kretprobe?)

Упражнение. Напишите программу bpftrace, которая будет печатать имя и пароль пользователя, всякий раз, как он запускает sudo.


Считаем и агрегируем события

В предыдущей программе про ping мы сделали ошибку — не защитились от того, что программа может быть запущена на разных CPU. Для более точного подсчета мы можем использовать функцию count. Следующий пример иллюстрирует проблему: 

# bpftrace -e 'p:hz:5000 { @x++; @y = count(); } i:s:10 { exit(); }'
Attaching 2 probes...
@x: 760528
@y: 799002

В течение 10 секунд по 5000 раз в секунду на каждом из 16 ядер моей системы мы увеличиваем значения двух счетчиков @x и @y. Операция ++ выполняется безо всяких блокировок и поэтому значение счетчика не совсем точное. Операция count() на самом деле выполняется тоже безо всяких блокировок, но использует CPU-локальные переменные: для каждого из CPU хранится свой счетчик, значения которых при печати суммируются.

Кроме подсчета событий в bpftrace есть несколько полезных функций, которые могут быстро показать какие-то баги в работающей системе. Главный инструмент тут — это гистограммы. Посмотрим на простой пример.

# bpftrace -e 'kr:vfs_write { @ = hist(retval); } i:s:10 { exit() }'
Attaching 2 probes...

@:
[1]             14966407 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[2, 4)                 0 |                                                    |
[4, 8)                 0 |                                                    |
[8, 16)             1670 |                                                    |
[16, 32)               0 |                                                    |
[32, 64)             123 |                                                    |
[64, 128)              0 |                                                    |
[128, 256)             0 |                                                    |
[256, 512)             0 |                                                    |
[512, 1K)              0 |                                                    |
[1K, 2K)               0 |                                                    |
[2K, 4K)               0 |                                                    |
[4K, 8K)               0 |                                                    |
[8K, 16K)        7531982 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |

В течении десяти секунд мы строим гистограмму возвращаемых значений функции vfs_write, и мы можем заметить, что кто-то уверенно пытается писать по одному байту! Давайте чуть усовершенствуем программу (то заняло у меня около 20 секунд): 

# bpftrace -e '
    kr:vfs_write /retval == 1/ { @[pid, comm] = hist(retval); }
    i:s:10 { exit() }
    END { print(@, 1); clear(@); }'
Attaching 3 probes...
@[133835, dd]:
[1]             14254511 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|

Для начала, мы смотрим только на записи, в которых retval равен единице. Для того, чтобы различить процессы мы добавляем ключи — идентификатор и имя процесса. Наконец, в END мы печатаем только процесс, который сделал больше всего записей. Что же он делает? Думаю вы уже догадались: 

# tr '\000' ' ' < /proc/133835/cmdline
dd if=/dev/zero of=/dev/null bs=1

Упражнение. Найдите ссылку на официальный туториал по bpftrace в конце статьи и выполните все шаги, в которых встречаются гистограммы.


Веселые Картинки: flame graphs

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

profile:hz:rate
profile:s:rate
profile:ms:rate
profile:us:rate

В первом случае мы задаем частоту события в HZ, а в следующих — частоту события в секундах, миллисекундах и микросекундах, соответственно.

Одной из интересных глобальных переменных, которые мы можем сэмплировать, является стек ядра, выглядит он так: 

bpftrace -e 'profile:hz:99 { print(kstack); exit() }'
Attaching 1 probe...

        cpuidle_enter_state+202
        cpuidle_enter+46
        call_cpuidle+35
        do_idle+487
        cpu_startup_entry+32
        rest_init+174
        arch_call_rest_init+14
        start_kernel+1724
        x86_64_start_reservations+36
        x86_64_start_kernel+139
        secondary_startup_64+182

здесь в момент сэмплирования мы попали на ядро-бездельника.

Для практического профилирования, однако, смотреть на миллионы стеков ядра не очень удобно. Поэтому БГ разработал механизм агрегации под названием flame graphs, превращающий текст в удобную кликабельную картинку.

Для начала, нам нужно запустить bpftrace следующим образом: 

# bpftrace -e 'profile:hz:333 { @[kstack] = count(); } i:s:10 { exit() }' > /tmp/raw
# wc -l /tmp/raw
3374 /tmp/raw

Здесь мы по 333 раза в секунду сэмплируем стек ядра и считаем сколько раз мы увидели разные стеки (мы используем kstack как ключ в словаре @, ведь kstack — это просто строка).

Далее нам нужно склонировать репозиторий FlameGraph и запустить пару скриптов: 

$ git clone https://github.com/brendangregg/FlameGraph.git
$ cd FlameGraph
$ ./stackcollapse-bpftrace.pl /tmp/raw > /tmp/ready
$ ./flamegraph.pl /tmp/ready > /tmp/kstack.svg

Первый скрипт приводит вывод bpftrace к каноническому виду, а второй строит по нему картинку (кликните на нее, чтобы открылся gist с SVG):

n8fkrowxakk7-lotzxtjd0ea4g4.png

Здесь моя система наполовину бездействует, а на половине CPU крутится все тот же dd, копирующий /dev/zero в /dev/null по одному байту. Кликайте на картинку, чтобы посмотреть подробности.

Упражнение. Снимки стека можно делать не только при помощи bpftrace. Загляните в в репозиторий FlameGraph и сделайте снимок своей системы другим способом.


Пора закругляться

Если вы дочитали до этого момента и запустили хотя бы половину примеров, то вы уже можете считать себя профессионалом в нелегком деле отладки при помощи bpftrace. Смотрите на ссылки в конце статьи для того, чтобы узнать куда двигаться дальше.


Благодаря проекту BCC люди, роботы и не определившиеся могут использовать возможности BPF без необходимости утруждать себя программированием — проект содержит почти 100 готовых утилит. Эти утилиты — не случайные примеры, а рабочие инструменты, используемые повседневно в недрах Netflix, Facebook и других компаний добра. См. ссылки на книжки БГ в конце статьи, в которых подробно описано большинство утилит и подробно обсуждается почему и зачем они нужны.

Утилиты написаны на основе libbcc и libbpf и представляют из себя код на питоне, в который встроены куски псевдо-C кода, так что их легко редактировать и расширять даже на боевой машине. Также вы можете писать новые утилиты по аналогии с существующими, см. следующий подраздел.

Утилиты BCC должны быть более-менее опакечены в популярных дистрибутивах. Например, на убунте достаточно поставить пакет bpfcc-tools. После этого мы можем сразу ими пользоваться. Например, команда

# funccount-bpfcc 'vfs_*' -d 5
Tracing 67 functions for "b'vfs_*'"... Hit Ctrl-C to end.

FUNC                                    COUNT
b'vfs_statfs'                               1
b'vfs_unlink'                               1
b'vfs_lock_file'                            2
b'vfs_fallocate'                           31
b'vfs_statx_fd'                            32
b'vfs_getattr'                             80
b'vfs_getattr_nosec'                       88
b'vfs_open'                               108
b'vfs_statx'                              174
b'vfs_writev'                            2789
b'vfs_write'                             6554
b'vfs_read'                              7363
Detaching...

посчитает сколько раз были вызваны функции ядра с префиксом vfs_ на интервале в пять секунд. Чуть интереснее подсунуть программе параметр -p, в котором передается PID процесса. Например, вот что делает мой mplayer, пока я это пишу: 

# funccount-bpfcc 'vfs_*' -d 5 -p 29380
Tracing 67 functions for "b'vfs_*'"... Hit Ctrl-C to end.

FUNC                                    COUNT
b'vfs_write'                              208
b'vfs_read'                               629
Detaching...

Пишем новую утилиту BCC

Давайте напишем простую утилиту BCC. Эта утилита будет считать сколько раз в секунду были вызваны функции ядра mutex_lock и mutex_unlock. Ее полный код приведен далее, также вы можете прочитать его здесь.

#! /usr/bin/python3

from bcc import BPF
from ctypes import c_int
from time import sleep, strftime
from sys import argv

b = BPF(text="""
BPF_PERCPU_ARRAY(mutex_stats, u64, 2);

static inline void inc(int key)
{
    u64 *x = mutex_stats.lookup(&key);
    if (x)
        *x += 1;
}

void do_lock(struct pt_regs *ctx) { inc(0); }
void do_unlock(struct pt_regs *ctx) { inc(1); }
""")

b.attach_kprobe(event="mutex_lock", fn_name="do_lock")
b.attach_kprobe(event="mutex_unlock", fn_name="do_unlock")

print("%-8s%10s%10s" % ("TIME", "LOCKED", "UNLOCKED"))

while 2 * 2 == 4:

    try:
        sleep(1)
    except KeyboardInterrupt:
        exit()

    print("%-8s%10d%10d" % (
          strftime("%H:%M:%S"),
          b["mutex_stats"].sum(0).value,
          b["mutex_stats"].sum(1).value))

    b["mutex_stats"].clear()

Вначале мы подключаем нужные библиотеки. Понятно, что самая интересная часть тут — это импорт класса BPF: 

from bcc import BPF

Этот класс позволяет нам определить программы BPF, которые мы будем подключать к событиям. В качестве параметра класс BPF принимает текст программы на псевдо-C. В нашем случае это

BPF_PERCPU_ARRAY(mutex_stats, u64, 2);

static inline void inc(int key)
{
    u64 *x = mutex_stats.lookup(&key);
    if (x)
        *x += 1;
}

void do_lock(struct pt_regs *ctx)   { inc(0); }
void do_unlock(struct pt_regs *ctx) { inc(1); }

Этот код написан на магическом C, вы не сможете скомпилировать его в таком виде, но при инициализации класса BPF некоторые части будут заменены реальным кодом на C.
Так или иначе, вначале мы определяем массив mutex_stats из двух элементов типа u64, наших счетчиков. Заметьте, что мы использовали PERCPU массив, это означает, что для каждого логического CPU будет создан свой массив. Далее мы определяем функцию inc, принимающую в качестве аргумента индекс в массиве mutex_stats. Эта функция увеличивает значение соответствующего счетчика.
Наконец, тривиальные функции do_lock и do_unlock увеличивают каждая свой счетчик.

На этом с ядерной частью почти покончено — во время инициализации класс BPF обратится к библиотеке libllvm, чтобы скомпилировать код, и потом зальет его в ядро. Осталось только подключить программы к интересующим нас kprobes: 

b.attach_kprobe(event="mutex_lock", fn_name="do_lock")
b.attach_kprobe(event="mutex_unlock", fn_name="do_unlock")

Пользовательская часть кода занимается исключительно сбором информации: 

print("%-8s%10s%10s" % ("TIME", "LOCKED", "UNLOCKED"))

while 2 * 2 == 4:

    try:
        sleep(1)
    except KeyboardInterrupt:
        exit()

    print("%-8s%10d%10d" % (
          strftime("%H:%M:%S"),
          b["mutex_stats"].sum(0).value,
          b["mutex_stats"].sum(1).value))

    b["mutex_stats"].clear()

После печати заголовка бесконечный цикл раз в секунду печатает значение счетчиков и обнуляет массив mutex_stats. Значение счетчиков мы получаем при помощи метода sum массива mutex_stats, который суммирует значения счетчиков для каждого CPU: 

sum(index) {
    result = 0
    для каждого CPU {
        result += cpu->mutex_
    
            
© Habrahabr.ru