Я занимаюсь отслеживанием различных функций ядра и системных вызовов и устанавливаю закономерности между ними, которые можно использовать для определенного профилирования производительности.
Одна вещь, которую я заметил, заключается в том, что иногда, даже в моем простом тестовом приложении, которое запускает несколько потоков, играющих с некоторыми мьютексами, я не получаю никаких вызовов 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-server, который выполняет обычные операции с фьютексами даже в состоянии простоя — по крайней мере, на моей машине) многие (часто 10+) futex start печатаются перед сообщением от return probe.
Вот пример трассировки вышеуказанной программы, которую я оставил запущенной на пару минут, пока писал этот пост:
... 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
