[RFC PATCH] perf sched latency: Add histogram and time interval options

[RFC PATCH] perf sched latency: Add histogram and time interval options

[Aaron Tomlin]

While 'perf sched latency' reports task runtime and delay statistics
(average and maximum delay), it does not provide a visual representation
of how task wait times are distributed across latency ranges between
snapshots (start and finish of the analysis window).

The --histogram option collects CPU wait latencies (time between when
a task becomes runnable and when it gets scheduled onto a CPU) into 22
latency buckets, displaying an ASCII bar chart distribution.

The --hist-mode option configures the bucketing scheme:
  - log (default). Logarithmic latency buckets ranging from
    sub-microsecond (< 1 us) up to >= 1.05 seconds

  - linear. Equal-width linear latency buckets
    (i.e., 100 us steps up to >= 2.1 ms)

The --time option allows filtering trace event processing to a
specific time interval [start,stop].

Example histogram output excerpt:

    ❯ sudo perf sched latency --histogram --CPU 0

     CPU Wait Latency Distribution Histogram (between snapshots) (total samples: 36114)
     -------------------------------------------------------------------
      Latency Range    |      Count |    Pct | Histogram Graph
     -------------------------------------------------------------------
      < 1 us           |         17 |   0.0% | #
      2 - 4 us         |        673 |   1.9% | #
      4 - 8 us         |       6237 |  17.3% | ######
      8 - 16 us        |       3224 |   8.9% | ###
      16 - 32 us       |       1388 |   3.8% | #
      32 - 64 us       |        709 |   2.0% | #
      64 - 128 us      |        690 |   1.9% | #
      128 - 256 us     |        789 |   2.2% | #
      256 - 512 us     |        541 |   1.5% | #
      512 - 1024 us    |       2256 |   6.2% | ##
      1 - 2 ms         |       3577 |   9.9% | ###
      2 - 4 ms         |      13259 |  36.7% | ##############
      4 - 8 ms         |       2523 |   7.0% | ##
      8 - 16 ms        |        222 |   0.6% | #
      16 - 32 ms       |         10 |   0.0% | #
      >= 1.05 s        |          3 |   0.0% | #
     -------------------------------------------------------------------

Signed-off-by: Aaron Tomlin <atomlin@atomlin.com>
---
 tools/perf/Documentation/perf-sched.txt |   6 +
 tools/perf/builtin-sched.c              | 180 +++++++++++++++++++++++-
 2 files changed, 183 insertions(+), 3 deletions(-)

diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
index a4221398e5e0..4da06215163a 100644
--- a/tools/perf/Documentation/perf-sched.txt
+++ b/tools/perf/Documentation/perf-sched.txt
@@ -40,6 +40,12 @@ There are several variants of 'perf sched':
   Tasks with the same command name are merged and the merge count is
   given within (), However if -p option is used, pid is mentioned.
 
+  If -H or --histogram option is passed, a CPU wait latency distribution
+  histogram is displayed illustrating how long tasks waited for CPU
+  runtime across latency buckets between snapshots. The --time
+  option (start,stop) limits analysis to a specific snapshot time interval.
+  The --hist-mode option (log or linear) configures the latency bucketing scheme.
+
   'perf sched script' to see a detailed trace of the workload that
    was recorded (aliased to 'perf script' for now).
 
diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index b3cf678573e0..b73149b84fb8 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -59,6 +59,68 @@
 #define MAX_PRIO		140
 #define SEP_LEN			100
 
+#define NUM_LAT_BUCKETS 22
+
+enum hist_mode {
+	HIST_MODE_LOG = 0,
+	HIST_MODE_LINEAR,
+};
+
+static const char *lat_bucket_names[NUM_LAT_BUCKETS] = {
+	"< 1 us",
+	"1 - 2 us",
+	"2 - 4 us",
+	"4 - 8 us",
+	"8 - 16 us",
+	"16 - 32 us",
+	"32 - 64 us",
+	"64 - 128 us",
+	"128 - 256 us",
+	"256 - 512 us",
+	"512 - 1024 us",
+	"1 - 2 ms",
+	"2 - 4 ms",
+	"4 - 8 ms",
+	"8 - 16 ms",
+	"16 - 32 ms",
+	"32 - 64 ms",
+	"64 - 128 ms",
+	"128 - 256 ms",
+	"256 - 512 ms",
+	"512 - 1024 ms",
+	">= 1.05 s"
+};
+
+static const char *linear_bucket_names[NUM_LAT_BUCKETS] = {
+	"< 100 us",
+	"100 - 200 us",
+	"200 - 300 us",
+	"300 - 400 us",
+	"400 - 500 us",
+	"500 - 600 us",
+	"600 - 700 us",
+	"700 - 800 us",
+	"800 - 900 us",
+	"900 - 1000 us",
+	"1.0 - 1.1 ms",
+	"1.1 - 1.2 ms",
+	"1.2 - 1.3 ms",
+	"1.3 - 1.4 ms",
+	"1.4 - 1.5 ms",
+	"1.5 - 1.6 ms",
+	"1.6 - 1.7 ms",
+	"1.7 - 1.8 ms",
+	"1.8 - 1.9 ms",
+	"1.9 - 2.0 ms",
+	"2.0 - 2.1 ms",
+	">= 2.1 ms"
+};
+
+struct perf_sched;
+static int latency_bucket(struct perf_sched *sched, u64 delta_ns);
+static void print_latency_histogram(struct perf_sched *sched, u64 *hist,
+				    u64 total_count, const char *title);
+
 static const char *cpu_list;
 static struct perf_cpu_map *user_requested_cpus;
 static DECLARE_BITMAP(cpu_bitmap, MAX_NR_CPUS);
