Bpftrace: Print warning when kretprobe's fail to fire

[ahrens]

Sometimes kretprobe's do not fire, depending on how many threads are currently "inside" the traced function, and the maxactive setting. The kernel tracks how many firings are missed. It would be helpful if bpftrace would print some sort of warning when these events are dropped.

https://www.kernel.org/doc/Documentation/kprobes.txt :

While the probed function is executing, its return address is
stored in an object of type kretprobe_instance. Before calling
register_kretprobe(), the user sets the maxactive field of the
kretprobe struct to specify how many instances of the specified
function can be probed simultaneously. register_kretprobe()
pre-allocates the indicated number of kretprobe_instance objects.

For example, if the function is non-recursive and is called with a
spinlock held, maxactive = 1 should be enough. If the function is
non-recursive and can never relinquish the CPU (e.g., via a semaphore
or preemption), NR_CPUS should be enough. If maxactive <= 0, it is
set to a default value. If CONFIG_PREEMPT is enabled, the default
is max(10, 2*NR_CPUS). Otherwise, the default is NR_CPUS.

It's not a disaster if you set maxactive too low; you'll just miss
some probes. In the kretprobe struct, the nmissed field is set to
zero when the return probe is registered, and is incremented every
time the probed function is entered but there is no kretprobe_instance
object available for establishing the return probe.

[ahrens]

Relatedly, is there a way to specify maxactive? If not, that would be a nice feature to have. It's important to set this correctly if you are using bpftrace to measure performance of heavily multi-threaded workloads.

[ahrens]

Example output today. Workload is random reads from 4x as many threads as there are CPU's. The kretprobe fires 1/4 as many times as the kprobe.

$ sudo bpftrace -e 'kretprobe:zpl_iter_read,kprobe:zpl_iter_read{@[probe]=count();}' -c 'sleep 10'
Attaching 2 probes...


@[kretprobe:zpl_iter_read]: 263207
@[kprobe:zpl_iter_read]: 1037071

I'd like for bpftrace to additionally output something like

kretprobe:zpl_read_iter failed to fire 750,000 times due to insufficient "maxactive".
The "maxactive" setting can be increased by <insert instructions here>.

[danobi]

I took a look at the code. It seems the code path is:

  perf_kprobe_init
    create_local_trace_kprobe
      max_active=0
      __register_trace_kprobe

https://github.com/torvalds/linux/blob/master/kernel/trace/trace_kprobe.c#L1405 is where maxactive is hardcoded to 0.

Since bpftrace uses the perf API, it doesn't look like there's currently a way to specify maxactive. This seems somewhat important to have as part of the API so I'll ask around and see what kind of kernel change is appropriate.

As far as overflow reporting goes, I don't immediately see how it's reported to perf right now (if at all). Will need to study the code later.

[yonghong-song]

cc @liu-song-6 who introduced the original API to see whether API can be extended to include maxactive in perf_event_attr for kretprobe.

[liu-song-6]

Thanks @yonghong-song for the tag.

As @danobi mentioned, currently, there is no way to specify maxactive via perf_kprobe_event_init(). We can probably support it with a few bits from perf_event_attr.config. I guess 8 bits (max of 255) should be sufficient.

There is also an alternative without kernel change here: use the old text-based kprobe API. Of course, with this approach, we lose benefits of the new kprobe API.

[danobi]

256 doesn’t seem too high to me. If 8 bits is the most the api can spare, is there also a way to report overflow count through the perf api?

Happy to write any kernel patches or start mailing list discussions if you’re busy.

[liu-song-6]

We have 31 bits left in perf_event_attr.config, so that's not a problem.

The change should be straightforward. I will get something for test soon.

[liu-song-6]

@danobi Could you please try https://github.com/liu-song-6/linux/tree/maxactive ?

To specify max_active, use the highest 12 bits of perf_event_attr.config. (0 to 4095).

[ahrens]

It's great to see progress on being able to specify maxactive, thank you!

Have y'all given any thought to how bpftrace could retrieve nmissed, and print it with a warning if it's nonzero? That way the user could realize that they might want to increase maxactive.

[danobi]

@ahrens , yeah I have the same concern. I'm worried that b/c # tasks is more or less unrestricted, any limit on max_active is an incomplete solution. I think it would be better if we could report nmissed. @liu-song-6 , does that sound possible?

[liu-song-6]

Maybe we can start with /sys/kernel/debug/tracing/kprobe_profile ?

[yonghong-song]

@liu-song-6 does this (/sys/kernel/debug/tracing/kprobe_profile) work with FD-based kprobe?

[liu-song-6]

@yonghong-song good point... It doesn't work with fd-based kprobe. And we don't want it to work with fd-based kprobes.

I think we will need new ioctl on the fd for this use case.

[yonghong-song]

This seems a viable solution. Thanks!

[liu-song-6]

@danobi would you like to work on the kernel patch to add ioctl for nmissed?

[danobi]

@liu-song-6 sure. I will come bug you about that tomorrow.

[danobi]

I put the patches up on the mailing list. It's also hosted here: https://github.com/danobi/linux/tree/perf_kprobe_ioctl

[danobi]

I've posted the second attempt: https://lore.kernel.org/bpf/[email protected]/T/

[ahrens]

@danobi Thanks for working on this. What's the status on your kernel patch? It looks like there was some discussion in September/October but I didn't see any conclusion.

[ahrens]

@danobi Any update on this?

[danobi]

Ah sorry, notification must have fallen into the void.

I sent a couple versions but then lost track of what PeterZ was talking about. Unfortunately ran out of time to figure it out. I believe this is the most up to date version here: https://github.com/danobi/linux/commits/perf_read_format_missed if anyone has time to pick it up.