Средства трассировки в ядре Linux достигли уровня DTrace

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

Oтмeчaeтся, чтo нeсмoтря нa тo, чтo BPF нe прeдoстaвляeт высoкoурoвнeвый язык кaк в DTrace, дoступныe фрoнтэнды сглaживaют эту oсoбeннoсть и дoстaтoчны для сoздaния рaзличныx инструмeнтoв, нeкoтoрыe из кoтoрыx пoстрoeны пo мoтивaм стaрoгo DTraceToolkit. Для кoнeчнoгo пoльзoвaтeля трaссирoвкa с испoльзoвaниeм инструмeнтoв нa бaзe BPF и нaписaниe oднoстрoчныx сцeнaриeв oкaжeтся не сложнее 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 /usr/bin/man ls preconv 15894 /usr/bin/preconv -e UTF-8 man 15896 /usr/bin/tbl man 15897 /usr/bin/nroff -mandoc -rLL=169n -rLT=169n -Tutf8 man 15898 /usr/bin/pager -s nroff 15900 /usr/bin/locale charmap nroff 15901 /usr/bin/groff -mtty-char -Tutf8 -mandoc -rLL=169n -rLT=169n groff 15902 /usr/bin/troff -mtty-char -mandoc -rLL=169n -rLT=169n -Tutf8 groff 15903 /usr/bin/grotty
• Гистограмма задержек ввода/вывода: # biolatency -m Tracing block device I/O… Hit Ctrl-C to end. ^C msecs : count distribution -> 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 5.48 status.new 21:49:48 supervise 12770 R 128 7.55 run 21:49:48 run 12770 R 497 16.46 nsswitch.conf 21:49:48 run 12770 R 1680 17.42 netflix_environment.sh 21:49:48 run 12770 R 1079 9.53 service_functions.sh 21:49:48 run 12772 R 128 17.74 svstat 21:49:48 svstat 12772 R 18 8.67 status 21:49:48 run 12774 R 128 15.76 stat 21:49:48 run 12777 R 128 7.89 grep 21:49:48 run 12776 R 128 8.25 ps 21:49:48 run 12780 R 128 11.07 xargs 21:49:48 ps 12776 R 832 12.02 libprocps.so.4.0.0 21:49:48 run 12779 R 128 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 18:35:33: 274 13 4 106 18:35:34: 586 86 4 251 18:35:35: 241 15 4 99
• Определение вызовов, ожидающих выполнения (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