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

[Arnaldo Carvalho de Melo]

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