lkml.org 
[lkml]   [2022]   [Jun]   [13]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
Subject[RFC 00/13] perf: Add perf kwork
Date
Sometimes, we need to analyze time properties of kernel work such as irq,
softirq, and workqueue, such as delay and running time of specific interrupts.
Currently, these events have kernel tracepoints, but perf tool does not
directly analyze the delay of these events

The perf-kwork tool is used to trace time properties of kernel work
(such as irq, softirq, and workqueue), including runtime, latency,
and timehist, using the infrastructure in the perf tools to allow
tracing extra targets

test case:

# perf kwork report

Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0007 | 3.488 ms | 1258 | 0.145 ms | 3398384.220013 s | 3398384.220157 s |
(s)NET_RX:3 | 0003 | 1.866 ms | 156 | 0.042 ms | 3398385.629764 s | 3398385.629806 s |
(s)TIMER:1 | 0000 | 1.799 ms | 117 | 0.055 ms | 3398385.568033 s | 3398385.568088 s |
(w)0xffff9c66e563ee98 | 0006 | 1.561 ms | 5 | 0.351 ms | 3398384.060021 s | 3398384.060371 s |
(s)RCU:9 | 0003 | 0.819 ms | 138 | 0.110 ms | 3398384.220018 s | 3398384.220128 s |
(s)TIMER:1 | 0006 | 0.548 ms | 149 | 0.022 ms | 3398385.404029 s | 3398385.404051 s |
(s)RCU:9 | 0005 | 0.525 ms | 52 | 0.147 ms | 3398384.208007 s | 3398384.208154 s |
ata_piix:14 | 0005 | 0.508 ms | 10 | 0.098 ms | 3398382.044203 s | 3398382.044301 s |
(s)RCU:9 | 0001 | 0.446 ms | 77 | 0.117 ms | 3398384.220017 s | 3398384.220134 s |
(s)RCU:9 | 0000 | 0.439 ms | 103 | 0.104 ms | 3398384.196011 s | 3398384.196115 s |
(w)0xffffffffc0793420 | 0006 | 0.376 ms | 57 | 0.017 ms | 3398386.700048 s | 3398386.700065 s |
(s)RCU:9 | 0002 | 0.319 ms | 50 | 0.103 ms | 3398384.196011 s | 3398384.196113 s |
(w)0xffff9c6698efbc08 | 0006 | 0.303 ms | 68 | 0.012 ms | 3398387.723996 s | 3398387.724008 s |
(w)0xffff9c66e321b1d0 | 0006 | 0.303 ms | 49 | 0.019 ms | 3398384.048042 s | 3398384.048061 s |
virtio4-input.0:38 | 0003 | 0.300 ms | 156 | 0.022 ms | 3398388.234593 s | 3398388.234615 s |
(s)RCU:9 | 0006 | 0.297 ms | 92 | 0.066 ms | 3398384.228012 s | 3398384.228077 s |
(s)TIMER:1 | 0003 | 0.291 ms | 162 | 0.024 ms | 3398388.648012 s | 3398388.648036 s |
(s)SCHED:7 | 0003 | 0.271 ms | 103 | 0.005 ms | 3398384.780022 s | 3398384.780027 s |
(s)SCHED:7 | 0000 | 0.263 ms | 74 | 0.015 ms | 3398385.636036 s | 3398385.636050 s |
(s)RCU:9 | 0004 | 0.256 ms | 63 | 0.083 ms | 3398384.196015 s | 3398384.196099 s |
(s)SCHED:7 | 0006 | 0.248 ms | 100 | 0.012 ms | 3398385.404051 s | 3398385.404063 s |
(s)TIMER:1 | 0007 | 0.224 ms | 227 | 0.008 ms | 3398381.916020 s | 3398381.916028 s |
...
--------------------------------------------------------------------------------------------------------------------------

