Re: [RFC bpf-next 3/4] bpftool: introduce "prog profile" command

[Song Liu <songliubraving@fb.com>]

> On Feb 14, 2020, at 4:45 PM, Alexei Starovoitov <alexei.starovoitov@gmail.com> wrote:
> 
> On Thu, Feb 13, 2020 at 01:01:14PM -0800, Song Liu wrote:
>> With fentry/fexit programs, it is possible to profile BPF program with
>> hardware counters. Introduce bpftool "prog profile", which measures key
>> metrics of a BPF program.
>> 
>> bpftool prog profile command creates per-cpu perf events. Then it attaches
>> fentry/fexit programs to the target BPF program. The fentry program saves
>> perf event value to a map. The fexit program reads the perf event again,
>> and calculates the difference, which is the instructions/cycles used by
>> the target program.
>> 
>> Example input and output:
>> 
>>  ./bpftool prog profile 20 id 810 cycles instructions
>>  cycles: duration 20 run_cnt 1368 miss_cnt 665
>>          counter 503377 enabled 668202 running 351857
>>  instructions: duration 20 run_cnt 1368 miss_cnt 707
>>          counter 398625 enabled 502330 running 272014
>> 
>> This command measures cycles and instructions for BPF program with id
>> 810 for 20 seconds. The program has triggered 1368 times. cycles was not
>> measured in 665 out of these runs, because of perf event multiplexing
>> (some perf commands are running in the background). In these runs, the BPF
>> program consumed 503377 cycles. The perf_event enabled and running time
>> are 668202 and 351857 respectively.
> 
> if (diff.enabled > diff.running) increment miss_cnt.
> Why show this to users?
> I think 'miss_cnt' the users will interpret as data is bogus,
> but it only means that the counter was multiplexed.
> The data is still accurate, no?

We (or the user) need to be careful to get all the math correct:

For # of run per second, we need total count;
For cycles per run, we need non-miss-count (total_count - miss_cnt). 

So miss_cnt is useful for some users. 

One thing tricky here is that different events in the same session may 
have different miss_cnt. I just realized that we can probably avoid most 
of such cases, and only take samples when all the counters are counting. 

> This condition will probably be hit fairly often, no?

This really depends on the system. Data center servers usually have a 
few perf_event running 24/7. We are more likely to hit multiplexing on
these systems. 

> 
>> tools/bpf/bpftool/profiler.skel.h         | 820 ++++++++++++++++++++++
> 
> I think bpftool needs to be build twice to avoid this.
> 
> Could you change the output format to be 'perf stat' like:
>         55,766.51 msec task-clock                #    0.996 CPUs utilized
>             4,891      context-switches          #    0.088 K/sec
>                31      cpu-migrations            #    0.001 K/sec
>         1,806,065      page-faults               #    0.032 M/sec
>   166,819,295,451      cycles                    #    2.991 GHz                      (50.12%)
>   251,115,795,764      instructions              #    1.51  insn per cycle           (50.10%)

Will try this in next version. 

> 
> Also printing 'duration' is unnecessary. The user specified it at the command
> line and it doesn't need to be reported back to the user.
> Can you also make it optional? Until users Ctrl-C's bpftool ?

Yes, I plan to add the Ctrl-C approach. Even with a duration, user can still 
hit Ctrl-C and get partial results. I guess, we should show the duration for 
when user Ctrl-C?

> So it may look like:
> $ ./bpftool prog profile id 810 cycles instructions
>             1,368      run_cnt
>           503,377      cycles
>           398,625      instructions         # 0.79 insn per cycle
> 
> Computing additional things like 'insn per cycle' do help humans to
> pay attention the issue. Like <1 ipc is not great and the next step
> would be to profile this program for cache misses.

Yes, instruction per cycle is useful. Let me add that.