Linux kernel mirror (for testing) git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel os linux

perf sched timehist: Show total scheduling time

Show length of analyzed sample time and rate of idle task running.
This also takes care of time range given by --time option.

$ perf sched timehist -sI | tail
Samples do not have callchains.
Idle stats:
CPU 0 idle for 930.316 msec ( 92.93%)
CPU 1 idle for 963.614 msec ( 96.25%)
CPU 2 idle for 885.482 msec ( 88.45%)
CPU 3 idle for 938.635 msec ( 93.76%)

Total number of unique tasks: 118
Total number of context switches: 2337
Total run time (msec): 3718.048
Total scheduling time (msec): 1001.131 (x 4)

Suggested-by: David Ahern <dsahern@gmail.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Link: http://lkml.kernel.org/r/20161222060350.17655-3-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

authored by

Namhyung Kim and committed by
Arnaldo Carvalho de Melo
9396c9cb 3705b975

+14 -3
+14 -3
tools/perf/builtin-sched.c
··· 209 209 u64 skipped_samples; 210 210 const char *time_str; 211 211 struct perf_time_interval ptime; 212 + struct perf_time_interval hist_time; 212 213 }; 213 214 214 215 /* per thread run time data */ ··· 2461 2460 timehist_print_sample(sched, sample, &al, thread, t); 2462 2461 2463 2462 out: 2463 + if (sched->hist_time.start == 0 && t >= ptime->start) 2464 + sched->hist_time.start = t; 2465 + if (ptime->end == 0 || t <= ptime->end) 2466 + sched->hist_time.end = t; 2467 + 2464 2468 if (tr) { 2465 2469 /* time of this sched_switch event becomes last time task seen */ 2466 2470 tr->last_time = sample->time; ··· 2630 2624 struct thread *t; 2631 2625 struct thread_runtime *r; 2632 2626 int i; 2627 + u64 hist_time = sched->hist_time.end - sched->hist_time.start; 2633 2628 2634 2629 memset(&totals, 0, sizeof(totals)); 2635 2630 ··· 2672 2665 totals.sched_count += r->run_stats.n; 2673 2666 printf(" CPU %2d idle for ", i); 2674 2667 print_sched_time(r->total_run_time, 6); 2675 - printf(" msec\n"); 2668 + printf(" msec (%6.2f%%)\n", 100.0 * r->total_run_time / hist_time); 2676 2669 } else 2677 2670 printf(" CPU %2d idle entire time window\n", i); 2678 2671 } ··· 2708 2701 2709 2702 printf("\n" 2710 2703 " Total number of unique tasks: %" PRIu64 "\n" 2711 - "Total number of context switches: %" PRIu64 "\n" 2712 - " Total run time (msec): ", 2704 + "Total number of context switches: %" PRIu64 "\n", 2713 2705 totals.task_count, totals.sched_count); 2714 2706 2707 + printf(" Total run time (msec): "); 2715 2708 print_sched_time(totals.total_run_time, 2); 2716 2709 printf("\n"); 2710 + 2711 + printf(" Total scheduling time (msec): "); 2712 + print_sched_time(hist_time, 2); 2713 + printf(" (x %d)\n", sched->max_cpu); 2717 2714 } 2718 2715 2719 2716 typedef int (*sched_handler)(struct perf_tool *tool,