Re: [PATCH v5 2/3] perf sched latency: Auto-scale latency and runtime display units

[Namhyung Kim <namhyung@kernel.org>]

On Thu, Jul 30, 2026 at 02:54:15PM -0400, Aaron Tomlin wrote:
> Currently, 'perf sched latency' displays task runtime and delay values
> exclusively in milliseconds (ms). This can be hard to read when
> latencies are very small (in the microsecond or nanosecond range) or
> unusually large (seconds).
> 
> Introduce auto-scaling for latency and runtime display columns. Values
> are dynamically scaled and output with the most appropriate unit:
> nanoseconds (ns), microseconds (us), milliseconds (ms), or seconds (s).
> 
> Additionally, rename column headers from "Runtime ms", "Avg delay ms",
> and "Max delay ms" to "Runtime", "Avg delay", and "Max delay"
> respectively, adjust spacing to maintain column alignment and stripe
> redundant prefix strings from each row's format string to produce a
> clean, tabular output.

It'd be nice if you could include example output when you touched user-
visible area.  Comparing before and after would be great.

Thanks,
Namhyung

> 
> Signed-off-by: Aaron Tomlin <atomlin@atomlin.com>
> ---
>  tools/perf/builtin-sched.c | 42 +++++++++++++++++++++++++++-----------
>  1 file changed, 30 insertions(+), 12 deletions(-)
> 
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index 0abf9f1f3c2e..bfbedd12b346 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -246,6 +246,17 @@ struct perf_sched {
>  	struct perf_data *data;
>  };
>  
> +static int scnprintf_latency_unit(char *buf, size_t size, u64 nsecs)
> +{
> +	if (nsecs < 1000)
> +		return scnprintf(buf, size, "%6" PRIu64 " ns", nsecs);
> +	if (nsecs < NSEC_PER_MSEC)
> +		return scnprintf(buf, size, "%6.3f us", (double)nsecs / NSEC_PER_USEC);
> +	if (nsecs < NSEC_PER_SEC)
> +		return scnprintf(buf, size, "%6.3f ms", (double)nsecs / NSEC_PER_MSEC);
> +	return scnprintf(buf, size, "%6.3f s ", (double)nsecs / NSEC_PER_SEC);
> +}
> +
>  /* per thread run time data */
>  struct thread_runtime {
>  	u64 last_time;      /* time of previous sched in/out event */
> @@ -1405,6 +1416,8 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
>  	int i;
>  	int ret;
>  	u64 avg;
> +	char runtime_lat[32];
> +	char avg_lat[32], max_lat[32];
>  	char max_lat_start[32], max_lat_end[32];
>  
>  	if (!work_list->nb_atoms)
> @@ -1430,14 +1443,17 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
>  		printf(" ");
>  
>  	avg = work_list->total_lat / work_list->nb_atoms;
> +	scnprintf_latency_unit(runtime_lat, sizeof(runtime_lat), work_list->total_runtime);
> +	scnprintf_latency_unit(avg_lat, sizeof(avg_lat), avg);
> +	scnprintf_latency_unit(max_lat, sizeof(max_lat), work_list->max_lat);
>  	timestamp__scnprintf_usec(work_list->max_lat_start, max_lat_start, sizeof(max_lat_start));
>  	timestamp__scnprintf_usec(work_list->max_lat_end, max_lat_end, sizeof(max_lat_end));
>  
> -	printf("|%11.3f ms |%9" PRIu64 " | avg:%8.3f ms | max:%8.3f ms | max start: %12s s | max end: %12s s\n",
> -	      (double)work_list->total_runtime / NSEC_PER_MSEC,
> -		 work_list->nb_atoms, (double)avg / NSEC_PER_MSEC,
> -		 (double)work_list->max_lat / NSEC_PER_MSEC,
> -		 max_lat_start, max_lat_end);
> +	printf(" |%15s |%9" PRIu64 " |%16s |%16s |%20s s |%20s s |\n",
> +	       runtime_lat,
> +	       work_list->nb_atoms, avg_lat, max_lat,
> +	       max_lat_start, max_lat_end);
> +
>  }
>  
>  static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
> @@ -3616,6 +3632,7 @@ static int perf_sched__lat(struct perf_sched *sched)
>  {
>  	int rc = -1;
>  	struct rb_node *next;
> +	char total_runtime_str[32];
>  
>  	setup_pager();
>  
> @@ -3628,9 +3645,9 @@ static int perf_sched__lat(struct perf_sched *sched)
>  	perf_sched__merge_lat(sched);
>  	perf_sched__sort_lat(sched);
>  
> -	printf("\n -------------------------------------------------------------------------------------------------------------------------------------------\n");
> -	printf("  Task                  |   Runtime ms  |  Count   | Avg delay ms    | Max delay ms    | Max delay start           | Max delay end          |\n");
> -	printf(" -------------------------------------------------------------------------------------------------------------------------------------------\n");
> +	printf("\n -----------------------------------------------------------------------------------------------------------------------------------------\n");
> +	printf("  Task                   |    Runtime     |  Count   |    Avg delay    |    Max delay    |      Max delay start  |     Max delay end     |\n");
> +	printf(" -----------------------------------------------------------------------------------------------------------------------------------------\n");
>  
>  	next = rb_first_cached(&sched->sorted_atom_root);
>  
> @@ -3642,11 +3659,12 @@ static int perf_sched__lat(struct perf_sched *sched)
>  		next = rb_next(next);
>  	}
>  
> -	printf(" -----------------------------------------------------------------------------------------------------------------\n");
> -	printf("  TOTAL:                |%11.3f ms |%9" PRIu64 " |\n",
> -		(double)sched->all_runtime / NSEC_PER_MSEC, sched->all_count);
> +	printf(" -----------------------------------------------------------------------------------------------------------------------------------------\n");
> +	scnprintf_latency_unit(total_runtime_str, sizeof(total_runtime_str), sched->all_runtime);
> +	printf("  TOTAL:                 |%15s |%9" PRIu64 " |\n",
> +	       total_runtime_str, sched->all_count);
>  
> -	printf(" ---------------------------------------------------\n");
> +	printf(" -----------------------------------------------------\n");
>  
>  	print_bad_events(sched);
>  	printf("\n");
> -- 
> 2.55.0
>