diff options
| author | Yang Jihong <yangjihong1@huawei.com> | 2022-07-09 04:50:29 +0300 |
|---|---|---|
| committer | Arnaldo Carvalho de Melo <acme@redhat.com> | 2022-07-26 22:31:54 +0300 |
| commit | bcc8b3e88d6fa1a3a3662bfebd26214b62b61c81 (patch) | |
| tree | fa5ad19433b9862b411d9adc96778125283d69d8 /tools/perf/Documentation | |
| parent | 53e49e32ae651984463b536fa379eab5149b5ead (diff) | |
| download | linux-bcc8b3e88d6fa1a3a3662bfebd26214b62b61c81.tar.xz | |
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>
Diffstat (limited to 'tools/perf/Documentation')
| -rw-r--r-- | tools/perf/Documentation/perf-kwork.txt | 65 |
1 files changed, 65 insertions, 0 deletions
diff --git a/tools/perf/Documentation/perf-kwork.txt b/tools/perf/Documentation/perf-kwork.txt index 069981457de1..51c1625bacae 100644 --- a/tools/perf/Documentation/perf-kwork.txt +++ b/tools/perf/Documentation/perf-kwork.txt @@ -21,10 +21,36 @@ There are several variants of 'perf kwork': 'perf kwork latency' to report the per kwork latencies. + 'perf kwork timehist' provides an analysis of kernel work events. + Example usage: perf kwork record -- sleep 1 perf kwork report perf kwork latency + perf kwork timehist + + By default it shows the individual work events such as irq, workqeueu, + including the run time and delay (time between raise and actually entry): + + Runtime start Runtime end Cpu Kwork name Runtime Delaytime + (TYPE)NAME:NUM (msec) (msec) + ----------------- ----------------- ------ ------------------------- ---------- ---------- + 1811186.976062 1811186.976327 [0000] (s)RCU:9 0.266 0.114 + 1811186.978452 1811186.978547 [0000] (s)SCHED:7 0.095 0.171 + 1811186.980327 1811186.980490 [0000] (s)SCHED:7 0.162 0.083 + 1811186.981221 1811186.981271 [0000] (s)SCHED:7 0.050 0.077 + 1811186.984267 1811186.984318 [0000] (s)SCHED:7 0.051 0.075 + 1811186.987252 1811186.987315 [0000] (s)SCHED:7 0.063 0.081 + 1811186.987785 1811186.987843 [0006] (s)RCU:9 0.058 0.645 + 1811186.988319 1811186.988383 [0000] (s)SCHED:7 0.064 0.143 + 1811186.989404 1811186.989607 [0002] (s)TIMER:1 0.203 0.111 + 1811186.989660 1811186.989732 [0002] (s)SCHED:7 0.072 0.310 + 1811186.991295 1811186.991407 [0002] eth0:10 0.112 + 1811186.991639 1811186.991734 [0002] (s)NET_RX:3 0.095 0.277 + 1811186.989860 1811186.991826 [0002] (w)vmstat_shepherd 1.966 0.345 + ... + + Times are in msec.usec. OPTIONS ------- @@ -100,6 +126,45 @@ OPTIONS for 'perf kwork latency' stop time is not given (i.e, time string is 'x.y,') then analysis goes to end of file. +OPTIONS for 'perf kwork timehist' +--------------------------------- + +-C:: +--cpu:: + Only show events for the given CPU(s) (comma separated list). + +-g:: +--call-graph:: + Display call chains if present (default off). + +-i:: +--input:: + Input file name. (default: perf.data unless stdin is a fifo) + +-k:: +--vmlinux=<file>:: + Vmlinux pathname + +-n:: +--name:: + Only show events for the given name. + +--kallsyms=<file>:: + Kallsyms pathname + +--max-stack:: + Maximum number of functions to display in backtrace, default 5. + +--symfs=<directory>:: + Look for files with symbols relative to this directory. + +--time:: + Only analyze samples within given time window: <start>,<stop>. Times + have the format seconds.microseconds. If start is not given (i.e., time + string is ',x.y') then analysis starts at the beginning of the file. If + stop time is not given (i.e, time string is 'x.y,') then analysis goes + to end of file. + SEE ALSO -------- linkperf:perf-record[1] |