Re: [PATCHSET 00/10] perf sched timehist: Introduce --idle-hist option (v1)

From: Arnaldo Carvalho de Melo
Date: Tue Dec 06 2016 - 14:44:39 EST


Em Tue, Dec 06, 2016 at 12:40:00PM +0900, Namhyung Kim escreveu:
> Hi,
>
> This patchset implements the idle hist feature which analyze reason of system
> idle. Sometimes I need to investigate what makes CPUs to go idle even though
> I have jobs to do. It may be due to I/O, waiting on lock or whatever.

So, on a first round, I've applied the ones David acked, will try
pushing to Ingo today.

David, I still haven't myself reviewed the patches, before that, do you
have any strong objection to the other patches? Will you continue
reviewing them?

- Arnaldo

> To identify the reasons it only accounts events related to idle task. Also it
> shows callchains when entering to idle and time how long it's in the idle.
> Although it's not perfect, it works well to help finding the reasons.
>
> With --idle-hist option, only idle task's runtime is accounted to previous
> task (which makes the cpu go to idle). With --summary(-only) option, you can
> see the total idle stat by task or callchains.
>
> The example output looks like below:
>
> Idle-time summary
> comm parent sched-out idle-time min-idle avg-idle max-idle stddev migrations
> (count) (msec) (msec) (msec) (msec) %
> ---------------------------------------------------------------------------------------------------------------------
> rcu_preempt[7] 2 95 550.872 0.011 5.798 23.146 7.63 0
> migration/1[16] 2 1 15.558 15.558 15.558 15.558 0.00 0
> khugepaged[39] 2 1 3.062 3.062 3.062 3.062 0.00 0
> kworker/0:1H[124] 2 2 4.728 0.611 2.364 4.116 74.12 0
> systemd-journal[167] 1 1 4.510 4.510 4.510 4.510 0.00 0
> kworker/u16:3[558] 2 13 74.737 0.080 5.749 12.960 21.96 0
> irq/34-iwlwifi[628] 2 21 118.403 0.032 5.638 23.990 24.00 0
> kworker/u17:0[673] 2 1 3.523 3.523 3.523 3.523 0.00 0
> dbus-daemon[722] 1 1 6.743 6.743 6.743 6.743 0.00 0
> ifplugd[741] 1 1 58.826 58.826 58.826 58.826 0.00 0
> wpa_supplicant[1490] 1 1 13.302 13.302 13.302 13.302 0.00 0
> wpa_actiond[1492] 1 2 4.064 0.168 2.032 3.896 91.72 0
> dockerd[1500] 1 1 0.055 0.055 0.055 0.055 0.00 0
> dockerd[1516/1500] 1500 1 5.732 5.732 5.732 5.732 0.00 0
> dockerd[1571/1500] 1500 1 0.020 0.020 0.020 0.020 0.00 0
> ...
>
> Idle stats:
> CPU 0 idle for 902.195 msec
> CPU 1 idle for 899.932 msec
> CPU 2 idle for 941.218 msec
> CPU 3 idle for 822.453 msec
>
> Idle stats by callchain:
> CPU 0: 902.195 msec
> Idle time (msec) Count Callchains
> ---------------- -------- --------------------------------------------------
> 370.589 69 futex_wait_queue_me <- futex_wait <- do_futex <- sys_futex <- entry_SYSCALL_64_fastpath
> 178.799 17 worker_thread <- kthread <- ret_from_fork
> 128.352 17 schedule_timeout <- rcu_gp_kthread <- kthread <- ret_from_fork
> 125.111 19 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_select <- core_sys_select
> 71.599 50 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- sys_poll
> 23.146 1 rcu_gp_kthread <- kthread <- ret_from_fork
> 4.510 1 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- ep_poll <- sys_epoll_wait <- do_syscall_64
> 0.085 1 schedule_hrtimeout_range_clock <- schedule_hrtimeout_range <- poll_schedule_timeout <- do_sys_poll <- do_restart_poll
> ...
>
>
> The patch 1-5 are cleanup and preparations so they can be applied separately.
> The patch 6-10 implements the -I/--idle-hist option.
>
> The code is available at 'perf/timehist-idle-v1' branch in my tree:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
>
> Any comments are welcome!
>
> Thanks,
> Namhyung
>
>
> Namhyung Kim (10):
> perf sched: Cleanup option processing
> perf tools: Introduce callchain_cursor__copy()
> perf sched timehist: Handle zero sample->tid properly
> perf sched timehist: Split is_idle_sample()
> perf sched timehist: Cleanup idle_max_cpu handling
> perf sched timehist: Introduce struct idle_time_data
> perf sched timehist: Save callchain when entering idle
> perf sched timehist: Skip non-idle events when necessary
> perf sched timehist: Add -I/--idle-hist option
> perf sched timehist: Show callchains for idle stat
>
> tools/perf/Documentation/perf-sched.txt | 4 +
> tools/perf/builtin-sched.c | 264 +++++++++++++++++++++++++++-----
> tools/perf/util/callchain.c | 27 ++++
> tools/perf/util/callchain.h | 3 +
> 4 files changed, 256 insertions(+), 42 deletions(-)
>
> --
> 2.10.1