perf kwork: Implement perf kwork timehist
Implements framework of perf kwork timehist,
to provide an analysis of kernel work events.
Test cases:
# perf kwork tim
Runtime start Runtime end Cpu Kwork name Runtime Delaytime
(TYPE)NAME:NUM (msec) (msec)
----------------- ----------------- ------ ------------------------------ ---------- ----------
91576.060290 91576.060344 [0000] (s)RCU:9 0.055 0.111
91576.061470 91576.061547 [0000] (s)SCHED:7 0.077 0.073
91576.062604 91576.062697 [0001] (s)RCU:9 0.094 0.409
91576.064443 91576.064517 [0002] (s)RCU:9 0.074 0.114
91576.065144 91576.065211 [0000] (s)SCHED:7 0.067 0.058
91576.066564 91576.066609 [0003] (s)RCU:9 0.045 0.110
91576.068495 91576.068559 [0000] (s)SCHED:7 0.064 0.059
91576.068900 91576.068996 [0004] (s)RCU:9 0.096 0.726
91576.069364 91576.069420 [0002] (s)RCU:9 0.056 0.082
91576.069649 91576.069701 [0004] (s)RCU:9 0.052 0.111
91576.070147 91576.070206 [0000] (s)SCHED:7 0.060 0.057
91576.073147 91576.073202 [0000] (s)SCHED:7 0.054 0.060
<SNIP>
# perf kwork tim --max-stack 2 -g
Runtime start Runtime end Cpu Kwork name Runtime Delaytime
(TYPE)NAME:NUM (msec) (msec)
----------------- ----------------- ------ ------------------------------ ---------- ----------
91576.060290 91576.060344 [0000] (s)RCU:9 0.055 0.111 irq_exit_rcu <- sysvec_apic_timer_interrupt
91576.061470 91576.061547 [0000] (s)SCHED:7 0.077 0.073 irq_exit_rcu <- sysvec_call_function_single
91576.062604 91576.062697 [0001] (s)RCU:9 0.094 0.409 irq_exit_rcu <- sysvec_apic_timer_interrupt
91576.064443 91576.064517 [0002] (s)RCU:9 0.074 0.114 irq_exit_rcu <- sysvec_apic_timer_interrupt
91576.065144 91576.065211 [0000] (s)SCHED:7 0.067 0.058 irq_exit_rcu <- sysvec_call_function_single
91576.066564 91576.066609 [0003] (s)RCU:9 0.045 0.110 irq_exit_rcu <- sysvec_apic_timer_interrupt
91576.068495 91576.068559 [0000] (s)SCHED:7 0.064 0.059 irq_exit_rcu <- sysvec_call_function_single
91576.068900 91576.068996 [0004] (s)RCU:9 0.096 0.726 irq_exit_rcu <- sysvec_apic_timer_interrupt
91576.069364 91576.069420 [0002] (s)RCU:9 0.056 0.082 irq_exit_rcu <- sysvec_apic_timer_interrupt
91576.069649 91576.069701 [0004] (s)RCU:9 0.052 0.111 irq_exit_rcu <- sysvec_apic_timer_interrupt
<SNIP>
Committer testing:
# perf kwork -k workqueue timehist | head -40
Runtime start Runtime end Cpu Kwork name Runtime Delaytime
(TYPE)NAME:NUM (msec) (msec)
----------------- ----------------- ------ ------------------------------ ---------- ----------
26520.211825 26520.211832 [0019] (w)free_work 0.007 0.004
26520.212929 26520.212934 [0020] (w)free_work 0.005 0.004
26520.213226 26520.213228 [0014] (w)kfree_rcu_work 0.002 0.004
26520.214057 26520.214061 [0021] (w)free_work 0.004 0.004
26520.221239 26520.221241 [0007] (w)kfree_rcu_work 0.002 0.009
26520.223232 26520.223238 [0013] (w)psi_avgs_work 0.005 0.006
26520.230057 26520.230060 [0020] (w)free_work 0.003 0.003
26520.270428 26520.270434 [0015] (w)free_work 0.006 0.004
26520.270546 26520.270550 [0014] (w)free_work 0.004 0.003
26520.281626 26520.281629 [0015] (w)free_work 0.003 0.002
26520.287225 26520.287230 [0012] (w)psi_avgs_work 0.005 0.008
26520.287231 26520.287235 [0001] (w)psi_avgs_work 0.004 0.011
26520.287236 26520.287239 [0001] (w)psi_avgs_work 0.003 0.012
26520.329488 26520.329492 [0024] (w)free_work 0.004 0.004
26520.330600 26520.330605 [0007] (w)free_work 0.005 0.004
26520.334218 26520.334218 [0007] (w)kfree_rcu_monitor 0.001 0.002
26520.335220 26520.335221 [0005] (w)kfree_rcu_monitor 0.001 0.004
26520.343980 26520.343985 [0007] (w)free_work 0.005 0.002
26520.345093 26520.345097 [0006] (w)free_work 0.004 0.003
26520.351233 26520.351238 [0027] (w)psi_avgs_work 0.005 0.008
26520.353228 26520.353229 [0007] (w)kfree_rcu_work 0.001 0.002
26520.353229 26520.353231 [0005] (w)kfree_rcu_work 0.001 0.006
26520.382381 26520.382383 [0006] (w)free_work 0.003 0.002
26520.386547 26520.386548 [0006] (w)free_work 0.002 0.001
26520.391243 26520.391245 [0015] (w)console_callback 0.002 0.016
26520.415369 26520.415621 [0027] (w)btrfs_work_helper 0.252
26520.415351 26520.416174 [0002] (w)btrfs_work_helper 0.823 0.037
26520.415343 26520.416304 [0031] (w)btrfs_work_helper 0.961
26520.415335 26520.417078 [0001] (w)btrfs_work_helper 1.743
26520.415250 26520.417564 [0002] (w)wb_workfn 2.314
26520.424777 26520.424787 [0002] (w)btrfs_work_helper 0.010
26520.424788 26520.424798 [0002] (w)btrfs_work_helper 0.010
26520.424790 26520.424805 [0001] (w)btrfs_work_helper 0.016 0.016
26520.424801 26520.424807 [0002] (w)btrfs_work_helper 0.006
26520.424809 26520.424831 [0002] (w)btrfs_work_helper 0.022 0.030
26520.424824 26520.424835 [0027] (w)btrfs_work_helper 0.011
26520.424809 26520.424867 [0001] (w)btrfs_work_helper 0.059 0.032
#
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Mark Rutland <mark.rutland@arm.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Clarke <pc@us.ibm.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: https://lore.kernel.org/r/20220709015033.38326-14-yangjihong1@huawei.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
OSDN Git Service
