On Fri, Feb 08, 2019 at 01:49:44PM -0800, Ashley wrote: > Hi Paul, > > Thanks for the prompt and detailed response! I hadn't considered trying it > with a kernel module, but I set one up to measure this as per your > suggestion, and -- almost frustratingly -- it seems to catch them all. > > Here's output from the kernel module: > [ 2130.067718] sys_futex returned 1 and took 6419 ns to execute 372 task 6920 > [ 2130.067829] sys_futex returned 0 and took 500407745 ns to execute 376 task > 6921 > [ 2130.567894] sys_futex returned 1 and took 6279 ns to execute 380 task 6921 > [ 2130.567923] sys_futex returned 1 and took 3998 ns to execute 381 task 6921 > [ 2130.567925] sys_futex returned 0 and took 500442358 ns to execute 381 task > 6920 > [ 2130.568043] sys_futex returned 0 and took 1000852410 ns to execute 385 > task 6922 > [ 2131.174619] sys_futex returned 0 and took 779 ns to execute 399 task 6922 > [ 2131.174713] sys_futex returned 1 and took 5393 ns to execute 400 task 6922 > [ 2131.174887] sys_futex returned 0 and took 607250418 ns to execute 403 task > 6920
What's the source code of that kernel module? > > And here's my output from my eBPF program: > ashley@ashley-VirtualBox ~/4/e> cat test | grep "FUTEX <<" > main-6921 [000] .... 2129.844847: 0x00000001: FUTEX << > main-6922 [000] .... 2129.844870: 0x00000001: FUTEX << > main-6920 [000] .... 2130.344893: 0x00000001: FUTEX << > main-6920 [000] .... 2130.344906: 0x00000001: FUTEX << > main-6921 [000] .... 2130.845068: 0x00000001: FUTEX << > main-6921 [000] .... 2130.845102: 0x00000001: FUTEX << > main-6920 [000] .... 2130.845113: 0x00000001: FUTEX << > main-6922 [000] .... 2131.451799: 0x00000001: FUTEX << > main-6922 [000] .N.. 2131.451887: 0x00000001: FUTEX << > ashley@ashley-VirtualBox ~/4/e> cat test | grep ">> FUTEX" > main-6921 [000] d... 2130.345015: 0x00000001: >> FUTEX > main-6922 [000] d... 2130.845228: 0x00000001: >> FUTEX > > So my eBPF program received all 9 futex calls as expected, but only 2 > returns, whereas the kernel module successfully gets all of them consistently. > > I'm also able to accurately track k[ret]probes for sys_write and sys_read > through eBPF, even though they seem to happen in higher density on my system. > The problem still occurs even if I don't use bpf_trace_printk within the > retprobe also. Weird, I have the same problem you have for sys_futex if I adapt the script to track sys_write instead... > > Any ideas where might be a good place to look from here? I'm totally stumped; > it's quite tempting to just migrate my code to kernel modules, but everything > else I'm instrumenting seems to work perfectly in eBPF, so it'd be a shame to > do that. I'm thinking it could be caused by a difference in kprobes configuration between the kernel module and bcc. > > Best, > Ashley Paul -=-=-=-=-=-=-=-=-=-=-=- Links: You receive all messages sent to this group. View/Reply Online (#1573): https://lists.iovisor.org/g/iovisor-dev/message/1573 Mute This Topic: https://lists.iovisor.org/mt/29702757/21656 Group Owner: [email protected] Unsubscribe: https://lists.iovisor.org/g/iovisor-dev/unsub [[email protected]] -=-=-=-=-=-=-=-=-=-=-=-
