Почему kretprobe в sys_futex вызывается реже, чем соответствующий kprobe?

Question

Я делаю некоторую трассировку различных функций ядра и системных вызовов и устанавливаю шаблоны между ними, которые можно использовать для определенного профилирования производительности.

Одна вещь, которую я заметил, это то, что иногда, даже в моем простом тестовом приложении, которое раскручивает несколько потоков, которые играют с некоторыми мьютексами, я не получаю никаких вызовов kretprobe__sys_futex, но я бы получил много kprobe__sys_futex,

Я предположил, что это потому, что, например, поток sys_futexи собирается спать или, возможно, завершается, но я на самом деле вижу те же процессы, вызывающие sys_futex несколько раз подряд без обратного зонда, никогда ничего не замечающего.

Я тогда предположил, что проблема была в том, как я фильтровал звонки kprobe__sys_futexИтак, я сделал минимальный пример, используя BCC/eBPF для проверки этого:

#! /usr/bin/env python

from bcc import BPF

b = BPF(text="""
BPF_HASH(call_count, int, int);

int kprobe__sys_futex() {
  int zero = 0;
  call_count.lookup_or_init(&zero, &zero);
  bpf_trace_printk("futex start\\n");
  call_count.increment(zero);
  return 0;
}

int kretprobe__sys_futex() {
  int zero = 0;
  int *val_p = call_count.lookup(&zero);
  if (val_p != NULL) {
      int val = *val_p;
      val--;
      call_count.update(&zero, &val);
      bpf_trace_printk("futex calls with no return: %d\\n", val);
  } else { bpf_trace_printk("unexpected futex return\\n"); }
  return 0;
}
""")

b.trace_print()

Я замечаю, что во всех видах приложений (хорошим примером является mysql-сервер, который выполняет обычные операции futex даже в режиме ожидания - по крайней мере, на моей машине), многие (часто более 10) futex starts печатаются перед сообщением от датчика возврата.

Вот пример трассировки вышеупомянутой программы, которую я оставил запущенной на пару минут, пока писал этот пост:

... hundreds of lines of much the same as below
           gdbus-612   [001] .... 211229.997665: 0x00000001: futex start
  NetworkManager-541   [001] .... 211229.997667: 0x00000001: futex start
           gdbus-612   [001] .... 211229.997670: 0x00000001: futex start
          mysqld-697   [001] .... 211230.789205: 0x00000001: futex start
          mysqld-697   [001] .... 211230.789227: 0x00000001: futex start
          mysqld-703   [001] .... 211230.789251: 0x00000001: futex start
          mysqld-703   [001] .... 211230.789253: 0x00000001: futex start
          mysqld-704   [001] d... 211230.789258: 0x00000001: futex calls with no return: 3994
          mysqld-704   [001] .... 211230.789259: 0x00000001: futex start
          mysqld-704   [001] d... 211230.789260: 0x00000001: futex calls with no return: 3994
          mysqld-704   [001] .... 211230.789272: 0x00000001: futex start
          mysqld-713   [000] .... 211231.037016: 0x00000001: futex start
          mysqld-713   [000] .... 211231.037036: 0x00000001: futex start
         vmstats-895   [000] .... 211231.464867: 0x00000001: futex start
          mysqld-697   [001] .... 211231.790738: 0x00000001: futex start
          mysqld-697   [001] .... 211231.790784: 0x00000001: futex start
          mysqld-703   [001] .... 211231.790796: 0x00000001: futex start
          mysqld-703   [001] .... 211231.790799: 0x00000001: futex start
          mysqld-704   [001] d... 211231.790809: 0x00000001: futex calls with no return: 4001
          mysqld-704   [001] .... 211231.790812: 0x00000001: futex start
          mysqld-704   [001] d... 211231.790814: 0x00000001: futex calls with no return: 4001

Как вы можете видеть, например, pid 697, похоже, вызвал sys_futex четыре раза, не возвращаясь в этот маленький след.

Я не думаю, что это условие гонки в коде eBPF, потому что, если вы выключаете операторы печати и печатаете только периодически, счетчик обычно ограничен несколькими вокруг нуля для sys_write, что случается на величины чаще, чем sys_futex (по крайней мере, на нагрузку моей системы), поэтому я ожидал бы, что любые условия гонки будут усугублены, а не решены.

Я использую Kernel 4.15.0-43-generic на Ubuntu 18.04 LTS, который находится в VirtualBox.

Рад предоставить больше контекста, который может быть полезным!

В списке рассылки IOVisor есть ветка, которая актуальна: https://lists.iovisor.org/g/iovisor-dev/topic/29702757

Answer 1

Это известное ограничение BCC (см. Iovisor / bcC# 1072). По сути, максимальное количество активных проб задано слишком низким для контекста трассировки, и поэтому вы пропускаете некоторые пробники возврата.

В ОЦК, maxactive Значение (максимальное количество активных зондов, см. выдержку из документации ниже) остается равным значению по умолчанию. Поскольку патч Alban Crequy для ядра Linux (см. Iovisor / bcC# 1072), можно изменить maxactive значение при подключении зондов через debugfs. Этот новый API еще не был выставлен через bcc. Я постараюсь отправить патч на этот счет на этой неделе.

Во время выполнения зондируемой функции ее адрес возврата сохраняется в объекте типа kretprobe_instance. Перед вызовом register_kretprobe() пользователь устанавливает максимальное поле структуры kretprobe, чтобы указать, сколько экземпляров указанной функции может быть проверено одновременно. register_kretprobe() предварительно выделяет указанное количество объектов kretprobe_instance.

Например, если функция нерекурсивная и вызывается с удерживаемой спин-блокировкой, maxactive = 1 должно быть достаточно. Если функция нерекурсивна и никогда не может освободить процессор (например, через семафор или выгрузку), NR_CPUS должно быть достаточно. Если maxactive <= 0, это значение по умолчанию. Если включено CONFIG_PREEMPT, по умолчанию используется максимальное значение (10, 2*NR_CPUS). В противном случае по умолчанию используется NR_CPUS.