Брендан Грег (Brendan Gregg), один из разработчиков DTrace, считает, что с добавлением в ядро Linux 4.9 хронометрированных выборок (timed sampling), средства для анализа производительности на базе BPF достигли уровня функциональности DTrace. По мнению Брендана Грега, это очень важное достижение и в Linux теперь доступны полноценные средства для анализа производительности приложения и ядра с использованием готовой для промышленного применения системы, создающей минимальную фоновую нагрузку и позволяющей использовать такие расширенные возможности как гистограммы задержек и счётчики частоты.

Отмечается, что несмотря на то, что 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


Источник: http://www.opennet.ru/opennews/art.shtml?num=45391