Брендан Грег (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