iovisor / iovisor/bcc

probe detach with many probes is slow (funccount)

Open
#1,317 2 comments 0 reactions 0 assignees View on GitHub
Dominant language
C
Stars
22.7k
Forks
4.1k
Avg merge
5d 13h
Merged PRs (30d)
3

Description

We've discussed this before, but I'm not sure we wrote anything down anywhere. So I'll create a ticket.

funccount with hundreds of probes takes tens of seconds to detach them. It gets annoying.

I wanted a CPU flame graph to see where in the kernel we were, but perf can't sample this CPU time (because we're in a scheduler lock? I haven't dug in as to why). I used ad hoc sampling of /proc/PID/stack instead to generate this wall-time flame graph:

![screen shot 2017-08-23 at 3 52 05 pm](https://user-images.githubusercontent.com/1101211/29641968-0c018914-881b-11e7-8cd4-75258828658a.png)

According to that, the time is all in synchronize_sched() (both on- and off-CPU). I imagine part of the problem is that we detach the probes one by one, so we end up in this path hundreds of times.

## Baseline

Here's tracing ext4 functions with a duration of 0 seconds, so the time measured is just setup and tear down:

```
# time ./funccount.py -d 0 'ext4_*' > /dev/null

real 0m40.703s
user 0m1.310s
sys 0m11.159s
```

That took 40 seconds. 28 of which it was blocked, off-CPU (synchronize_sched()).

## Offlining CPUs

Just as an experiment, I added this just before the exit, to turn off all CPUs on this 8 CPU system, except one:

```
os.system("for c in `seq 1 7`; do echo 0 > /sys/devices/system/cpu/cpu$c/online; done")
```

Now I get:

```
# time ./funccount.py -d 0 'ext4_*' > /dev/null

real 0m10.765s
user 0m1.191s
sys 0m8.935s
```

About 7 seconds of that is startup. So it's improved tear-down from 33 seconds to 3.

I'm not suggesting we have libbcc offline CPUs during detach, just measuring the magnitude of the RCU issue.

## Expedited RCUs

As another experiment with synchronize_sched(), I tried using expedited RCUs (after making sure my CPUs were back online):

```
echo 1 > /sys/kernel/rcu_expedited
```

Which brings it down to:

```
# time ./funccount.py -d 0 'ext4_*' > /dev/null

real 0m12.495s
user 0m1.242s
sys 0m11.207s
```

Pretty good. Should we set this, or should disable_track_kprobe() use synchronize_sched_expedited()? I'm not yet sure. (Might be a question for Paul E. McKenney).

Just looking at those numbers, it's letting bcc do the detach work without blocking. Compare those times to the baseline run, where 70% of the time is blocked off-CPU.

## Multiple detach

Another option of course is to have libbcc do multiple detach, instead of one by one.

Contributor guide

No contributing guide indexed for this repository

Research direction

Start with funccount.py and the libbcc detach path, especially disable_track_kprobe() and the synchronize_sched() calls discussed. Reproduce the timed ext4_* run with -d 0, then compare teardown time for hundreds of probes. Done means substantially faster detachment without relying on CPU offlining or globally enabling expedited RCU.

Written by the indexing model from the issue text.

Assessment

Tech stack
c, linux, python
Domain
observability-sre, operating-systems, tooling
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.