# perf kwork latency

Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(w)0xffff9c66f37deee0 | 0007 | 2.786 ms | 4 | 11.099 ms | 3398385.632034 s | 3398385.643133 s |
(w)0xffff9c6698efbc08 | 0006 | 0.033 ms | 39 | 0.383 ms | 3398385.630078 s | 3398385.630461 s |
(s)SCHED:7 | 0000 | 0.027 ms | 74 | 0.060 ms | 3398385.568029 s | 3398385.568089 s |
(s)RCU:9 | 0006 | 0.007 ms | 92 | 0.023 ms | 3398385.884016 s | 3398385.884039 s |
(s)RCU:9 | 0002 | 0.006 ms | 50 | 0.019 ms | 3398387.420012 s | 3398387.420031 s |
(s)RCU:9 | 0004 | 0.006 ms | 63 | 0.019 ms | 3398384.412019 s | 3398384.412039 s |
(s)SCHED:7 | 0001 | 0.006 ms | 30 | 0.015 ms | 3398386.908018 s | 3398386.908034 s |
(s)RCU:9 | 0005 | 0.006 ms | 52 | 0.016 ms | 3398387.492007 s | 3398387.492024 s |
(w)0xffff9c66e3f35040 | 0007 | 0.006 ms | 6 | 0.009 ms | 3398385.701201 s | 3398385.701210 s |
(w)0xffff9c66e45a79d0 | 0006 | 0.005 ms | 1 | 0.005 ms | 3398383.836011 s | 3398383.836016 s |
(w)0xffff9c66e50f40b8 | 0006 | 0.005 ms | 5 | 0.006 ms | 3398386.076145 s | 3398386.076151 s |
(s)SCHED:7 | 0004 | 0.005 ms | 27 | 0.013 ms | 3398380.412016 s | 3398380.412029 s |
(s)SCHED:7 | 0002 | 0.005 ms | 23 | 0.014 ms | 3398387.420013 s | 3398387.420027 s |
(s)RCU:9 | 0001 | 0.005 ms | 77 | 0.021 ms | 3398386.908017 s | 3398386.908038 s |
(s)SCHED:7 | 0003 | 0.005 ms | 103 | 0.027 ms | 3398388.648010 s | 3398388.648036 s |
(s)SCHED:7 | 0007 | 0.005 ms | 66 | 0.013 ms | 3398385.632026 s | 3398385.632039 s |
(s)TIMER:1 | 0007 | 0.005 ms | 227 | 0.015 ms | 3398385.636010 s | 3398385.636025 s |
(s)SCHED:7 | 0005 | 0.005 ms | 20 | 0.010 ms | 3398384.924020 s | 3398384.924030 s |
(s)TIMER:1 | 0000 | 0.004 ms | 117 | 0.009 ms | 3398385.568024 s | 3398385.568033 s |
(s)TIMER:1 | 0004 | 0.004 ms | 61 | 0.009 ms | 3398383.632005 s | 3398383.632014 s |
(s)RCU:9 | 0003 | 0.004 ms | 138 | 0.014 ms | 3398384.324014 s | 3398384.324028 s |
...
---------------------------------------------------------------------------------------------------------------------------
INFO: 2.133% skipped events (383 including 86 raise, 297 entry, 0 exit)

# perf kwork timehist
Runtime start Runtime end Cpu Kwork name Runtime Delaytime
(TYPE)NAME:NUM (msec) (msec)
----------------- ----------------- ------ ------------------------- ---------- ----------
3398378.780013 3398378.780014 [0007] (s)TIMER:1 0.001 0.005
3398378.780013 3398378.780014 [0000] (s)TIMER:1 0.001 0.006
3398378.780012 3398378.780015 [0004] (s)TIMER:1 0.002 0.005
3398378.780014 3398378.780017 [0007] (s)SCHED:7 0.003 0.004
3398378.780014 3398378.780017 [0000] (s)SCHED:7 0.002 0.005
3398378.780015 3398378.780017 [0004] (s)SCHED:7 0.002 0.005
3398378.780017 3398378.780018 [0004] (s)RCU:9 0.001 0.008
3398378.780017 3398378.780023 [0000] (s)RCU:9 0.006 0.008
3398378.780017 3398378.780030 [0007] (s)RCU:9 0.013 0.008
3398378.784008 3398378.784008 [0007] (s)TIMER:1 0.000 0.003
3398378.784008 3398378.784009 [0000] (s)TIMER:1 0.001 0.003
3398378.784009 3398378.784009 [0000] (s)RCU:9 0.001 0.003
3398378.784009 3398378.784010 [0007] (s)RCU:9 0.001 0.003
3398378.784650 3398378.784653 [0003] virtio4-input.0:38 0.003
3398378.784656 3398378.784672 [0003] (s)NET_RX:3 0.016 0.004
3398378.788007 3398378.788008 [0007] (s)TIMER:1 0.000 0.002
3398378.788008 3398378.788009 [0007] (s)RCU:9 0.001 0.003
3398378.788010 3398378.788011 [0000] (s)TIMER:1 0.001 0.003
3398378.788011 3398378.788012 [0000] (s)RCU:9 0.001 0.003
3398378.788009 3398378.788012 [0003] (s)TIMER:1 0.004 0.003
3398378.788013 3398378.788015 [0003] (s)SCHED:7 0.002 0.006
3398378.788015 3398378.788016 [0003] (s)RCU:9 0.001 0.009
3398378.788019 3398378.788021 [0003] (w)0xffff9c66f36deee0 0.002 0.009
3398378.792007 3398378.792008 [0007] (s)TIMER:1 0.000 0.002
3398378.792008 3398378.792009 [0000] (s)TIMER:1 0.000 0.002
3398378.792009 3398378.792014 [0000] (s)RCU:9 0.005 0.003
...

Yang Jihong (13):
perf kwork: New tool
perf kwork: Add irq record support
perf kwork: Add softirq record support
perf kwork: Add workqueue record support
tools lib: Add list_last_entry_or_null
perf kwork: Implement perf kwork report
perf kwork: Add irq report support
perf kwork: Add softirq report support
perf kwork: Add workqueue report support
perf kwork: Implement perf kwork latency
perf kwork: Add softirq latency support
perf kwork: Add workqueue latency support
perf kwork: Implement perf kwork timehist

tools/include/linux/list.h | 11 +
tools/perf/Build | 1 +
tools/perf/Documentation/perf-kwork.txt | 173 ++
tools/perf/builtin-kwork.c | 1915 +++++++++++++++++++++++
tools/perf/builtin.h | 1 +
tools/perf/command-list.txt | 1 +
tools/perf/perf.c | 1 +
7 files changed, 2103 insertions(+)
create mode 100644 tools/perf/Documentation/perf-kwork.txt
create mode 100644 tools/perf/builtin-kwork.c

--
2.30.GIT

\
 
 \ /
  Last update: 2022-06-13 11:49    [W:0.147 / U:0.368 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site