Средства трассировки в ядре Linux достигли уровня DTrace
Брендан Грег (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
Полный текст статьи читайте на OpenNet