@@ -124,6 +186,7 @@ struct work_atoms {
 	u64			nb_atoms;
 	u64			total_runtime;
 	int			num_merged;
+	u64			hist[NUM_LAT_BUCKETS];
 };
 
 typedef int (*sort_fn_t)(struct work_atoms *, struct work_atoms *);
@@ -219,6 +282,10 @@ struct perf_sched {
 	struct list_head sort_list, cmp_pid;
 	bool force;
 	bool skip_merge;
+	bool show_histogram;
+	enum hist_mode hist_mode;
+	const char *hist_mode_str;
+	u64 global_hist[NUM_LAT_BUCKETS];
 	struct perf_sched_map map;
 
 	/* options for timehist command */
@@ -246,6 +313,59 @@ struct perf_sched {
 	struct perf_data *data;
 };
 
+static int latency_bucket(struct perf_sched *sched, u64 delta_ns)
+{
+	u64 delta_us = delta_ns / NSEC_PER_USEC;
+	int b;
+
+	if (sched->hist_mode == HIST_MODE_LINEAR) {
+		b = delta_us / 100;
+	} else {
+		if (delta_us == 0)
+			return 0;
+		b = 64 - __builtin_clzll(delta_us);
+	}
+
+	if (b >= NUM_LAT_BUCKETS - 1)
+		return NUM_LAT_BUCKETS - 1;
+	return b;
+}
+
+static void print_latency_histogram(struct perf_sched *sched, u64 *hist,
+				    u64 total_count, const char *title)
+{
+	const char **bucket_names = (sched->hist_mode == HIST_MODE_LINEAR) ?
+		linear_bucket_names : lat_bucket_names;
+	int bar_total = 40;
+	char bar[] = "########################################";
+	int i;
+
+	if (total_count == 0)
+		return;
+
+	printf("\n %s (total samples: %" PRIu64 ")\n", title, total_count);
+	printf(" -------------------------------------------------------------------\n");
+	printf("  %-16s | %10s | %6s | %s\n",
+	       "Latency Range", "Count", "Pct", "Histogram Graph");
+	printf(" -------------------------------------------------------------------\n");
+
+	for (i = 0; i < NUM_LAT_BUCKETS; i++) {
+		double pct;
+		int bar_len;
+
+		if (hist[i] == 0)
+			continue;
+		pct = (double)hist[i] * 100.0 / total_count;
+		bar_len = (hist[i] * bar_total) / total_count;
+		if (bar_len == 0 && hist[i] > 0)
+			bar_len = 1;
+		printf("  %-16s | %10" PRIu64 " | %5.1f%% | %.*s\n",
+		       bucket_names[i], hist[i], pct,
+		       bar_len, bar);
+	}
+	printf(" -------------------------------------------------------------------\n");
+}
+
 /* per thread run time data */
 struct thread_runtime {
 	u64 last_time;      /* time of previous sched in/out event */
@@ -1129,10 +1249,12 @@ add_runtime_event(struct work_atoms *atoms, u64 delta,
 }
 
 static void
-add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
+add_sched_in_event(struct perf_sched *sched, struct work_atoms *atoms,
+		   u64 timestamp)
 {
 	struct work_atom *atom;
 	u64 delta;
+	int b;
 
 	if (list_empty(&atoms->work_list))
 		return;
@@ -1158,6 +1280,10 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
 		atoms->max_lat_end = timestamp;
 	}
 	atoms->nb_atoms++;
+
+	b = latency_bucket(sched, delta);
+	atoms->hist[b]++;
+	sched->global_hist[b]++;
 }
 
 static void free_work_atoms(struct work_atoms *atoms)
@@ -1188,6 +1314,9 @@ static int latency_switch_event(struct perf_sched *sched,
 	int cpu = sample->cpu, err = -1;
 	s64 delta;
 
+	if (perf_time__skip_sample(&sched->ptime, sample->time))
+		return 0;
+
 	/* perf.data is untrusted input — CPU may be absent or corrupted */
 	if (cpu >= MAX_CPUS || cpu < 0) {
 		pr_warning("WARNING: at offset %#" PRIx64 ": out-of-bound sample CPU %d, skipping sample\n",
@@ -1241,7 +1370,7 @@ static int latency_switch_event(struct perf_sched *sched,
 		if (add_sched_out_event(in_events, 'R', timestamp))
 			goto out_put;
 	}
-	add_sched_in_event(in_events, timestamp);
+	add_sched_in_event(sched, in_events, timestamp);
 	err = 0;
 out_put:
 	thread__put(sched_out);
@@ -1255,11 +1384,15 @@ static int latency_runtime_event(struct perf_sched *sched,
 {
 	const u32 pid	   = perf_sample__intval(sample, "pid");
 	const u64 runtime  = perf_sample__intval(sample, "runtime");
-	struct thread *thread = machine__findnew_thread(machine, -1, pid);
+	struct thread *thread;
 	struct work_atoms *atoms;
 	u64 timestamp = sample->time;
 	int cpu = sample->cpu, err = -1;
 
+	if (perf_time__skip_sample(&sched->ptime, sample->time))
+		return 0;
+
+	thread = machine__findnew_thread(machine, -1, pid);
 	if (thread == NULL)
 		return -1;
 
@@ -1302,6 +1435,9 @@ static int latency_wakeup_event(struct perf_sched *sched,
 	u64 timestamp = sample->time;
 	int err = -1;
 
+	if (perf_time__skip_sample(&sched->ptime, sample->time))
+		return 0;
+
 	wakee = machine__findnew_thread(machine, -1, pid);
 	if (wakee == NULL)
 		return -1;
@@ -1362,6 +1498,9 @@ static int latency_migrate_task_event(struct perf_sched *sched,
 	struct thread *migrant;
 	int err = -1;
 
+	if (perf_time__skip_sample(&sched->ptime, sample->time))
+		return 0;
+
 	/*
 	 * Only need to worry about migration when profiling one CPU.
 	 */
@@ -1438,6 +1577,11 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
 		 work_list->nb_atoms, (double)avg / NSEC_PER_MSEC,
 		 (double)work_list->max_lat / NSEC_PER_MSEC,
 		 max_lat_start, max_lat_end);
+
+	if (sched->show_histogram && verbose > 0)
+		print_latency_histogram(sched, work_list->hist,
+					work_list->nb_atoms,
+					"Task Latency Histogram");
 }
 
 static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
@@ -3544,6 +3688,8 @@ static void __merge_work_atoms(struct rb_root_cached *root, struct work_atoms *d
 				this->max_lat_start = data->max_lat_start;
 				this->max_lat_end = data->max_lat_end;
 			}
+			for (int i = 0; i < NUM_LAT_BUCKETS; i++)
+				this->hist[i] += data->hist[i];
 			free_work_atoms(data);
 			return;
 		}
@@ -3602,6 +3748,24 @@ static int perf_sched__lat(struct perf_sched *sched)
 
 	setup_pager();
 
+	if (sched->hist_mode_str) {
+		sched->show_histogram = true;
+		if (!strcmp(sched->hist_mode_str, "linear"))
+			sched->hist_mode = HIST_MODE_LINEAR;
+		else if (!strcmp(sched->hist_mode_str, "log"))
+			sched->hist_mode = HIST_MODE_LOG;
+		else {
+			pr_err("Invalid --hist-mode '%s', expected 'log' or 'linear'\n",
+			       sched->hist_mode_str);
+			return -EINVAL;
+		}
+	}
+
+	if (sched->time_str && perf_time__parse_str(&sched->ptime, sched->time_str) != 0) {
+		pr_err("Invalid time string\n");
+		return -EINVAL;
+	}
+
 	if (setup_cpus_switch_event(sched))
 		return rc;
 
@@ -3634,6 +3798,10 @@ static int perf_sched__lat(struct perf_sched *sched)
 	print_bad_events(sched);
 	printf("\n");
 
+	if (sched->show_histogram)
+		print_latency_histogram(sched, sched->global_hist, sched->all_count,
+					"CPU Wait Latency Distribution Histogram (between snapshots)");
+
 	rc = 0;
 
 	while ((next = rb_first_cached(&sched->sorted_atom_root))) {
@@ -5052,6 +5220,12 @@ int cmd_sched(int argc, const char **argv)
 		    "CPU to profile on"),
 	OPT_BOOLEAN('p', "pids", &sched.skip_merge,
 		    "latency stats per pid instead of per comm"),
+	OPT_BOOLEAN('H', "histogram", &sched.show_histogram,
+		    "show CPU wait latency distribution histogram"),
+	OPT_STRING(0, "hist-mode", &sched.hist_mode_str, "log|linear",
+		   "latency bucket mode (log or linear, default: log)"),
+	OPT_STRING(0, "time", &sched.time_str, "str",
+		   "Time span for analysis (start,stop)"),
 	OPT_PARENT(sched_options)
 	};
 	const struct option replay_options[] = {
-- 
2.54.0

Re: [RFC PATCH] perf sched latency: Add histogram and time interval options

[sashiko-bot]

Thank you for your contribution! Sashiko AI review found 1 potential issue(s) to consider:
- [Medium] Integer overflow in linear histogram bucket calculation allows out-of-bounds array writes.
--

--- Patch [1]: [RFC PATCH] perf sched latency: Add histogram and time interval options ---
commit 94bdb73befc369d9beaf56650ada8fcf80ad4ac5
Author: Aaron Tomlin <atomlin@atomlin.com>

perf sched latency: Add histogram and time interval options

This patch introduces options to display a latency histogram in perf sched
latency. It includes both logarithmic and linear bucketing modes, as well
as a time interval filter.

> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
[ ... ]
> @@ -246,6 +313,59 @@ struct perf_sched {
>  	struct perf_data *data;
>  };
>  
> +static int latency_bucket(struct perf_sched *sched, u64 delta_ns)
> +{
> +	u64 delta_us = delta_ns / NSEC_PER_USEC;
> +	int b;
> +
> +	if (sched->hist_mode == HIST_MODE_LINEAR) {
> +		b = delta_us / 100;

[Severity: Medium]
Could a very large delta_us value cause an integer overflow here?

If perf.data contains a massive time difference between wakeup and sched-in, 
delta_us / 100 could exceed INT_MAX. Since b is a signed 32-bit integer,
this would cause b to wrap into a negative number.

> +	} else {
> +		if (delta_us == 0)
> +			return 0;
> +		b = 64 - __builtin_clzll(delta_us);
> +	}
> +
> +	if (b >= NUM_LAT_BUCKETS - 1)

Because b is signed, this bounds check will evaluate to false for negative
numbers, allowing a negative index to be returned.

> +		return NUM_LAT_BUCKETS - 1;
> +	return b;
> +}
[ ... ]
> @@ -1129,10 +1249,12 @@ add_runtime_event(struct work_atoms *atoms, u64 delta,
>  }
>  
>  static void
> -add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
> +add_sched_in_event(struct perf_sched *sched, struct work_atoms *atoms,
> +		   u64 timestamp)
>  {
>  	struct work_atom *atom;
>  	u64 delta;
> +	int b;
>  
>  	if (list_empty(&atoms->work_list))
>  		return;
> @@ -1158,6 +1280,10 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
>  		atoms->max_lat_end = timestamp;
>  	}
>  	atoms->nb_atoms++;
> +
> +	b = latency_bucket(sched, delta);
> +	atoms->hist[b]++;
> +	sched->global_hist[b]++;

If latency_bucket() returns a negative value, does this result in an
out-of-bounds memory write that could corrupt memory before these arrays?

>  }

-- 
Sashiko AI review · https://sashiko.dev/#/patchset/20260724201207.661300-1-atomlin@atomlin.com?part=1

Re: [RFC PATCH] perf sched latency: Add histogram and time interval options

[Ian Rogers]

On Fri, Jul 24, 2026 at 1:12 PM Aaron Tomlin <atomlin@atomlin.com> wrote:
>
> While 'perf sched latency' reports task runtime and delay statistics
> (average and maximum delay), it does not provide a visual representation
> of how task wait times are distributed across latency ranges between
> snapshots (start and finish of the analysis window).
>
> The --histogram option collects CPU wait latencies (time between when
> a task becomes runnable and when it gets scheduled onto a CPU) into 22
> latency buckets, displaying an ASCII bar chart distribution.
>
> The --hist-mode option configures the bucketing scheme:
>   - log (default). Logarithmic latency buckets ranging from
>     sub-microsecond (< 1 us) up to >= 1.05 seconds
>
>   - linear. Equal-width linear latency buckets
>     (i.e., 100 us steps up to >= 2.1 ms)
>
> The --time option allows filtering trace event processing to a
> specific time interval [start,stop].
>
> Example histogram output excerpt:
>
>     ❯ sudo perf sched latency --histogram --CPU 0
>
>      CPU Wait Latency Distribution Histogram (between snapshots) (total samples: 36114)
>      -------------------------------------------------------------------
>       Latency Range    |      Count |    Pct | Histogram Graph
>      -------------------------------------------------------------------
>       < 1 us           |         17 |   0.0% | #
>       2 - 4 us         |        673 |   1.9% | #
>       4 - 8 us         |       6237 |  17.3% | ######
>       8 - 16 us        |       3224 |   8.9% | ###
>       16 - 32 us       |       1388 |   3.8% | #
>       32 - 64 us       |        709 |   2.0% | #
>       64 - 128 us      |        690 |   1.9% | #
>       128 - 256 us     |        789 |   2.2% | #
>       256 - 512 us     |        541 |   1.5% | #
>       512 - 1024 us    |       2256 |   6.2% | ##
>       1 - 2 ms         |       3577 |   9.9% | ###
>       2 - 4 ms         |      13259 |  36.7% | ##############
>       4 - 8 ms         |       2523 |   7.0% | ##
>       8 - 16 ms        |        222 |   0.6% | #
>       16 - 32 ms       |         10 |   0.0% | #
>       >= 1.05 s        |          3 |   0.0% | #
>      -------------------------------------------------------------------
>
> Signed-off-by: Aaron Tomlin <atomlin@atomlin.com>

This looks like a useful addition and because the behavior is behind a
flag it won't break anyone. I saw Sashiko had some issues, but I'd be
happy to add my tags once that's cleaned up.

Thanks,
Ian

> ---
>  tools/perf/Documentation/perf-sched.txt |   6 +
>  tools/perf/builtin-sched.c              | 180 +++++++++++++++++++++++-
>  2 files changed, 183 insertions(+), 3 deletions(-)
>
> diff --git a/tools/perf/Documentation/perf-sched.txt b/tools/perf/Documentation/perf-sched.txt
> index a4221398e5e0..4da06215163a 100644
> --- a/tools/perf/Documentation/perf-sched.txt
> +++ b/tools/perf/Documentation/perf-sched.txt
> @@ -40,6 +40,12 @@ There are several variants of 'perf sched':
>    Tasks with the same command name are merged and the merge count is
>    given within (), However if -p option is used, pid is mentioned.
>
> +  If -H or --histogram option is passed, a CPU wait latency distribution
> +  histogram is displayed illustrating how long tasks waited for CPU
> +  runtime across latency buckets between snapshots. The --time
> +  option (start,stop) limits analysis to a specific snapshot time interval.
> +  The --hist-mode option (log or linear) configures the latency bucketing scheme.
> +
>    'perf sched script' to see a detailed trace of the workload that
>     was recorded (aliased to 'perf script' for now).
>
> diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
> index b3cf678573e0..b73149b84fb8 100644
> --- a/tools/perf/builtin-sched.c
> +++ b/tools/perf/builtin-sched.c
> @@ -59,6 +59,68 @@
>  #define MAX_PRIO               140
>  #define SEP_LEN                        100
>
> +#define NUM_LAT_BUCKETS 22
> +
> +enum hist_mode {
> +       HIST_MODE_LOG = 0,
> +       HIST_MODE_LINEAR,
> +};
> +
> +static const char *lat_bucket_names[NUM_LAT_BUCKETS] = {
> +       "< 1 us",
> +       "1 - 2 us",
> +       "2 - 4 us",
> +       "4 - 8 us",
> +       "8 - 16 us",
> +       "16 - 32 us",
> +       "32 - 64 us",
> +       "64 - 128 us",
> +       "128 - 256 us",
> +       "256 - 512 us",
> +       "512 - 1024 us",
> +       "1 - 2 ms",
> +       "2 - 4 ms",
> +       "4 - 8 ms",
> +       "8 - 16 ms",
> +       "16 - 32 ms",
> +       "32 - 64 ms",
> +       "64 - 128 ms",
> +       "128 - 256 ms",
> +       "256 - 512 ms",
> +       "512 - 1024 ms",
> +       ">= 1.05 s"
> +};
> +
> +static const char *linear_bucket_names[NUM_LAT_BUCKETS] = {
> +       "< 100 us",
> +       "100 - 200 us",
> +       "200 - 300 us",
> +       "300 - 400 us",
> +       "400 - 500 us",
> +       "500 - 600 us",
> +       "600 - 700 us",
> +       "700 - 800 us",
> +       "800 - 900 us",
> +       "900 - 1000 us",
> +       "1.0 - 1.1 ms",
> +       "1.1 - 1.2 ms",
> +       "1.2 - 1.3 ms",
> +       "1.3 - 1.4 ms",
> +       "1.4 - 1.5 ms",
> +       "1.5 - 1.6 ms",
> +       "1.6 - 1.7 ms",
> +       "1.7 - 1.8 ms",
> +       "1.8 - 1.9 ms",
> +       "1.9 - 2.0 ms",
> +       "2.0 - 2.1 ms",
> +       ">= 2.1 ms"
> +};
> +
> +struct perf_sched;
> +static int latency_bucket(struct perf_sched *sched, u64 delta_ns);
> +static void print_latency_histogram(struct perf_sched *sched, u64 *hist,
> +                                   u64 total_count, const char *title);
> +
>  static const char *cpu_list;
>  static struct perf_cpu_map *user_requested_cpus;
>  static DECLARE_BITMAP(cpu_bitmap, MAX_NR_CPUS);
> @@ -124,6 +186,7 @@ struct work_atoms {
>         u64                     nb_atoms;
>         u64                     total_runtime;
>         int                     num_merged;
> +       u64                     hist[NUM_LAT_BUCKETS];
>  };
>
>  typedef int (*sort_fn_t)(struct work_atoms *, struct work_atoms *);
> @@ -219,6 +282,10 @@ struct perf_sched {
>         struct list_head sort_list, cmp_pid;
>         bool force;
>         bool skip_merge;
> +       bool show_histogram;
> +       enum hist_mode hist_mode;
> +       const char *hist_mode_str;
> +       u64 global_hist[NUM_LAT_BUCKETS];
>         struct perf_sched_map map;
>
>         /* options for timehist command */
> @@ -246,6 +313,59 @@ struct perf_sched {
>         struct perf_data *data;
>  };
>
> +static int latency_bucket(struct perf_sched *sched, u64 delta_ns)
> +{
> +       u64 delta_us = delta_ns / NSEC_PER_USEC;
> +       int b;
> +
> +       if (sched->hist_mode == HIST_MODE_LINEAR) {
> +               b = delta_us / 100;
> +       } else {
> +               if (delta_us == 0)
> +                       return 0;
> +               b = 64 - __builtin_clzll(delta_us);
> +       }
> +
> +       if (b >= NUM_LAT_BUCKETS - 1)
> +               return NUM_LAT_BUCKETS - 1;
> +       return b;
> +}
> +
> +static void print_latency_histogram(struct perf_sched *sched, u64 *hist,
> +                                   u64 total_count, const char *title)
> +{
> +       const char **bucket_names = (sched->hist_mode == HIST_MODE_LINEAR) ?
> +               linear_bucket_names : lat_bucket_names;
> +       int bar_total = 40;
> +       char bar[] = "########################################";
> +       int i;
> +
> +       if (total_count == 0)
> +               return;
> +
> +       printf("\n %s (total samples: %" PRIu64 ")\n", title, total_count);
> +       printf(" -------------------------------------------------------------------\n");
> +       printf("  %-16s | %10s | %6s | %s\n",
> +              "Latency Range", "Count", "Pct", "Histogram Graph");
> +       printf(" -------------------------------------------------------------------\n");
> +
> +       for (i = 0; i < NUM_LAT_BUCKETS; i++) {
> +               double pct;
> +               int bar_len;
> +
> +               if (hist[i] == 0)
> +                       continue;
> +               pct = (double)hist[i] * 100.0 / total_count;
> +               bar_len = (hist[i] * bar_total) / total_count;
> +               if (bar_len == 0 && hist[i] > 0)
> +                       bar_len = 1;
> +               printf("  %-16s | %10" PRIu64 " | %5.1f%% | %.*s\n",
> +                      bucket_names[i], hist[i], pct,
> +                      bar_len, bar);
> +       }
> +       printf(" -------------------------------------------------------------------\n");
> +}
> +
>  /* per thread run time data */
>  struct thread_runtime {
>         u64 last_time;      /* time of previous sched in/out event */
> @@ -1129,10 +1249,12 @@ add_runtime_event(struct work_atoms *atoms, u64 delta,
>  }
>
>  static void
> -add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
> +add_sched_in_event(struct perf_sched *sched, struct work_atoms *atoms,
> +                  u64 timestamp)
>  {
>         struct work_atom *atom;
>         u64 delta;
> +       int b;
>
>         if (list_empty(&atoms->work_list))
>                 return;
> @@ -1158,6 +1280,10 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
>                 atoms->max_lat_end = timestamp;
>         }
>         atoms->nb_atoms++;
> +
> +       b = latency_bucket(sched, delta);
> +       atoms->hist[b]++;
> +       sched->global_hist[b]++;
>  }
>
>  static void free_work_atoms(struct work_atoms *atoms)
> @@ -1188,6 +1314,9 @@ static int latency_switch_event(struct perf_sched *sched,
>         int cpu = sample->cpu, err = -1;
>         s64 delta;
>
> +       if (perf_time__skip_sample(&sched->ptime, sample->time))
> +               return 0;
> +
>         /* perf.data is untrusted input — CPU may be absent or corrupted */
>         if (cpu >= MAX_CPUS || cpu < 0) {
>                 pr_warning("WARNING: at offset %#" PRIx64 ": out-of-bound sample CPU %d, skipping sample\n",
> @@ -1241,7 +1370,7 @@ static int latency_switch_event(struct perf_sched *sched,
>                 if (add_sched_out_event(in_events, 'R', timestamp))
>                         goto out_put;
>         }
> -       add_sched_in_event(in_events, timestamp);
> +       add_sched_in_event(sched, in_events, timestamp);
>         err = 0;
>  out_put:
>         thread__put(sched_out);
> @@ -1255,11 +1384,15 @@ static int latency_runtime_event(struct perf_sched *sched,
>  {
>         const u32 pid      = perf_sample__intval(sample, "pid");
>         const u64 runtime  = perf_sample__intval(sample, "runtime");
> -       struct thread *thread = machine__findnew_thread(machine, -1, pid);
> +       struct thread *thread;
>         struct work_atoms *atoms;
>         u64 timestamp = sample->time;
>         int cpu = sample->cpu, err = -1;
>
> +       if (perf_time__skip_sample(&sched->ptime, sample->time))
> +               return 0;
> +
> +       thread = machine__findnew_thread(machine, -1, pid);
>         if (thread == NULL)
>                 return -1;
>
> @@ -1302,6 +1435,9 @@ static int latency_wakeup_event(struct perf_sched *sched,
>         u64 timestamp = sample->time;
>         int err = -1;
>
> +       if (perf_time__skip_sample(&sched->ptime, sample->time))
> +               return 0;
> +
>         wakee = machine__findnew_thread(machine, -1, pid);
>         if (wakee == NULL)
>                 return -1;
> @@ -1362,6 +1498,9 @@ static int latency_migrate_task_event(struct perf_sched *sched,
>         struct thread *migrant;
>         int err = -1;
>
> +       if (perf_time__skip_sample(&sched->ptime, sample->time))
> +               return 0;
> +
>         /*
>          * Only need to worry about migration when profiling one CPU.
>          */
> @@ -1438,6 +1577,11 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
>                  work_list->nb_atoms, (double)avg / NSEC_PER_MSEC,
>                  (double)work_list->max_lat / NSEC_PER_MSEC,
>                  max_lat_start, max_lat_end);
> +
> +       if (sched->show_histogram && verbose > 0)
> +               print_latency_histogram(sched, work_list->hist,
> +                                       work_list->nb_atoms,
> +                                       "Task Latency Histogram");
>  }
>
>  static int pid_cmp(struct work_atoms *l, struct work_atoms *r)
> @@ -3544,6 +3688,8 @@ static void __merge_work_atoms(struct rb_root_cached *root, struct work_atoms *d
>                                 this->max_lat_start = data->max_lat_start;
>                                 this->max_lat_end = data->max_lat_end;
>                         }
> +                       for (int i = 0; i < NUM_LAT_BUCKETS; i++)
> +                               this->hist[i] += data->hist[i];
>                         free_work_atoms(data);
>                         return;
>                 }
> @@ -3602,6 +3748,24 @@ static int perf_sched__lat(struct perf_sched *sched)
>
>         setup_pager();
>
> +       if (sched->hist_mode_str) {
> +               sched->show_histogram = true;
> +               if (!strcmp(sched->hist_mode_str, "linear"))
> +                       sched->hist_mode = HIST_MODE_LINEAR;
> +               else if (!strcmp(sched->hist_mode_str, "log"))
> +                       sched->hist_mode = HIST_MODE_LOG;
> +               else {
> +                       pr_err("Invalid --hist-mode '%s', expected 'log' or 'linear'\n",
> +                              sched->hist_mode_str);
> +                       return -EINVAL;
> +               }
> +       }
> +
> +       if (sched->time_str && perf_time__parse_str(&sched->ptime, sched->time_str) != 0) {
> +               pr_err("Invalid time string\n");
> +               return -EINVAL;
> +       }
> +
>         if (setup_cpus_switch_event(sched))
>                 return rc;
>
> @@ -3634,6 +3798,10 @@ static int perf_sched__lat(struct perf_sched *sched)
>         print_bad_events(sched);
>         printf("\n");
>
> +       if (sched->show_histogram)
> +               print_latency_histogram(sched, sched->global_hist, sched->all_count,
> +                                       "CPU Wait Latency Distribution Histogram (between snapshots)");
> +
>         rc = 0;
>
>         while ((next = rb_first_cached(&sched->sorted_atom_root))) {
> @@ -5052,6 +5220,12 @@ int cmd_sched(int argc, const char **argv)
>                     "CPU to profile on"),
>         OPT_BOOLEAN('p', "pids", &sched.skip_merge,
>                     "latency stats per pid instead of per comm"),
> +       OPT_BOOLEAN('H', "histogram", &sched.show_histogram,
> +                   "show CPU wait latency distribution histogram"),
> +       OPT_STRING(0, "hist-mode", &sched.hist_mode_str, "log|linear",
> +                  "latency bucket mode (log or linear, default: log)"),
> +       OPT_STRING(0, "time", &sched.time_str, "str",
> +                  "Time span for analysis (start,stop)"),
>         OPT_PARENT(sched_options)
>         };
>         const struct option replay_options[] = {
> --
> 2.54.0
>

Re: [RFC PATCH] perf sched latency: Add histogram and time interval options

[Aaron Tomlin]

On Fri, Jul 24, 2026 at 04:27:07PM -0700, Ian Rogers wrote:
> On Fri, Jul 24, 2026 at 1:12 PM Aaron Tomlin <atomlin@atomlin.com> wrote:
> >
> > While 'perf sched latency' reports task runtime and delay statistics
> > (average and maximum delay), it does not provide a visual representation
> > of how task wait times are distributed across latency ranges between
> > snapshots (start and finish of the analysis window).
> >
> > The --histogram option collects CPU wait latencies (time between when
> > a task becomes runnable and when it gets scheduled onto a CPU) into 22
> > latency buckets, displaying an ASCII bar chart distribution.
> >
> > The --hist-mode option configures the bucketing scheme:
> >   - log (default). Logarithmic latency buckets ranging from
> >     sub-microsecond (< 1 us) up to >= 1.05 seconds
> >
> >   - linear. Equal-width linear latency buckets
> >     (i.e., 100 us steps up to >= 2.1 ms)
> >
> > The --time option allows filtering trace event processing to a
> > specific time interval [start,stop].
> >
> > Example histogram output excerpt:
> >
> >     ❯ sudo perf sched latency --histogram --CPU 0
> >
> >      CPU Wait Latency Distribution Histogram (between snapshots) (total samples: 36114)
> >      -------------------------------------------------------------------
> >       Latency Range    |      Count |    Pct | Histogram Graph
> >      -------------------------------------------------------------------
> >       < 1 us           |         17 |   0.0% | #
> >       2 - 4 us         |        673 |   1.9% | #
> >       4 - 8 us         |       6237 |  17.3% | ######
> >       8 - 16 us        |       3224 |   8.9% | ###
> >       16 - 32 us       |       1388 |   3.8% | #
> >       32 - 64 us       |        709 |   2.0% | #
> >       64 - 128 us      |        690 |   1.9% | #
> >       128 - 256 us     |        789 |   2.2% | #
> >       256 - 512 us     |        541 |   1.5% | #
> >       512 - 1024 us    |       2256 |   6.2% | ##
> >       1 - 2 ms         |       3577 |   9.9% | ###
> >       2 - 4 ms         |      13259 |  36.7% | ##############
> >       4 - 8 ms         |       2523 |   7.0% | ##
> >       8 - 16 ms        |        222 |   0.6% | #
> >       16 - 32 ms       |         10 |   0.0% | #
> >       >= 1.05 s        |          3 |   0.0% | #
> >      -------------------------------------------------------------------
> >
> > Signed-off-by: Aaron Tomlin <atomlin@atomlin.com>
> 
> This looks like a useful addition and because the behavior is behind a
> flag it won't break anyone. I saw Sashiko had some issues, but I'd be
> happy to add my tags once that's cleaned up.
> 
> Thanks,

Hi Ian,

Thank you for your feedback.

Understood.

Kind regards,
-- 
Aaron Tomlin