mirror of
https://github.com/torvalds/linux.git
synced 2026-09-22 20:54:03 +02:00
perf sched latency: Add histogram and time interval options
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% | #
-------------------------------------------------------------------
Reviewed-by: Ian Rogers <irogers@google.com>
Signed-off-by: Aaron Tomlin <atomlin@atomlin.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
This commit is contained in:
Aaron Tomlin
Namhyung Kim
parent
19ea850c02
commit
bf10e6ee2a
|
|
@ -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).
|
||||
|
||||
|
|
|
|||
|
|
@ -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 */
|
||||
|
|
@ -257,6 +324,59 @@ static int scnprintf_latency_unit(char *buf, size_t size, u64 nsecs)
|
|||
return scnprintf(buf, size, "%6.3f s ", (double)nsecs / NSEC_PER_SEC);
|
||||
}
|
||||
|
||||
static int latency_bucket(struct perf_sched *sched, u64 delta_ns)
|
||||
{
|
||||
u64 delta_us = delta_ns / NSEC_PER_USEC;
|
||||
u64 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 */
|
||||
|
|
@ -1108,20 +1228,33 @@ add_sched_out_event(struct work_atoms *atoms,
|
|||
char run_state,
|
||||
u64 timestamp)
|
||||
{
|
||||
struct work_atom *atom = zalloc(sizeof(*atom));
|
||||
struct work_atom *atom = NULL;
|
||||
|
||||
if (!list_empty(&atoms->work_list)) {
|
||||
atom = list_entry(atoms->work_list.prev, struct work_atom, list);
|
||||
if (atom->state != THREAD_SCHED_IN)
|
||||
goto reuse;
|
||||
}
|
||||
|
||||
atom = zalloc(sizeof(*atom));
|
||||
if (!atom) {
|
||||
pr_err("Non memory at %s", __func__);
|
||||
return -1;
|
||||
}
|
||||
|
||||
list_add_tail(&atom->list, &atoms->work_list);
|
||||
|
||||
reuse:
|
||||
atom->sched_out_time = timestamp;
|
||||
|
||||
if (run_state == 'R') {
|
||||
atom->state = THREAD_WAIT_CPU;
|
||||
atom->wake_up_time = atom->sched_out_time;
|
||||
} else {
|
||||
atom->state = THREAD_SLEEPING;
|
||||
atom->wake_up_time = 0;
|
||||
}
|
||||
|
||||
list_add_tail(&atom->list, &atoms->work_list);
|
||||
return 0;
|
||||
}
|
||||
|
||||
|
|
@ -1140,10 +1273,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 +1293,9 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
|
|||
return;
|
||||
}
|
||||
|
||||
if (perf_time__skip_sample(&sched->ptime, timestamp))
|
||||
return;
|
||||
|
||||
atom->state = THREAD_SCHED_IN;
|
||||
atom->sched_in_time = timestamp;
|
||||
|
||||
|
|
@ -1168,7 +1306,13 @@ add_sched_in_event(struct work_atoms *atoms, u64 timestamp)
|
|||
atoms->max_lat_start = atom->wake_up_time;
|
||||
atoms->max_lat_end = timestamp;
|
||||
}
|
||||
|
||||
atoms->nb_atoms++;
|
||||
|
||||
b = latency_bucket(sched, delta);
|
||||
atoms->hist[b]++;
|
||||
if (thread__tid(atoms->thread) != 0)
|
||||
sched->global_hist[b]++;
|
||||
}
|
||||
|
||||
static void free_work_atoms(struct work_atoms *atoms)
|
||||
|
|
@ -1252,7 +1396,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);
|
||||
|
|
@ -1266,11 +1410,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, timestamp))
|
||||
return 0;
|
||||
|
||||
thread = machine__findnew_thread(machine, -1, pid);
|
||||
if (thread == NULL)
|
||||
return -1;
|
||||
|
||||
|
|
@ -1425,7 +1573,7 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
|
|||
/*
|
||||
* Ignore idle threads:
|
||||
*/
|
||||
if (!strcmp(thread__comm_str(work_list->thread), "swapper"))
|
||||
if (thread__tid(work_list->thread) == 0)
|
||||
return;
|
||||
|
||||
sched->all_runtime += work_list->total_runtime;
|
||||
|
|
@ -1454,6 +1602,10 @@ static void output_lat_thread(struct perf_sched *sched, struct work_atoms *work_
|
|||
work_list->nb_atoms, avg_lat, max_lat,
|
||||
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)
|
||||
|
|
@ -3590,6 +3742,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;
|
||||
}
|
||||
|
|
@ -3649,6 +3803,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;
|
||||
|
||||
|
|
@ -3658,6 +3830,21 @@ static int perf_sched__lat(struct perf_sched *sched)
|
|||
perf_sched__merge_lat(sched);
|
||||
perf_sched__sort_lat(sched);
|
||||
|
||||
next = rb_first_cached(&sched->sorted_atom_root);
|
||||
while (next) {
|
||||
struct work_atoms *work_list = rb_entry(next, struct work_atoms, node);
|
||||
|
||||
if (work_list->nb_atoms && thread__tid(work_list->thread) != 0)
|
||||
break;
|
||||
next = rb_next(next);
|
||||
}
|
||||
|
||||
if (!next) {
|
||||
pr_info("No matching trace samples found.\n");
|
||||
rc = 0;
|
||||
goto out_free_atoms;
|
||||
}
|
||||
|
||||
printf("\n ------------------------------------------------------------------------------------------------------------------------------------------\n");
|
||||
printf(" Task | Runtime | Count | Avg delay | Max delay | Max delay start | Max delay end |\n");
|
||||
printf(" ------------------------------------------------------------------------------------------------------------------------------------------\n");
|
||||
|
|
@ -3682,8 +3869,13 @@ 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;
|
||||
|
||||
out_free_atoms:
|
||||
while ((next = rb_first_cached(&sched->sorted_atom_root))) {
|
||||
struct work_atoms *data;
|
||||
|
||||
|
|
@ -5104,6 +5296,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[] = {
|
||||
|
|
|
|||
|
|
@ -76,6 +76,32 @@ test_sched_latency() {
|
|||
fi
|
||||
}
|
||||
|
||||
test_sched_latency_histogram() {
|
||||
echo "Sched latency histogram"
|
||||
|
||||
if ! perf sched latency -H -i "${perfdata}" | grep -q "Latency Distribution Histogram"
|
||||
then
|
||||
echo "Sched latency histogram [Failed missing log histogram]"
|
||||
err=1
|
||||
fi
|
||||
|
||||
if ! perf sched latency --histogram --hist-mode linear -i "${perfdata}" | grep -q "Latency Distribution Histogram"
|
||||
then
|
||||
echo "Sched latency histogram [Failed missing linear histogram]"
|
||||
err=1
|
||||
fi
|
||||
}
|
||||
|
||||
test_sched_latency_time() {
|
||||
echo "Sched latency time filter"
|
||||
|
||||
if ! perf sched latency --time 0, -i "${perfdata}" | grep -q perf-noploop
|
||||
then
|
||||
echo "Sched latency time filter [Failed missing output]"
|
||||
err=1
|
||||
fi
|
||||
}
|
||||
|
||||
test_sched_script() {
|
||||
echo "Sched script"
|
||||
|
||||
|
|
@ -108,9 +134,12 @@ test_sched_timehist() {
|
|||
|
||||
test_sched_record
|
||||
test_sched_latency
|
||||
test_sched_latency_histogram
|
||||
test_sched_latency_time
|
||||
test_sched_script
|
||||
test_sched_map
|
||||
test_sched_timehist
|
||||
|
||||
cleanup
|
||||
exit $err
|
||||
|
||||
|
|
|
|||
Loading…
Reference in New Issue
Block a user