Bpftrace: probes should have a default action if none are specified

[tyroguru]

Probes should have a default action if one isn't specified as it's super convenient when you just want to see if a particular probe site is being hit. At the minute if no actions are given we get an error:

#  bpftrace.232 -e 'tracepoint:syscalls:sys_enter_futex'
1.36: syntax error, unexpected end of file, expecting {

We should be able to do something like DTrace does:

bash-3.2# dtrace -n 'syscall::write:entry'
dtrace: description 'syscall::write:entry' matched 1 probe
CPU     ID                    FUNCTION:NAME
  2    160                      write:entry
  2    160                      write:entry
  1    160                      write:entry

[brendangregg]

Yes, I'd already been thinking of a few things to do.

Here's ftrace's default fields:

# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     device poll-29591 [003] .... 274199.143624: do_nanosleep: (do_nanosleep+0x0/0x190)
     device poll-29591 [007] .... 274200.144759: do_nanosleep: (do_nanosleep+0x0/0x190)
     device poll-29591 [003] .... 274201.145933: do_nanosleep: (do_nanosleep+0x0/0x190)

And perf script's default fields (on 4.15):

            Xorg  1458 [006] 274032.138767:          1 cs:  ffffffffbad97e7c schedule ([kernel.kallsyms])
         swapper     0 [001] 274032.138790:          1 cs:  ffffffffbad98132 schedule_idle ([kernel.kallsyms])
            perf 18709 [007] 274032.138819:          1 cs:  ffffffffbad97e7c schedule ([kernel.kallsyms])
            perf 18712 [001] 274032.138876:          1 cs:  ffffffffbad98097 _cond_resched ([kernel.kallsyms])
         swapper     0 [002] 274032.138882:          1 cs:  ffffffffbad98132 schedule_idle ([kernel.kallsyms])

I'd like to see something like:

COMM PID TID [CPU] TIMESTAMP: NAME

Which would be very similar to ftrace/perf. I'm not suggesting this because it's ftrace/perf, but rather, ftrace/perf have evolved for years and I know their default outputs are proven for addressing a variety of problems. The big thing missing with them both was having both PID & TID output by default, so I added them both above.

[brendangregg]

I should add: since we're using the perf_event_open ring buffers to pass per-event data from kernel to user, perf may already have most of these fields in the metadata for each event. If so (I haven't dug in), it'd be more efficient to use whatever we can from the metadata that's already included, before fetching things in BPF.

[jasonkeene]

I am in favor of this but are you worried at all that someone might forget to add a comma with multiple probes?

otherProbe
/filter/
{
    // aggregation logic
}

Many examples put each probe and filter on their own line. If this were the case forgetting the comma would be a valid program where highFrequencyProbe fires for each event and outputs data that is written to stdout. That seems like a land mine waiting to blow up on someone.

I suppose it would be immediately noticeable and you would then kill the program.

[brendangregg]

I've had an idea: I don't want per-event output to be the default. Like Jason said, that can be a landmine if you trace something more frequent than you were expecting, or did so by accident. I'm really starting all my ad hoc perf investigations using funccount. Why not make that the default behavior? I'm using it first anyway, and it does a summary, not per-event output.

It would mean these are equivalent:

bpftrace -e 'kprobe:vfs_read { @[probe] = count(); }'
bpftrace -e 'kprobe:vfs_read'

If a program is not specified, it defaults to "{ @[probe] = count(); }".

As for a nice per-event summary, we may get that through #381.

[tyroguru]

This is only really a problem because bpftrace doesn't have a buffer management scheme which is quite a serious problem and causes issues in various ways. Obviously, the inability to interrupt consuming trace output from a high frequency probe is quite a serious shortcoming at the minute.

The thing that would concern me about adding syntactic sugar to give this aggregation count as a default action is that I would have to explicitly do something to get that output - either or put on interval probe in there. Quite often I just want to see if a probe has fired and I should be able to get that with the simplest form of a bpftrace invocation (e.g., uprobe:/path/func).

[brendangregg]

bpftrace uses perf's buffers, which have capabilities we aren't fully using yet -- they can do dynamic wakeups so that instead of blindly picking a switch rate (10 Hz) it will wake up an appropriate number of times for the workload. See the number of wakeups reported in perf report. So awesome. They also have ring buffers and other capabilities, and a fixed rate of wakeups can be choosen as well. There's a ton we can do, we just haven't yet because I've had zero need for this during my production use. As soon as there's a compelling production use case to add buffer management, we'll add it.

Bear in mind: bpftrace is designed for a system that already has perf(1). perf(1) isn't going away, it lives in the Linux tree. If the use case is: I need to trace and dump these probes/tracepoints for later analysis, even though they are high frequency, then perf has already optimized that with its binary output format and dynamic user-level wakeups.

There is no inability to interrupt trace output. You can Ctrl-C. It's just annoying.

I get what you mean about visual feedback, but I'd really want a way to use wildcards without worrying about the printf() flood. Imagine if it worked like this:

# bpftrace -e 'kprobe:vfs_*'
Attaching 54 probes...
First probe fired (kprobe:vfs_read). Now counting. Ctrl-C for summary.
^C
@[kprobe:vfs_statfs]: 3
@[kprobe:vfs_readlink]: 3
@[kprobe:vfs_fsync_range]: 5
@[kprobe:vfs_lock_file]: 9
@[kprobe:vfs_statx_fd]: 49
@[kprobe:vfs_writev]: 103
@[kprobe:vfs_getattr_nosec]: 170
@[kprobe:vfs_getattr]: 171
@[kprobe:vfs_open]: 189
@[kprobe:vfs_statx]: 231
@[kprobe:vfs_write]: 594
@[kprobe:vfs_read]: 1774

So you get a line for the first fired probe, so you know that something is happening.

[brendangregg]

@tyroguru build on the latest (to include -B and r), and try this:

bpftrace -B none -e 'BEGIN { @epoch = nsecs; printf("Tracing... Ctrl-C for probe hit counts.\n"); } k:vfs_r* { printf("        \r%d ms %s", (nsecs - @epoch) / 1000000, probe); @[probe] = count(); } END { delete(@epoch); }'

[brendangregg]

update: this proof-of-concept one-liner is now:

bpftrace -B none -e 'BEGIN { printf("Tracing... Ctrl-C for probe hit counts.\n"); }
    k:vfs_r* { printf("        \r%d ms %s", elapsed / 1000000, probe); @[probe] = count(); }'

and the proposal is that this is what would happen if you ran:

bpftrace -e 'k:vfs_r*'

[tyroguru]

I didn't think this issue had been addressed and I don't have an older version to test previous behavior but I think the current behavior is different to what it was. Now if give a probe to enable with braces but nothing in the block then the probe is enabled but nothing happens:

# bpftrace -e 'tracepoint:syscalls:sys_enter_futex{}'
Attaching 1 probe...

Has this always been the case?

[brendangregg]

I don't know. It kind-of makes sense: you provided an action with nothing in it.

On the other hand, if you don't provide an action at all (no {}) then we should do our default behavior. Did you try my proof-of-concept?