Stfw.RuОтмечается, что несмотря на то, что BPF не предоставляет высокоуровневый язык как в
DTrace, доступные фронтэнды сглаживают эту особенность и достаточны для создания различных инструментов, некоторые из которых построены по мотивам старого DTraceToolkit. Для конечного пользователя трассировка с использованием инструментов на базе BPF и написание однострочных сценариев окажется не сложнее DTrace. Но для разработки новых инструментов на базе BPF пока требуется заметно больше усилий - предоставляемый в DTrace язык D, похожий на AWK, значительно проще для написания сценариев трассировки, чем предлагаемые для BPF средства написания обработчиков на языках C, Python и Lua с внешними библиотеками.
Основные возможности системы трассировки ядра Linux (по состоянию на 4.9rc1):
Динамическая трассировка на уровне ядра (BPF для kprobes);
Динамическая трассировка пространства пользователя (BPF для uprobes);
Статическая трассировка на уровне ядра (BPF для tracepoints);
Обработка событий с сохранением хронометража (BPF с perf_event_open);
События PMC (BPF с perf_event_open);
Фильтрация (через программы BPF);
Отладочный вывод (bpf_trace_printk());
Вывод в привязке к отдельным событиям (bpf_perf_event_output());
Использование переменных (глобальные и привязанные к потокам переменные, реализуемые через BPF maps);
Ассоциативные массивы (через BPF maps);
Подсчёт частоты выполнения операций (через BPF maps);
Гистограммы (квадратичные, линейные и произвольные через BPF maps)
Учёт времени выполнения операций и разницы во времени (через bpf_ktime_get_ns() и программы BPF);
Трассировка стека ядра (BPF stackmap);
Трассировка стека пользовательских процессов (BPF stackmap);
Переопределение кольцевых буфров (perf_event_attr.write_backward).
Примеры использования некоторых утилит из набора bcc для решения задач трассировки:
Отслеживание новых процессов:
# execsnoop
PCOMM
PID
RET ARGS
bash
15887
0 /usr/bin/man ls
preconv
15894
0 /usr/bin/preconv -e UTF-8
man
15896
0 /usr/bin/tbl
man
15897
0 /usr/bin/nroff -mandoc -rLL=169n -rLT=169n -Tutf8
man
15898
0 /usr/bin/pager -s
nroff
15900
0 /usr/bin/locale charmap
nroff
15901
0 /usr/bin/groff -mtty-char -Tutf8 -mandoc -rLL=169n -rLT=169n
groff
15902
0 /usr/bin/troff -mtty-char -mandoc -rLL=169n -rLT=169n -Tutf8
groff
15903
0 /usr/bin/grotty
Гистограмма задержек ввода/вывода:
# biolatency -m
Tracing block device I/O... Hit Ctrl-C to end.
^C
msecs
: count
distribution
0 -> 1
: 96
|************************************ |
2 -> 3
: 25
|*********
|
4 -> 7
: 29
|***********
|
8 -> 15
: 62
|***********************
|
16 -> 31
: 100
|**************************************|
32 -> 63
: 62
|***********************
|
64 -> 127
: 18
|******
|
Отслеживание типовых операций в ФС ext4, выполняемых дольше 5 мс:
# ext4slower 5
Tracing ext4 operations slower than 5 ms
TIME
COMM
PID
T BYTES
OFF_KB
LAT(ms) FILENAME
21:49:45 supervise
3570
W 18
0
5.48 status.new
21:49:48 supervise
12770 R 128
0
7.55 run
21:49:48 run
12770 R 497
0
16.46 nsswitch.conf
21:49:48 run
12770 R 1680
0
17.42 netflix_environment.sh
21:49:48 run
12770 R 1079
0
9.53 service_functions.sh
21:49:48 run
12772 R 128
0
17.74 svstat
21:49:48 svstat
12772 R 18
0
8.67 status
21:49:48 run
12774 R 128
0
15.76 stat
21:49:48 run
12777 R 128
0
7.89 grep
21:49:48 run
12776 R 128
0
8.25 ps
21:49:48 run
12780 R 128
0
11.07 xargs
21:49:48 ps
12776 R 832
0
12.02 libprocps.so.4.0.0
21:49:48 run
12779 R 128
0
13.21 cut
[...]
Отслеживание новых активных соединений по TCP (connect()):
# tcpconnect
PID
COMM
IP SADDR
DADDR
DPORT
1479
telnet
4 127.0.0.1
127.0.0.1
23
1469
curl
4 10.201.219.236
54.245.105.25
80
1469
curl
4 10.201.219.236
54.67.101.145
80
1991
telnet
6 ::1
::1
23
2015
ssh
6 fe80::2000:bff:fe82:3ac fe80::2000:bff:fe82:3ac 22
Отслеживание отзывчивости DNS при обработке библиотечных вызовов getaddrinfo()/gethostbyname():
# gethostlatency
TIME
PID
COMM
LATms HOST
06:10:24 28011 wget
90.00 www.iovisor.org
06:10:28 28127 wget
0.00 www.iovisor.org
06:10:41 28404 wget
9.00 www.netflix.com
06:10:48 28544 curl
35.00 www.netflix.com.au
06:11:10 29054 curl
31.00 www.plumgrid.com
06:11:16 29195 curl
3.00 www.facebook.com
06:11:25 29404 curl
72.00 foo
06:11:28 29475 curl
1.00 foo
Суммарные данные о типах операций VFS, обновляемые ежесекундно:
# vfsstat
TIME
READ/s WRITE/s CREATE/s
OPEN/s FSYNC/s
18:35:32:
231
12
4
98
0
18:35:33:
274
13
4
106
0
18:35:34:
586
86
4
251
0
18:35:35:
241
15
4
99
0
Определение вызовов, ожидающих выполнения (off-CPU) в ядре и пространстве пользователя для заданного PID:
# offcputime -d -p 24347
Tracing off-CPU time (us) of PID 24347 by user + kernel stack... Hit Ctrl-C to end.
^C
[...]
ffffffff810a9581 finish_task_switch
ffffffff8185d385 schedule
ffffffff81085672 do_wait
ffffffff8108687b sys_wait4
ffffffff81861bf6 entry_SYSCALL_64_fastpath
--
00007f6733a6b64a waitpid
-
bash (24347)
4952
ffffffff810a9581 finish_task_switch
ffffffff8185d385 schedule
ffffffff81860c48 schedule_timeout
ffffffff810c5672 wait_woken
ffffffff8150715a n_tty_read
ffffffff815010f2 tty_read
ffffffff8122cd67 __vfs_read
ffffffff8122df65 vfs_read
ffffffff8122f465 sys_read
ffffffff81861bf6 entry_SYSCALL_64_fastpath
--
00007f6733a969b0 read
-
bash (24347)
1450908
Отслеживание задержек при выполнении запросов MySQL:
# mysqld_qslower `pgrep -n mysqld`
Tracing MySQL server queries for PID 14371 slower than 1 ms...
TIME(s)
PID
MS QUERY
0.000000
18608
130.751 SELECT * FROM words WHERE word REGEXP '^bre.*n$'
2.921535
18608
130.590 SELECT * FROM words WHERE word REGEXP '^alex.*$'
4.603549
18608
24.164 SELECT COUNT(*) FROM words
9.733847
18608
130.936 SELECT count(*) AS count FROM words WHERE word REGEXP '^bre.*n$'
17.864776
18608
130.298 SELECT * FROM words WHERE word REGEXP '^bre.*n$' ORDER BY word
Использование утилиты multi-tool для слежения за запросами входа в систему, обрабатываемыми через PAM:
# trace 'pam:pam_start "%s: %s", arg1, arg2'
TIME
PID
COMM
FUNC
-
17:49:45 5558
sshd
pam_start
sshd: root
17:49:47 5662
sudo
pam_start
sudo: root
17:49:49 5727
login
pam_start
login: bgregg
