Можно ли использовать eBPF или perf для расчета времени, затрачиваемого на отдельные отслеживаемые функции?

В настоящее время я могу сказать trace-cmd (внешний интерфейс ftrace) использовать инфраструктуру графа функций ftrace для трассировки указанной рабочей нагрузки. Используя некоторые инструменты обработки данных трассировки, я могу просмотреть частоту вызова функций и соответствующую общую продолжительность каждого вызова функции. Пример вывода может выглядеть следующим образом, где я отслеживаю вызовы функций ext4, сгенерированные моей рабочей нагрузкой:

# trace-cmd post-processing example output
# function name, frequency, total duration (us)
ext4_alloc_inode(),1,35.567
ext4_read_inode_bitmap(),1,12.076
ext4_init_io_end(),2,41.216
ext4_journal_check_start(),39,716.3
ext4_da_write_end(),10,102.661
ext4_da_get_block_prep(),9,257.46999999999997
ext4_block_write_begin(),2,88.069
ext4_bio_write_page(),1,33.016

Я видел невероятные графики пламени, которые можно создать с помощью eBPF, systemtap, perf. , и т. д., которые заставили меня поверить, что я смогу добиться вывода, аналогичного моему выводу trace-cmd, используя perf или eBPF. Однако есть несколько препятствий:

  1. Моя рабочая нагрузка может длиться до 15 минут, что может привести к созданию огромных журналов, если я буду использовать perf. Для справки вы можете просмотреть пример вывода, который отслеживает bash гораздо дешевле. время.
  2. Я недостаточно хорошо знаком с eBPF, чтобы определить, могу ли я получить такие же данные/вывод, как в моем примере постобработки trace-cmd.

Для тех из вас, кто знаком с eBPF или perf лучше, чем я, я хотел бы знать:

  • Можно ли использовать eBPF или perf для достижения моей цели?
  • Если да, то почему это возможно?

Если вы чувствуете себя особенно щедрым, буду признателен за примеры кода/команд, которые помогут мне достичь моей цели.


person buratino    schedule 30.10.2017    source источник


Ответы (1)


Безусловно, для этого можно использовать eBPF.

На самом деле есть инструмент, который делает что-то подобное в инструментах скрытой копии. funclatency отслеживает набор функций и отображает гистограмму их задержек (время пребывания в функции при каждом вызове):

# ./funclatency do_sys_open
Tracing do_sys_open... Hit Ctrl-C to end.
^C
     nsecs           : count     distribution
       0 -> 1        : 0        |                                      |
       2 -> 3        : 0        |                                      |
       4 -> 7        : 0        |                                      |
       8 -> 15       : 0        |                                      |
      16 -> 31       : 0        |                                      |
      32 -> 63       : 0        |                                      |
      64 -> 127      : 0        |                                      |
     128 -> 255      : 0        |                                      |
     256 -> 511      : 0        |                                      |
     512 -> 1023     : 0        |                                      |
    1024 -> 2047     : 0        |                                      |
    2048 -> 4095     : 124      |****************                      |
    4096 -> 8191     : 291      |**************************************|
    8192 -> 16383    : 36       |****                                  |
   16384 -> 32767    : 16       |**                                    |
   32768 -> 65535    : 8        |*                                     |
   65536 -> 131071   : 0        |                                      |
  131072 -> 262143   : 0        |                                      |
  262144 -> 524287   : 0        |                                      |
  524288 -> 1048575  : 0        |                                      |
 1048576 -> 2097151  : 0        |                                      |
 2097152 -> 4194303  : 1        |                                      |
Detaching...

Начиная с функлатенции, довольно легко получить инструмент, который делает то, что вы ищете:

from __future__ import print_function
from bcc import BPF
from time import sleep, strftime
import argparse

parser = argparse.ArgumentParser(
    description="Time functions and print time spent in each function",
    formatter_class=argparse.RawDescriptionHelpFormatter)
parser.add_argument("-p", "--pid", type=int, help="trace this PID only")
parser.add_argument("pattern", help="search expression for functions")
args = parser.parse_args()

# define BPF program
bpf_text = """
#include <uapi/linux/ptrace.h>

struct stats_t {
    u64 time;
    u64 freq;
};
BPF_HASH(start, u32);
BPF_HASH(ipaddr, u32);
BPF_HASH(stats, u64, struct stats_t);

int trace_func_entry(struct pt_regs *ctx)
{
    u64 pid_tgid = bpf_get_current_pid_tgid();
    u32 pid = pid_tgid;
    u64 ts = bpf_ktime_get_ns();

    u64 ip = PT_REGS_IP(ctx);
    ipaddr.update(&pid, &ip);
    start.update(&pid, &ts);

    return 0;
}

int trace_func_return(struct pt_regs *ctx)
{
    u64 *tsp, delta;
    u64 pid_tgid = bpf_get_current_pid_tgid();
    u32 pid = pid_tgid;

    // calculate delta time
    tsp = start.lookup(&pid);
    if (tsp == 0) {
        return 0;   // missed start
    }
    delta = bpf_ktime_get_ns() - *tsp;
    start.delete(&pid);

    // store as histogram
    u64 ip, *ipp = ipaddr.lookup(&pid);
    if (ipp) {
        ip = *ipp;
        struct stats_t *stat = stats.lookup(&ip);
        if (stat) {
            stat->time += delta;
            stat->freq++;
        } else {
            struct stats_t s = {};
            s.time = delta;
            s.freq = 1;
            stats.update(&ip, &s);
        }
        ipaddr.delete(&pid);
    }

    return 0;
}
"""

# load BPF program
b = BPF(text=bpf_text)
pattern = args.pattern.replace('*', '.*')
pattern = '^' + pattern + '$'
b.attach_kprobe(event_re=pattern, fn_name="trace_func_entry")
b.attach_kretprobe(event_re=pattern, fn_name="trace_func_return")
matched = b.num_open_kprobes()

if matched == 0:
    print("0 functions matched by \"%s\". Exiting." % args.pattern)
    exit()
# header
print("Tracing %d functions for \"%s\"... Hit Ctrl-C to end." %
    (matched / 2, args.pattern))

while (1):
    try:
        sleep(99999999)
    except KeyboardInterrupt:
        break

print()
print("%-36s %8s %16s" % ("FUNC", "COUNT", "TIME (nsecs)"))
stats = b.get_table("stats")
for k, v in stats.items():
    print("%-36s %8s %16s" % (BPF.sym(k.value, -1), v.freq, v.time))

Этот инструмент использует BPF для вычисления частоты и общей продолжительности каждого вызова функции непосредственно в ядре. Агрегированные значения копируются в пользовательское пространство только в конце перед их отображением. Выход:

# ./time-spent do_sys_*
Tracing 6 functions for "do_sys_*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT     TIME (nsecs)
do_sys_poll                              6783     213928440379
do_sys_open                              3127         43172656
do_sys_ftruncate.constprop.15              39           189623

Это решение использует bcc для загрузки программ BPF в ядре, но также можно делать все на C. docs/tutorial_bcc_python_developer.md" rel="noreferrer">начните работу с скрытой копией в репозитории.

person pchaigno    schedule 31.10.2017