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

[Suchit Karunakaran <magneto712003@gmail.com>]

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.