Re: [PATCH bpf-next] bpftool: Print average cycles per program run in profiler

[Mykyta Yatsenko <mykyta.yatsenko5@gmail.com>]

On 8/28/26 7:46 PM, Suchit Karunakaran wrote:
> Hi,
> 
> On 8/27/26 8:59 PM, Mykyta Yatsenko wrote:
>> From: Mykyta Yatsenko <yatsenko@meta.com>
>>
>> Total cycle counts are difficult to compare across workloads with
>> different run counts. Report cycles per run to expose the per-invocation
>> cost directly.
>>
>> Example:
>> sudo ./bpftool prog profile name mprog duration 15 cycles instructions
>>
>>              423256 run_cnt
>>           947413975 cycles              #  2238.39 cycles per run
>>           333965846 instructions        #     0.35 insns per cycle
>>
>> Signed-off-by: Mykyta Yatsenko <yatsenko@meta.com>
>> ---
>>   tools/bpf/bpftool/Documentation/bpftool-prog.rst |  6 ++++--
>>   tools/bpf/bpftool/prog.c                         | 18 +++++++++++-------
>>   2 files changed, 15 insertions(+), 9 deletions(-)
>>
>> diff --git a/tools/bpf/bpftool/Documentation/bpftool-prog.rst b/tools/bpf/bpftool/Documentation/bpftool-prog.rst
>> index 90fa2a48cc26..2280dc4492c0 100644
>> --- a/tools/bpf/bpftool/Documentation/bpftool-prog.rst
>> +++ b/tools/bpf/bpftool/Documentation/bpftool-prog.rst
>> @@ -217,7 +217,9 @@ bpftool prog run *PROG* data_in *FILE* [data_out *FILE* [data_size_out *L*]] [ct
>>   bpftool prog profile *PROG* [duration *DURATION*] *METRICs*
>>       Profile *METRICs* for bpf program *PROG* for *DURATION* seconds or until
>>       user hits <Ctrl+C>. *DURATION* is optional. If *DURATION* is not specified,
>> -    the profiling will run up to **UINT_MAX** seconds.
>> +    the profiling will run up to **UINT_MAX** seconds. When **cycles** is
>> +    selected, plain output also reports the average number of cycles per
>> +    program run.
>>     bpftool prog help
>>       Print short help message.
>> @@ -360,7 +362,7 @@ EXAMPLES
>>   ::
>>              51397 run_cnt
>> -      40176203 cycles                                                 (83.05%)
>> +      40176203 cycles          # 781.68 cycles per run                (83.05%)
>>         42518139 instructions    #   1.06 insns per cycle               (83.39%)
>>              123 llc_misses      #   2.89 LLC misses per million insns  (83.15%)
>>   diff --git a/tools/bpf/bpftool/prog.c b/tools/bpf/bpftool/prog.c
>> index a9f730d407a9..8935508f955b 100644
>> --- a/tools/bpf/bpftool/prog.c
>> +++ b/tools/bpf/bpftool/prog.c
>> @@ -2069,9 +2069,9 @@ struct profile_metric {
>>       bool selected;
>>         /* calculate ratios like instructions per cycle */
>> -    const int ratio_metric; /* 0 for N/A, 1 for index 0 (cycles) */
>> +    const int ratio_metric; /* 0 for run_cnt, 1 for index 0 (cycles) */
>>       const char *ratio_desc;
>> -    const float ratio_mul;
>> +    const double ratio_mul;
>>   } metrics[] = {
>>       {
>>           .name = "cycles",
>> @@ -2080,6 +2080,9 @@ struct profile_metric {
>>               .config = PERF_COUNT_HW_CPU_CYCLES,
>>               .exclude_user = 1,
>>           },
>> +        .ratio_metric = 0,
>> +        .ratio_desc = "cycles per run",
>> +        .ratio_mul = 1.0,
>>       },
>>       {
>>           .name = "instructions",
>> @@ -2256,17 +2259,18 @@ static void profile_print_readings_plain(void)
>>       for (m = 0; m < ARRAY_SIZE(metrics); m++) {
>>           struct bpf_perf_event_value *val = &metrics[m].val;
>>           int r;
>> +        __u64 ratio;
>>             if (!metrics[m].selected)
>>               continue;
>>           printf("%18llu %-20s", val->counter, metrics[m].name);
>>   -        r = metrics[m].ratio_metric - 1;
>> -        if (r >= 0 && metrics[r].selected &&
>> -            metrics[r].val.counter > 0) {
>> +        r = metrics[m].ratio_metric;
>> +        /* r == 0 is a special case for run_cnt */
>> +        ratio = r ? metrics[r - 1].val.counter : profile_total_count;
>> +        if (metrics[m].ratio_desc && ratio) {
>>               printf("# %8.2f %-30s",
>> -                   val->counter * metrics[m].ratio_mul /
>> -                   metrics[r].val.counter,
>> +                   val->counter * metrics[m].ratio_mul / ratio,
>>                      metrics[m].ratio_desc);
>>           } else {
>>               printf("%-41s", "");
>>
>> ---
>> base-commit: 23ff631b3b8b1452dfe933ee21f96321a9c5e209
>> change-id: 20260827-bpftool_cyles_per_run-93169fcb30b7
>>
>> Best regards,
>> -- 
>> Mykyta Yatsenko <yatsenko@meta.com>
>>
> I think val->counter be normalized for counter multiplexing before dividing by profile_total_count? val->counter contains only the cycles observed while the event was actively scheduled on the PMU, whereas profile_total_count reflects all program invocations across the full duration. When val->running < val->enabled, dividing raw val->counter by profile_total_count undercounts the true cycles per run. Should we apply scaling before computing the ratio like below?
> if (val->running > 0) {
>     double scaled = (double)val->counter * val->enabled / val->running;
>     double cycles_per_run = scaled / profile_total_count;
> }
> 
> We can actually see this in the example:
> 
> 51397 run_cnt
> 40176203 cycles          # 781.68 cycles per run (83.05%)
> Here, 781.68 uses the raw unscaled count during the 83.05% runtime window. If we scale it to 100% estimated coverage, the true cost is closer to ~941.22 cycles per run.
> 

Not sure if it's a good idea to scale just this metric. 
I understand the existing metrics and ratios have the same problem. 
I think we should scale all or none.

bpftool on its own does not use too many PMUs, so most of the time
this problem should not manifest: it only bites when other profiler
is running in parallel. Andrii, Quentin any thoughts on this problem?