Главная »
2016 »
Октябрь »
30 » Средства трассировки в ядре Linux достигли уровня DTrace
00:23 Средства трассировки в ядре 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
|
|
Просмотров: 170 |
Добавил: muge
| Рейтинг: 0.0/0 |