* [RFC 00/13] perf: Add perf kwork
@ 2022-06-13 9:45 Yang Jihong
2022-06-13 9:45 ` [RFC 01/13] perf kwork: New tool Yang Jihong
` (13 more replies)
0 siblings, 14 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:45 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
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
^ permalink raw reply [flat|nested] 28+ messages in thread
* [RFC 01/13] perf kwork: New tool
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
@ 2022-06-13 9:45 ` Yang Jihong
2022-06-14 21:43 ` Namhyung Kim
2022-06-13 9:45 ` [RFC 02/13] perf kwork: Add irq record support Yang Jihong
` (12 subsequent siblings)
13 siblings, 1 reply; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:45 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
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:
# perf kwork -h
Usage: perf kwork [<options>] {record|report|latency|timehist}
-D, --dump-raw-trace dump raw trace in ASCII
-f, --force don't complain, do it
-k, --kwork <kwork> list of kwork to profile (irq, softirq, workqueue etc)
-v, --verbose be more verbose (show symbol address, etc)
# perf kwork record -- sleep 1
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 1.696 MB perf.data ]
# perf kwork report -h
Usage: perf kwork report [<options>]
-C, --cpu <cpu> list of cpus to profile
-i, --input <file> input file name
-n, --name <name> event name to profile
-s, --sort <key[,key2...]>
sort by key(s): runtime, max, freq
-S, --with-summary Show summary with statistics
--time <str> Time span for analysis (start,stop)
# perf kwork latency -h
Usage: perf kwork latency [<options>]
-C, --cpu <cpu> list of cpus to profile
-i, --input <file> input file name
-n, --name <name> event name to profile
-s, --sort <key[,key2...]>
sort by key(s): avg, max, freq
--time <str> Time span for analysis (start,stop)
# perf kwork timehist -h
Usage: perf kwork timehist [<options>]
-C, --cpu <cpu> list of cpus to profile
-g, --call-graph Display call chains if present
-i, --input <file> input file name
-k, --vmlinux <file> vmlinux pathname
-n, --name <name> event name to profile
--kallsyms <file>
kallsyms pathname
--max-stack <n> Maximum number of functions to display backtrace.
--symfs <directory>
Look for files with symbols relative to this directory
--time <str> Time span for analysis (start,stop)
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/Build | 1 +
tools/perf/Documentation/perf-kwork.txt | 173 ++++++++++++++
tools/perf/builtin-kwork.c | 291 ++++++++++++++++++++++++
tools/perf/builtin.h | 1 +
tools/perf/command-list.txt | 1 +
tools/perf/perf.c | 1 +
6 files changed, 468 insertions(+)
create mode 100644 tools/perf/Documentation/perf-kwork.txt
create mode 100644 tools/perf/builtin-kwork.c
diff --git a/tools/perf/Build b/tools/perf/Build
index db61dbe2b543..496b096153bb 100644
--- a/tools/perf/Build
+++ b/tools/perf/Build
@@ -25,6 +25,7 @@ perf-y += builtin-data.o
perf-y += builtin-version.o
perf-y += builtin-c2c.o
perf-y += builtin-daemon.o
+perf-y += builtin-kwork.o
perf-$(CONFIG_TRACE) += builtin-trace.o
perf-$(CONFIG_LIBELF) += builtin-probe.o
diff --git a/tools/perf/Documentation/perf-kwork.txt b/tools/perf/Documentation/perf-kwork.txt
new file mode 100644
index 000000000000..59e0a36c527d
--- /dev/null
+++ b/tools/perf/Documentation/perf-kwork.txt
@@ -0,0 +1,173 @@
+perf-kwork(1)
+=============
+
+NAME
+----
+perf-kwork - Tool to trace/measure kernel work properties (latencies)
+
+SYNOPSIS
+--------
+[verse]
+'perf kwork' {record|report|latency|timehist}
+
+DESCRIPTION
+-----------
+There are several variants of 'perf kwork':
+
+ 'perf kwork record <command>' to record the kernel work
+ of an arbitrary workload.
+
+ 'perf kwork report' to report the per kwork runtime.
+
+ 'perf kwork latency' to report the per kwork latencies.
+
+ 'perf kwork script' to see a detailed trace of the workload that
+ was recorded (aliased to 'perf script' for now).
+
+ '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)0xffff888102fc14a0 1.966 0.345
+ ...
+
+ Times are in msec.usec.
+
+OPTIONS
+-------
+-D::
+--dump-raw-trace=::
+ Display verbose dump of the trace data.
+
+-f::
+--force::
+ Don't complain, do it.
+
+-k::
+--kwork::
+ list of kwork to profile (irq, softirq, workqueue etc)
+
+-v::
+--verbose::
+ Be more verbose. (show symbol address, etc)
+
+OPTIONS for 'perf kwork report'
+----------------------------
+
+-C::
+--cpu::
+ Only show events for the given CPU(s) (comma separated list).
+
+-i::
+--input::
+ Input file name. (default: perf.data unless stdin is a fifo)
+
+-n::
+--name::
+ Only show events for the given name.
+
+-s::
+--sort::
+ sort by key(s): runtime, max, freq
+
+-S::
+--with-summary::
+ Show summary with statistics
+
+--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.
+
+OPTIONS for 'perf kwork latency'
+----------------------------
+
+-C::
+--cpu::
+ Only show events for the given CPU(s) (comma separated list).
+
+-i::
+--input::
+ Input file name. (default: perf.data unless stdin is a fifo)
+
+-n::
+--name::
+ Only show events for the given name.
+
+-s::
+--sort::
+ sort by key(s): avg, max, freq
+
+--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.
+
+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]
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
new file mode 100644
index 000000000000..b89e41fcc568
--- /dev/null
+++ b/tools/perf/builtin-kwork.c
@@ -0,0 +1,291 @@
+// SPDX-License-Identifier: GPL-2.0
+#include "builtin.h"
+#include "perf.h"
+
+#include "util/data.h"
+#include "util/tool.h"
+#include "util/debug.h"
+#include "util/event.h"
+#include "util/evlist.h"
+#include "util/symbol.h"
+#include "util/thread.h"
+#include "util/session.h"
+#include "util/string2.h"
+#include "util/callchain.h"
+#include "util/time-utils.h"
+#include "util/evsel_fprintf.h"
+
+#include <subcmd/pager.h>
+#include <subcmd/parse-options.h>
+
+#include <errno.h>
+#include <inttypes.h>
+#include <linux/err.h>
+#include <linux/time64.h>
+#include <linux/zalloc.h>
+
+enum kwork_class_type {
+ KWORK_CLASS_MAX,
+};
+
+struct kwork_class {
+ struct list_head list;
+ const char *name;
+
+ unsigned int nr_tracepoints;
+ const struct evsel_str_handler *tp_handlers;
+};
+
+struct perf_kwork {
+ /*
+ * metadata
+ */
+ struct list_head class_list;
+
+ /*
+ * profile filters
+ */
+ const char *profile_name;
+
+ const char *cpu_list;
+ DECLARE_BITMAP(cpu_bitmap, MAX_NR_CPUS);
+
+ const char *time_str;
+ struct perf_time_interval ptime;
+
+ /*
+ * options for command
+ */
+ bool force;
+ const char *event_list_str;
+
+ /*
+ * options for subcommand
+ */
+ bool summary;
+ bool show_callchain;
+ unsigned int max_stack;
+ const char *sort_order;
+};
+
+static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] = {
+};
+
+static void setup_event_list(struct perf_kwork *kwork,
+ const struct option *options,
+ const char * const usage_msg[])
+{
+ int i;
+ struct kwork_class *class;
+ char *tmp, *tok, *str;
+
+ if (kwork->event_list_str == NULL)
+ goto null_event_list_str;
+
+ str = strdup(kwork->event_list_str);
+ for (tok = strtok_r(str, ", ", &tmp);
+ tok; tok = strtok_r(NULL, ", ", &tmp)) {
+ for (i = 0; i < KWORK_CLASS_MAX; i++) {
+ class = kwork_class_supported_list[i];
+ if (strcmp(tok, class->name) == 0) {
+ list_add_tail(&class->list, &kwork->class_list);
+ break;
+ }
+ }
+ if (i == KWORK_CLASS_MAX)
+ usage_with_options_msg(usage_msg, options,
+ "Unknown --event key: `%s'", tok);
+ }
+ free(str);
+
+null_event_list_str:
+ /*
+ * config all kwork events if not specified
+ */
+ if (list_empty(&kwork->class_list))
+ for (i = 0; i < KWORK_CLASS_MAX; i++)
+ list_add_tail(&kwork_class_supported_list[i]->list,
+ &kwork->class_list);
+
+ pr_debug("Config event list:");
+ list_for_each_entry(class, &kwork->class_list, list)
+ pr_debug(" %s", class->name);
+ pr_debug("\n");
+}
+
+static int perf_kwork__record(struct perf_kwork *kwork,
+ int argc, const char **argv)
+{
+ const char **rec_argv;
+ unsigned int rec_argc, i, j;
+ struct kwork_class *class;
+
+ const char *const record_args[] = {
+ "record",
+ "-a",
+ "-R",
+ "-m", "1024",
+ "-c", "1",
+ };
+
+ rec_argc = ARRAY_SIZE(record_args) + argc - 1;
+
+ list_for_each_entry(class, &kwork->class_list, list)
+ rec_argc += 2 * class->nr_tracepoints;
+
+ rec_argv = calloc(rec_argc + 1, sizeof(char *));
+ if (rec_argv == NULL)
+ return -ENOMEM;
+
+ for (i = 0; i < ARRAY_SIZE(record_args); i++)
+ rec_argv[i] = strdup(record_args[i]);
+
+ list_for_each_entry(class, &kwork->class_list, list) {
+ for (j = 0; j < class->nr_tracepoints; j++) {
+ rec_argv[i++] = strdup("-e");
+ rec_argv[i++] = strdup(class->tp_handlers[j].name);
+ }
+ }
+
+ for (j = 1; j < (unsigned int)argc; j++, i++)
+ rec_argv[i] = argv[j];
+
+ BUG_ON(i != rec_argc);
+
+ pr_debug("record comm: ");
+ for (j = 0; j < rec_argc; j++)
+ pr_debug("%s ", rec_argv[j]);
+ pr_debug("\n");
+
+ return cmd_record(i, rec_argv);
+}
+
+int cmd_kwork(int argc, const char **argv)
+{
+ static struct perf_kwork kwork = {
+ .class_list = LIST_HEAD_INIT(kwork.class_list),
+
+ .profile_name = NULL,
+ .cpu_list = NULL,
+ .time_str = NULL,
+ .force = false,
+ .event_list_str = NULL,
+ .summary = false,
+ .show_callchain = false,
+ .max_stack = 5,
+ .sort_order = NULL,
+ };
+
+ const struct option kwork_options[] = {
+ OPT_INCR('v', "verbose", &verbose,
+ "be more verbose (show symbol address, etc)"),
+ OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
+ "dump raw trace in ASCII"),
+ OPT_STRING('k', "kwork", &kwork.event_list_str, "kwork",
+ "list of kwork to profile (irq, softirq, workqueue etc)"),
+ OPT_BOOLEAN('f', "force", &kwork.force, "don't complain, do it"),
+ OPT_END()
+ };
+ const struct option latency_options[] = {
+ OPT_STRING('s', "sort", &kwork.sort_order, "key[,key2...]",
+ "sort by key(s): avg, max, freq"),
+ OPT_STRING('C', "cpu", &kwork.cpu_list, "cpu",
+ "list of cpus to profile"),
+ OPT_STRING('n', "name", &kwork.profile_name, "name",
+ "event name to profile"),
+ OPT_STRING(0, "time", &kwork.time_str, "str",
+ "Time span for analysis (start,stop)"),
+ OPT_STRING('i', "input", &input_name, "file",
+ "input file name"),
+ OPT_PARENT(kwork_options)
+ };
+ const struct option report_options[] = {
+ OPT_STRING('s', "sort", &kwork.sort_order, "key[,key2...]",
+ "sort by key(s): runtime, max, freq"),
+ OPT_STRING('C', "cpu", &kwork.cpu_list, "cpu",
+ "list of cpus to profile"),
+ OPT_STRING('n', "name", &kwork.profile_name, "name",
+ "event name to profile"),
+ OPT_STRING(0, "time", &kwork.time_str, "str",
+ "Time span for analysis (start,stop)"),
+ OPT_STRING('i', "input", &input_name, "file",
+ "input file name"),
+ OPT_BOOLEAN('S', "with-summary", &kwork.summary,
+ "Show summary with statistics"),
+ OPT_PARENT(kwork_options)
+ };
+ const struct option timehist_options[] = {
+ OPT_STRING('k', "vmlinux", &symbol_conf.vmlinux_name,
+ "file", "vmlinux pathname"),
+ OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name,
+ "file", "kallsyms pathname"),
+ OPT_BOOLEAN('g', "call-graph", &kwork.show_callchain,
+ "Display call chains if present"),
+ OPT_UINTEGER(0, "max-stack", &kwork.max_stack,
+ "Maximum number of functions to display backtrace."),
+ OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
+ "Look for files with symbols relative to this directory"),
+ OPT_STRING(0, "time", &kwork.time_str, "str",
+ "Time span for analysis (start,stop)"),
+ OPT_STRING('C', "cpu", &kwork.cpu_list, "cpu",
+ "list of cpus to profile"),
+ OPT_STRING('n', "name", &kwork.profile_name, "name",
+ "event name to profile"),
+ OPT_STRING('i', "input", &input_name, "file",
+ "input file name"),
+ OPT_PARENT(kwork_options)
+ };
+
+ const char *kwork_usage[] = {
+ NULL,
+ NULL
+ };
+ const char * const latency_usage[] = {
+ "perf kwork latency [<options>]",
+ NULL
+ };
+ const char * const report_usage[] = {
+ "perf kwork report [<options>]",
+ NULL
+ };
+ const char * const timehist_usage[] = {
+ "perf kwork timehist [<options>]",
+ NULL
+ };
+ const char *const kwork_subcommands[] = {
+ "record", "report", "latency", "timehist", NULL
+ };
+
+ argc = parse_options_subcommand(argc, argv, kwork_options,
+ kwork_subcommands, kwork_usage,
+ PARSE_OPT_STOP_AT_NON_OPTION);
+ if (!argc)
+ usage_with_options(kwork_usage, kwork_options);
+
+ setup_event_list(&kwork, kwork_options, kwork_usage);
+
+ if (strlen(argv[0]) > 2 && strstarts("record", argv[0])) {
+ return perf_kwork__record(&kwork, argc, argv);
+ } else if (strlen(argv[0]) > 2 && strstarts("report", argv[0])) {
+ if (argc > 1) {
+ argc = parse_options(argc, argv, report_options, report_usage, 0);
+ if (argc)
+ usage_with_options(report_usage, report_options);
+ }
+ } else if (strlen(argv[0]) > 2 && strstarts("latency", argv[0])) {
+ if (argc > 1) {
+ argc = parse_options(argc, argv, latency_options, latency_usage, 0);
+ if (argc)
+ usage_with_options(latency_usage, latency_options);
+ }
+ } else if (strlen(argv[0]) > 2 && strstarts("timehist", argv[0])) {
+ if (argc > 1) {
+ argc = parse_options(argc, argv, timehist_options, timehist_usage, 0);
+ if (argc)
+ usage_with_options(timehist_usage, timehist_options);
+ }
+ } else
+ usage_with_options(kwork_usage, kwork_options);
+
+ return 0;
+}
diff --git a/tools/perf/builtin.h b/tools/perf/builtin.h
index 7303e80a639c..d03afea86217 100644
--- a/tools/perf/builtin.h
+++ b/tools/perf/builtin.h
@@ -38,6 +38,7 @@ int cmd_mem(int argc, const char **argv);
int cmd_data(int argc, const char **argv);
int cmd_ftrace(int argc, const char **argv);
int cmd_daemon(int argc, const char **argv);
+int cmd_kwork(int argc, const char **argv);
int find_scripts(char **scripts_array, char **scripts_path_array, int num,
int pathlen);
diff --git a/tools/perf/command-list.txt b/tools/perf/command-list.txt
index 4aa034aefa33..295418840426 100644
--- a/tools/perf/command-list.txt
+++ b/tools/perf/command-list.txt
@@ -18,6 +18,7 @@ perf-iostat mainporcelain common
perf-kallsyms mainporcelain common
perf-kmem mainporcelain common
perf-kvm mainporcelain common
+perf-kwork mainporcelain common
perf-list mainporcelain common
perf-lock mainporcelain common
perf-mem mainporcelain common
diff --git a/tools/perf/perf.c b/tools/perf/perf.c
index 0170cb0819d6..c21b3973641a 100644
--- a/tools/perf/perf.c
+++ b/tools/perf/perf.c
@@ -91,6 +91,7 @@ static struct cmd_struct commands[] = {
{ "data", cmd_data, 0 },
{ "ftrace", cmd_ftrace, 0 },
{ "daemon", cmd_daemon, 0 },
+ { "kwork", cmd_kwork, 0 },
};
struct pager_config {
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 02/13] perf kwork: Add irq record support
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
2022-06-13 9:45 ` [RFC 01/13] perf kwork: New tool Yang Jihong
@ 2022-06-13 9:45 ` Yang Jihong
2022-06-13 9:45 ` [RFC 03/13] perf kwork: Add softirq " Yang Jihong
` (11 subsequent siblings)
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:45 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Record interrupt events irq:irq_handler_entry & irq_handler_exit:
Record irq events:
# perf kwork record -o perf_kwork.date -- sleep 1
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 0.524 MB perf_kwork.date ]
# perf evlist -i perf_kwork.date
irq:irq_handler_entry
irq:irq_handler_exit
dummy:HG
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 13 +++++++++++++
1 file changed, 13 insertions(+)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index b89e41fcc568..822904b2597e 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -25,6 +25,7 @@
#include <linux/zalloc.h>
enum kwork_class_type {
+ KWORK_CLASS_IRQ,
KWORK_CLASS_MAX,
};
@@ -68,7 +69,19 @@ struct perf_kwork {
const char *sort_order;
};
+const struct evsel_str_handler irq_tp_handlers[] = {
+ { "irq:irq_handler_entry", NULL, },
+ { "irq:irq_handler_exit", NULL, },
+};
+
+static struct kwork_class kwork_irq = {
+ .name = "irq",
+ .nr_tracepoints = 2,
+ .tp_handlers = irq_tp_handlers,
+};
+
static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] = {
+ [KWORK_CLASS_IRQ] = &kwork_irq,
};
static void setup_event_list(struct perf_kwork *kwork,
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 03/13] perf kwork: Add softirq record support
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
2022-06-13 9:45 ` [RFC 01/13] perf kwork: New tool Yang Jihong
2022-06-13 9:45 ` [RFC 02/13] perf kwork: Add irq record support Yang Jihong
@ 2022-06-13 9:45 ` Yang Jihong
2022-06-13 9:45 ` [RFC 04/13] perf kwork: Add workqueue " Yang Jihong
` (10 subsequent siblings)
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:45 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Record softirq events irq:softirq_raise, irq:softirq_entry &
irq:softirq_exit.
Record all events:
# perf kwork record -o perf_kwork.date -- sleep 1
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 0.736 MB perf_kwork.date ]
# perf evlist -i perf_kwork.date
irq:irq_handler_entry
irq:irq_handler_exit
irq:softirq_raise
irq:softirq_entry
irq:softirq_exit
dummy:HG
Record softirq events:
# perf kwork -k softirq record -o perf_kwork.date -- sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.165 MB perf_kwork.date ]
# perf evlist -i perf_kwork.date
irq:softirq_raise
irq:softirq_entry
irq:softirq_exit
dummy:HG
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 14 ++++++++++++++
1 file changed, 14 insertions(+)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index 822904b2597e..0da554e04f16 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -26,6 +26,7 @@
enum kwork_class_type {
KWORK_CLASS_IRQ,
+ KWORK_CLASS_SOFTIRQ,
KWORK_CLASS_MAX,
};
@@ -80,8 +81,21 @@ static struct kwork_class kwork_irq = {
.tp_handlers = irq_tp_handlers,
};
+const struct evsel_str_handler softirq_tp_handlers[] = {
+ { "irq:softirq_raise", NULL, },
+ { "irq:softirq_entry", NULL, },
+ { "irq:softirq_exit", NULL, },
+};
+
+static struct kwork_class kwork_softirq = {
+ .name = "softirq",
+ .nr_tracepoints = 3,
+ .tp_handlers = softirq_tp_handlers,
+};
+
static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] = {
[KWORK_CLASS_IRQ] = &kwork_irq,
+ [KWORK_CLASS_SOFTIRQ] = &kwork_softirq,
};
static void setup_event_list(struct perf_kwork *kwork,
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 04/13] perf kwork: Add workqueue record support
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (2 preceding siblings ...)
2022-06-13 9:45 ` [RFC 03/13] perf kwork: Add softirq " Yang Jihong
@ 2022-06-13 9:45 ` Yang Jihong
2022-06-13 9:45 ` [RFC 05/13] tools lib: Add list_last_entry_or_null Yang Jihong
` (9 subsequent siblings)
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:45 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Record workqueue events workqueue:workqueue_activate_work,
workqueue:workqueue_execute_start & workqueue:workqueue_execute_end
Record all events:
# perf kwork record -o perf_kwork.date -- sleep 1
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 0.839 MB perf_kwork.date ]
# perf evlist -i perf_kwork.date
irq:irq_handler_entry
irq:irq_handler_exit
irq:softirq_raise
irq:softirq_entry
irq:softirq_exit
workqueue:workqueue_activate_work
workqueue:workqueue_execute_start
workqueue:workqueue_execute_end
dummy:HG
Record workqueue events:
# perf kwork -k workqueue record -o perf_kwork.date -- sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.080 MB perf_kwork.date ]
# perf evlist -i perf_kwork.date
workqueue:workqueue_activate_work
workqueue:workqueue_execute_start
workqueue:workqueue_execute_end
dummy:HG
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 14 ++++++++++++++
1 file changed, 14 insertions(+)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index 0da554e04f16..cda6fcbc6e41 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -27,6 +27,7 @@
enum kwork_class_type {
KWORK_CLASS_IRQ,
KWORK_CLASS_SOFTIRQ,
+ KWORK_CLASS_WORKQUEUE,
KWORK_CLASS_MAX,
};
@@ -93,9 +94,22 @@ static struct kwork_class kwork_softirq = {
.tp_handlers = softirq_tp_handlers,
};
+const struct evsel_str_handler workqueue_tp_handlers[] = {
+ { "workqueue:workqueue_activate_work", NULL, },
+ { "workqueue:workqueue_execute_start", NULL, },
+ { "workqueue:workqueue_execute_end", NULL, },
+};
+
+static struct kwork_class kwork_workqueue = {
+ .name = "workqueue",
+ .nr_tracepoints = 3,
+ .tp_handlers = workqueue_tp_handlers,
+};
+
static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] = {
[KWORK_CLASS_IRQ] = &kwork_irq,
[KWORK_CLASS_SOFTIRQ] = &kwork_softirq,
+ [KWORK_CLASS_WORKQUEUE] = &kwork_workqueue,
};
static void setup_event_list(struct perf_kwork *kwork,
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 05/13] tools lib: Add list_last_entry_or_null
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (3 preceding siblings ...)
2022-06-13 9:45 ` [RFC 04/13] perf kwork: Add workqueue " Yang Jihong
@ 2022-06-13 9:45 ` Yang Jihong
2022-06-13 9:45 ` [RFC 06/13] perf kwork: Implement perf kwork report Yang Jihong
` (8 subsequent siblings)
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:45 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Add list_last_entry_or_null to get the last element from a list,
returns NULL if the list is empty.
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/include/linux/list.h | 11 +++++++++++
1 file changed, 11 insertions(+)
diff --git a/tools/include/linux/list.h b/tools/include/linux/list.h
index b2fc48d5478c..a4dfb6a7cc6a 100644
--- a/tools/include/linux/list.h
+++ b/tools/include/linux/list.h
@@ -384,6 +384,17 @@ static inline void list_splice_tail_init(struct list_head *list,
#define list_first_entry_or_null(ptr, type, member) \
(!list_empty(ptr) ? list_first_entry(ptr, type, member) : NULL)
+/**
+ * list_last_entry_or_null - get the last element from a list
+ * @ptr: the list head to take the element from.
+ * @type: the type of the struct this is embedded in.
+ * @member: the name of the list_head within the struct.
+ *
+ * Note that if the list is empty, it returns NULL.
+ */
+#define list_last_entry_or_null(ptr, type, member) \
+ (!list_empty(ptr) ? list_last_entry(ptr, type, member) : NULL)
+
/**
* list_next_entry - get the next element in list
* @pos: the type * to cursor
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 06/13] perf kwork: Implement perf kwork report
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (4 preceding siblings ...)
2022-06-13 9:45 ` [RFC 05/13] tools lib: Add list_last_entry_or_null Yang Jihong
@ 2022-06-13 9:45 ` Yang Jihong
2022-06-14 21:49 ` Namhyung Kim
2022-06-13 9:45 ` [RFC 07/13] perf kwork: Add irq report support Yang Jihong
` (7 subsequent siblings)
13 siblings, 1 reply; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:45 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Implements framework of perf kwork report, which is used to report time
properties such as run time and frequency:
test case:
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------
Since there are no report supported events, the output is empty.
Briefly describe the data structure:
1. "class" indicates event type. For example, irq and softiq correspond
to different types.
2. "cluster" refers to a specific event corresponding to a type. For
example, RCU and TIMER in softirq correspond to different clusters,
which contains three types of events: raise, entry, and exit.
3. "atom" includes time of each sample and sample of the previous phase.
(For example, exit corresponds to entry, which is used for timehist.)
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 937 +++++++++++++++++++++++++++++++++++++
1 file changed, 937 insertions(+)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index cda6fcbc6e41..ec199942150f 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -31,19 +31,122 @@ enum kwork_class_type {
KWORK_CLASS_MAX,
};
+enum kwork_trace_type {
+ KWORK_TRACE_ENTRY,
+ KWORK_TRACE_EXIT,
+ KWORK_TRACE_MAX,
+};
+
+enum kwork_report_type {
+ KWORK_REPORT_RUNTIME,
+};
+
+/*
+ * data structure:
+ * perf_kwork --> kwork_class (irq) --> kwork_cluster (RCU) --> atom_list (KWROK_TRACE_RAISE)
+ * | | |-> atom_list (KWROK_TRACE_ENTRY)
+ * | | -> atom_list (KWROK_TRACE_EXIT)
+ * | |
+ * | |-> kwork_cluster (TIMER) --> atom_list (KWROK_TRACE_RAISE)
+ * | | |-> atom_list (KWROK_TRACE_ENTRY)
+ * | | -> atom_list (KWROK_TRACE_EXIT)
+ * | |
+ * | -> ...
+ * |
+ * |-> kwork_class (softirq) --> ...
+ * | |
+ * | -> ...
+ * |
+ * -> ...
+ */
+
+struct kwork_atom {
+ struct list_head list;
+ u64 time;
+ struct kwork_atom *prev;
+
+ void *page_addr;
+ unsigned long bit_inpage;
+};
+
+#define NR_ATOM_PER_PAGE 128
+struct kwork_atom_page {
+ struct list_head list;
+ struct kwork_atom atoms[NR_ATOM_PER_PAGE];
+ DECLARE_BITMAP(bitmap, NR_ATOM_PER_PAGE);
+};
+
+struct kwork_class;
+struct kwork_cluster {
+ /*
+ * class field
+ */
+ struct rb_node node;
+ struct kwork_class *class;
+
+ /*
+ * cluster filed
+ */
+ u64 id;
+ int cpu;
+ char *name;
+
+ /*
+ * atom field
+ */
+ u64 nr_atoms;
+ struct list_head atom_list[KWORK_TRACE_MAX];
+
+ /*
+ * runtime report
+ */
+ u64 max_runtime;
+ u64 max_runtime_start;
+ u64 max_runtime_end;
+ u64 total_runtime;
+};
+
struct kwork_class {
struct list_head list;
const char *name;
unsigned int nr_tracepoints;
const struct evsel_str_handler *tp_handlers;
+
+ struct rb_root_cached cluster_root;
+
+ int (*class_init)(struct kwork_class *class,
+ struct perf_session *session);
+
+ void (*cluster_init)(struct kwork_class *class,
+ struct kwork_cluster *cluster,
+ struct evsel *evsel, struct perf_sample *sample);
+
+ void (*cluster_name)(struct kwork_cluster *cluster,
+ char *buf, int len);
+};
+
+struct perf_kwork;
+struct trace_kwork_handler {
+ int (*entry_event)(struct perf_kwork *kwork,
+ struct kwork_class *class, struct evsel *evsel,
+ struct perf_sample *sample, struct machine *machine);
+
+ int (*exit_event)(struct perf_kwork *kwork,
+ struct kwork_class *class, struct evsel *evsel,
+ struct perf_sample *sample, struct machine *machine);
};
struct perf_kwork {
/*
* metadata
*/
+ struct perf_tool tool;
struct list_head class_list;
+ struct list_head atom_page_list;
+ struct list_head sort_list, cmp_id;
+ struct rb_root_cached sorted_cluster_root;
+ const struct trace_kwork_handler *tp_handler;
/*
* profile filters
@@ -61,6 +164,7 @@ struct perf_kwork {
*/
bool force;
const char *event_list_str;
+ enum kwork_report_type report;
/*
* options for subcommand
@@ -69,8 +173,472 @@ struct perf_kwork {
bool show_callchain;
unsigned int max_stack;
const char *sort_order;
+
+ /*
+ * statistics
+ */
+ u64 timestart;
+ u64 timeend;
+
+ unsigned long nr_events;
+ unsigned long nr_lost_chunks;
+ unsigned long nr_lost_events;
+
+ u64 all_runtime;
+ u64 all_count;
+ u64 nr_skipped_events[KWORK_TRACE_MAX + 1];
+};
+
+/*
+ * report header elements width
+ */
+#define PRINT_CPU_WIDTH 4
+#define PRINT_FREQ_WIDTH 9
+#define PRINT_RUNTIME_WIDTH 10
+#define PRINT_TIMESTAMP_WIDTH 17
+#define PRINT_KWORK_NAME_WIDTH 25
+#define RPINT_DECIMAL_WIDTH 3
+#define PRINT_TIME_UNIT_SEC_WIDTH 2
+#define PRINT_TIME_UNIT_MESC_WIDTH 3
+#define PRINT_RUNTIME_HEADER_WIDTH (PRINT_RUNTIME_WIDTH + PRINT_TIME_UNIT_MESC_WIDTH)
+#define PRINT_TIMESTAMP_HEADER_WIDTH (PRINT_TIMESTAMP_WIDTH + PRINT_TIME_UNIT_SEC_WIDTH)
+
+struct sort_dimension {
+ const char *name;
+ int (*cmp)(struct kwork_cluster *l, struct kwork_cluster *r);
+ struct list_head list;
};
+static int id_cmp(struct kwork_cluster *l, struct kwork_cluster *r)
+{
+ if (l->cpu > r->cpu)
+ return 1;
+ if (l->cpu < r->cpu)
+ return -1;
+
+ if (l->id > r->id)
+ return 1;
+ if (l->id < r->id)
+ return -1;
+
+ return 0;
+}
+
+static int freq_cmp(struct kwork_cluster *l, struct kwork_cluster *r)
+{
+ if (l->nr_atoms > r->nr_atoms)
+ return 1;
+ if (l->nr_atoms < r->nr_atoms)
+ return -1;
+
+ return 0;
+}
+
+static int runtime_cmp(struct kwork_cluster *l, struct kwork_cluster *r)
+{
+ if (l->total_runtime > r->total_runtime)
+ return 1;
+ if (l->total_runtime < r->total_runtime)
+ return -1;
+
+ return 0;
+}
+
+static int max_runtime_cmp(struct kwork_cluster *l, struct kwork_cluster *r)
+{
+ if (l->max_runtime > r->max_runtime)
+ return 1;
+ if (l->max_runtime < r->max_runtime)
+ return -1;
+
+ return 0;
+}
+
+static int sort_dimension__add(struct perf_kwork *kwork __maybe_unused,
+ const char *tok, struct list_head *list)
+{
+ size_t i;
+ static struct sort_dimension max_sort_dimension = {
+ .name = "max",
+ .cmp = max_runtime_cmp,
+ };
+ static struct sort_dimension id_sort_dimension = {
+ .name = "id",
+ .cmp = id_cmp,
+ };
+ static struct sort_dimension runtime_sort_dimension = {
+ .name = "runtime",
+ .cmp = runtime_cmp,
+ };
+ static struct sort_dimension freq_sort_dimension = {
+ .name = "freq",
+ .cmp = freq_cmp,
+ };
+ struct sort_dimension *available_sorts[] = {
+ &id_sort_dimension,
+ &max_sort_dimension,
+ &freq_sort_dimension,
+ &runtime_sort_dimension,
+ };
+
+ for (i = 0; i < ARRAY_SIZE(available_sorts); i++) {
+ if (!strcmp(available_sorts[i]->name, tok)) {
+ list_add_tail(&available_sorts[i]->list, list);
+ return 0;
+ }
+ }
+
+ return -1;
+}
+
+static void setup_sorting(struct perf_kwork *kwork,
+ const struct option *options,
+ const char * const usage_msg[])
+{
+ char *tmp, *tok, *str = strdup(kwork->sort_order);
+
+ for (tok = strtok_r(str, ", ", &tmp);
+ tok; tok = strtok_r(NULL, ", ", &tmp)) {
+ if (sort_dimension__add(kwork, tok, &kwork->sort_list) < 0)
+ usage_with_options_msg(usage_msg, options,
+ "Unknown --sort key: `%s'", tok);
+ }
+
+ pr_debug("Sort order: %s\n", kwork->sort_order);
+ free(str);
+}
+
+static struct kwork_atom *atom_new(struct perf_kwork *kwork,
+ struct perf_sample *sample)
+{
+ unsigned long i;
+ struct kwork_atom_page *page;
+ struct kwork_atom *atom = NULL;
+
+ list_for_each_entry(page, &kwork->atom_page_list, list) {
+ if (!bitmap_full(page->bitmap, NR_ATOM_PER_PAGE)) {
+ i = find_first_zero_bit(page->bitmap, NR_ATOM_PER_PAGE);
+ BUG_ON(i >= NR_ATOM_PER_PAGE);
+ atom = &page->atoms[i];
+ goto found_atom;
+ }
+ }
+
+ /*
+ * new page
+ */
+ page = zalloc(sizeof(*page));
+ if (page == NULL) {
+ pr_debug("Failed to zalloc kwork atom page\n");
+ return NULL;
+ }
+
+ i = 0;
+ atom = &page->atoms[0];
+ list_add_tail(&page->list, &kwork->atom_page_list);
+
+found_atom:
+ set_bit(i, page->bitmap);
+ atom->time = sample->time;
+ atom->prev = NULL;
+ atom->page_addr = page;
+ atom->bit_inpage = i;
+ return atom;
+}
+
+static void atom_free(struct kwork_atom *atom)
+{
+ if (atom->prev != NULL)
+ atom_free(atom->prev);
+
+ clear_bit(atom->bit_inpage,
+ ((struct kwork_atom_page *)atom->page_addr)->bitmap);
+}
+
+static void atom_del(struct kwork_atom *atom)
+{
+ list_del(&atom->list);
+ atom_free(atom);
+}
+
+static int cluster_cmp(struct list_head *list,
+ struct kwork_cluster *l, struct kwork_cluster *r)
+{
+ int ret = 0;
+ struct sort_dimension *sort;
+
+ BUG_ON(list_empty(list));
+
+ list_for_each_entry(sort, list, list) {
+ ret = sort->cmp(l, r);
+ if (ret)
+ return ret;
+ }
+
+ return ret;
+}
+
+static struct kwork_cluster *cluster_search(struct rb_root_cached *root,
+ struct kwork_cluster *key,
+ struct list_head *sort_list)
+{
+ int cmp;
+ struct kwork_cluster *cluster;
+ struct rb_node *node = root->rb_root.rb_node;
+
+ while (node) {
+ cluster = container_of(node, struct kwork_cluster, node);
+ cmp = cluster_cmp(sort_list, key, cluster);
+ if (cmp > 0)
+ node = node->rb_left;
+ else if (cmp < 0)
+ node = node->rb_right;
+ else {
+ if (cluster->name == NULL)
+ cluster->name = key->name;
+ return cluster;
+ }
+ }
+ return NULL;
+}
+
+static void cluster_insert(struct rb_root_cached *root,
+ struct kwork_cluster *key, struct list_head *sort_list)
+{
+ int cmp;
+ bool leftmost = true;
+ struct kwork_cluster *cur;
+ struct rb_node **new = &(root->rb_root.rb_node), *parent = NULL;
+
+ while (*new) {
+ cur = container_of(*new, struct kwork_cluster, node);
+ parent = *new;
+ cmp = cluster_cmp(sort_list, key, cur);
+
+ if (cmp > 0)
+ new = &((*new)->rb_left);
+ else {
+ new = &((*new)->rb_right);
+ leftmost = false;
+ }
+ }
+
+ rb_link_node(&key->node, parent, new);
+ rb_insert_color_cached(&key->node, root, leftmost);
+}
+
+static struct kwork_cluster *cluster_new(struct kwork_cluster *key)
+{
+ int i;
+ struct kwork_cluster *cluster = zalloc(sizeof(*cluster));
+
+ if (cluster == NULL) {
+ pr_debug("Failed to zalloc kwork cluster\n");
+ return NULL;
+ }
+
+ for (i = 0; i < KWORK_TRACE_MAX; i++)
+ INIT_LIST_HEAD(&cluster->atom_list[i]);
+
+ cluster->id = key->id;
+ cluster->cpu = key->cpu;
+ cluster->name = key->name;
+ cluster->class = key->class;
+ return cluster;
+}
+
+static struct kwork_cluster *cluster_findnew(struct rb_root_cached *root,
+ struct kwork_cluster *key,
+ struct list_head *sort_list)
+{
+ struct kwork_cluster *cluster = NULL;
+
+ cluster = cluster_search(root, key, sort_list);
+ if (cluster != NULL)
+ return cluster;
+
+ cluster = cluster_new(key);
+ if (cluster == NULL)
+ return NULL;
+
+ cluster_insert(root, cluster, sort_list);
+ return cluster;
+}
+
+static void profile_update_timespan(struct perf_kwork *kwork,
+ struct perf_sample *sample)
+{
+ if (!kwork->summary)
+ return;
+
+ if ((kwork->timestart == 0) || (kwork->timestart > sample->time))
+ kwork->timestart = sample->time;
+
+ if (kwork->timeend < sample->time)
+ kwork->timeend = sample->time;
+}
+
+static bool profile_event_match(struct perf_kwork *kwork,
+ struct kwork_cluster *cluster,
+ struct perf_sample *sample)
+{
+ int cpu = cluster->cpu;
+ u64 time = sample->time;
+ struct perf_time_interval *ptime = &kwork->ptime;
+
+ if ((kwork->cpu_list != NULL) && !test_bit(cpu, kwork->cpu_bitmap))
+ return false;
+
+ if (((ptime->start != 0) && (ptime->start > time)) ||
+ ((ptime->end != 0) && (ptime->end < time)))
+ return false;
+
+ if ((kwork->profile_name != NULL) &&
+ ((cluster->name == NULL) ||
+ (strcmp(cluster->name, kwork->profile_name) != 0)))
+ return false;
+
+ profile_update_timespan(kwork, sample);
+ return true;
+}
+
+static int cluster_push_atom(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ enum kwork_trace_type src_type,
+ enum kwork_trace_type dst_type,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct kwork_cluster **ret_cluster)
+{
+ struct kwork_atom *atom, *dst_atom;
+ struct kwork_cluster *cluster, key;
+
+ BUG_ON(class->cluster_init == NULL);
+ class->cluster_init(class, &key, evsel, sample);
+
+ atom = atom_new(kwork, sample);
+ if (atom == NULL)
+ return -1;
+
+ cluster = cluster_findnew(&class->cluster_root, &key, &kwork->cmp_id);
+ if (cluster == NULL) {
+ free(atom);
+ return -1;
+ }
+
+ if (!profile_event_match(kwork, cluster, sample))
+ return 0;
+
+ if ((dst_type >= 0) && (dst_type < KWORK_TRACE_MAX)) {
+ dst_atom = list_last_entry_or_null(&cluster->atom_list[dst_type],
+ struct kwork_atom, list);
+ if (dst_atom != NULL) {
+ atom->prev = dst_atom;
+ list_del(&dst_atom->list);
+ }
+ }
+
+ if (ret_cluster != NULL)
+ *ret_cluster = cluster;
+
+ list_add_tail(&atom->list, &cluster->atom_list[src_type]);
+
+ return 0;
+}
+
+static struct kwork_atom *cluster_pop_atom(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ enum kwork_trace_type src_type,
+ enum kwork_trace_type dst_type,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct kwork_cluster **ret_cluster)
+{
+ struct kwork_atom *atom, *src_atom;
+ struct kwork_cluster *cluster, key;
+
+ BUG_ON(class->cluster_init == NULL);
+ class->cluster_init(class, &key, evsel, sample);
+
+ cluster = cluster_findnew(&class->cluster_root, &key, &kwork->cmp_id);
+ if (ret_cluster != NULL)
+ *ret_cluster = cluster;
+
+ if (cluster == NULL)
+ return NULL;
+
+ if (!profile_event_match(kwork, cluster, sample))
+ return NULL;
+
+ atom = list_last_entry_or_null(&cluster->atom_list[dst_type],
+ struct kwork_atom, list);
+ if (atom != NULL)
+ return atom;
+
+ src_atom = atom_new(kwork, sample);
+ if (src_atom != NULL)
+ list_add_tail(&src_atom->list, &cluster->atom_list[src_type]);
+ else {
+ if (ret_cluster != NULL)
+ *ret_cluster = NULL;
+ }
+
+ return NULL;
+}
+
+static void report_update_exit_event(struct kwork_cluster *cluster,
+ struct kwork_atom *atom,
+ struct perf_sample *sample)
+{
+ u64 delta;
+ u64 exit_time = sample->time;
+ u64 entry_time = atom->time;
+
+ if ((entry_time != 0) && (exit_time >= entry_time)) {
+ delta = exit_time - entry_time;
+ if ((delta > cluster->max_runtime) ||
+ (cluster->max_runtime == 0)) {
+ cluster->max_runtime = delta;
+ cluster->max_runtime_start = entry_time;
+ cluster->max_runtime_end = exit_time;
+ }
+ cluster->total_runtime += delta;
+ cluster->nr_atoms++;
+ }
+}
+
+static int report_entry_event(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ return cluster_push_atom(kwork, class, KWORK_TRACE_ENTRY,
+ KWORK_TRACE_MAX, evsel, sample, NULL);
+}
+
+static int report_exit_event(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ struct kwork_atom *atom = NULL;
+ struct kwork_cluster *cluster = NULL;
+
+ atom = cluster_pop_atom(kwork, class, KWORK_TRACE_EXIT,
+ KWORK_TRACE_ENTRY, evsel, sample, &cluster);
+ if (cluster == NULL)
+ return -1;
+
+ if (atom != NULL) {
+ report_update_exit_event(cluster, atom, sample);
+ atom_del(atom);
+ }
+
+ return 0;
+}
+
const struct evsel_str_handler irq_tp_handlers[] = {
{ "irq:irq_handler_entry", NULL, },
{ "irq:irq_handler_exit", NULL, },
@@ -112,6 +680,182 @@ static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] = {
[KWORK_CLASS_WORKQUEUE] = &kwork_workqueue,
};
+static void print_separator(int len)
+{
+ printf(" %.*s\n", len, graph_dotted_line);
+}
+
+static void report_print_cluster(struct perf_kwork *kwork,
+ struct kwork_cluster *cluster)
+{
+ int ret = 0;
+ char kwork_name[PRINT_KWORK_NAME_WIDTH];
+ char max_runtime_start[32], max_runtime_end[32];
+
+ printf(" ");
+
+ /*
+ * kwork name
+ */
+ if (cluster->class && cluster->class->cluster_name) {
+ cluster->class->cluster_name(cluster, kwork_name,
+ PRINT_KWORK_NAME_WIDTH);
+ ret += printf(" %-*s |", PRINT_KWORK_NAME_WIDTH, kwork_name);
+ } else
+ ret += printf(" %-*s |", PRINT_KWORK_NAME_WIDTH, "");
+
+ /*
+ * cpu
+ */
+ ret += printf(" %0*d |", PRINT_CPU_WIDTH, cluster->cpu);
+
+ /*
+ * total runtime
+ */
+ if (kwork->report == KWORK_REPORT_RUNTIME)
+ ret += printf(" %*.*f ms |",
+ PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH,
+ (double)cluster->total_runtime / NSEC_PER_MSEC);
+
+ /*
+ * frequency
+ */
+ ret += printf(" %*" PRIu64 " |", PRINT_FREQ_WIDTH, cluster->nr_atoms);
+
+ /*
+ * max runtime, max runtime start, max runtime end
+ */
+ if (kwork->report == KWORK_REPORT_RUNTIME) {
+
+ timestamp__scnprintf_usec(cluster->max_runtime_start,
+ max_runtime_start,
+ sizeof(max_runtime_start));
+ timestamp__scnprintf_usec(cluster->max_runtime_end,
+ max_runtime_end,
+ sizeof(max_runtime_end));
+ ret += printf(" %*.*f ms | %*s s | %*s s |",
+ PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH,
+ (double)cluster->max_runtime / NSEC_PER_MSEC,
+ PRINT_TIMESTAMP_WIDTH, max_runtime_start,
+ PRINT_TIMESTAMP_WIDTH, max_runtime_end);
+ }
+
+ printf("\n");
+}
+
+static int report_print_header(struct perf_kwork *kwork)
+{
+ int ret;
+
+ printf("\n ");
+ ret = printf(" %-*s | %-*s |",
+ PRINT_KWORK_NAME_WIDTH, "Kwork Name",
+ PRINT_CPU_WIDTH, "Cpu");
+
+ if (kwork->report == KWORK_REPORT_RUNTIME)
+ ret += printf(" %-*s |",
+ PRINT_RUNTIME_HEADER_WIDTH, "Total Runtime");
+
+ ret += printf(" %-*s |", PRINT_FREQ_WIDTH, "Frequency");
+
+ if (kwork->report == KWORK_REPORT_RUNTIME)
+ ret += printf(" %-*s | %-*s | %-*s |",
+ PRINT_RUNTIME_HEADER_WIDTH, "Max runtime",
+ PRINT_TIMESTAMP_HEADER_WIDTH, "Max runtime start",
+ PRINT_TIMESTAMP_HEADER_WIDTH, "Max runtime end");
+
+ printf("\n");
+ print_separator(ret);
+ return ret;
+}
+
+static void print_summary(struct perf_kwork *kwork)
+{
+ u64 time = kwork->timeend - kwork->timestart;
+
+ printf(" Total count : %9" PRIu64 "\n", kwork->all_count);
+ printf(" Total runtime (msec) : %9.3f (%.3f%% load average)\n",
+ (double)kwork->all_runtime / NSEC_PER_MSEC,
+ (double)kwork->all_runtime / time);
+ printf(" Total time span (msec) : %9.3f\n",
+ (double)time / NSEC_PER_MSEC);
+}
+
+static unsigned long long nr_list_entry(struct list_head *head)
+{
+ struct list_head *pos;
+ unsigned long long n = 0;
+
+ list_for_each(pos, head)
+ n++;
+
+ return n;
+}
+
+static void print_skipped_events(struct perf_kwork *kwork)
+{
+ int i;
+ const char *const kwork_event_str[] = {
+ [KWORK_TRACE_ENTRY] = "entry",
+ [KWORK_TRACE_EXIT] = "exit",
+ };
+
+ if ((kwork->nr_skipped_events[KWORK_TRACE_MAX] != 0) &&
+ (kwork->nr_events != 0)) {
+ printf(" INFO: %.3f%% skipped events (%" PRIu64 " including ",
+ (double)kwork->nr_skipped_events[KWORK_TRACE_MAX] /
+ (double)kwork->nr_events * 100.0,
+ kwork->nr_skipped_events[KWORK_TRACE_MAX]);
+
+ for (i = 0; i < KWORK_TRACE_MAX; i++)
+ printf("%" PRIu64 " %s%s",
+ kwork->nr_skipped_events[i],
+ kwork_event_str[i],
+ (i == KWORK_TRACE_MAX - 1) ? ")\n" : ", ");
+ }
+
+ if (verbose > 0)
+ printf(" INFO: use %lld atom pages\n",
+ nr_list_entry(&kwork->atom_page_list));
+}
+
+static void print_bad_events(struct perf_kwork *kwork)
+{
+ if ((kwork->nr_lost_events != 0) && (kwork->nr_events != 0))
+ printf(" INFO: %.3f%% lost events (%ld out of %ld, in %ld chunks)\n",
+ (double)kwork->nr_lost_events /
+ (double)kwork->nr_events * 100.0,
+ kwork->nr_lost_events, kwork->nr_events,
+ kwork->nr_lost_chunks);
+}
+
+static void cluster_sort(struct perf_kwork *kwork, struct kwork_class *class)
+{
+ struct rb_node *node;
+ struct kwork_cluster *data;
+ struct rb_root_cached *root = &class->cluster_root;
+
+ pr_debug("Sorting %s ...\n", class->name);
+ for (;;) {
+ node = rb_first_cached(root);
+ if (!node)
+ break;
+
+ rb_erase_cached(node, root);
+ data = rb_entry(node, struct kwork_cluster, node);
+ cluster_insert(&kwork->sorted_cluster_root,
+ data, &kwork->sort_list);
+ }
+}
+
+static void perf_kwork__sort(struct perf_kwork *kwork)
+{
+ struct kwork_class *class;
+
+ list_for_each_entry(class, &kwork->class_list, list)
+ cluster_sort(kwork, class);
+}
+
static void setup_event_list(struct perf_kwork *kwork,
const struct option *options,
const char * const usage_msg[])
@@ -154,6 +898,176 @@ static void setup_event_list(struct perf_kwork *kwork,
pr_debug("\n");
}
+static int perf_kwork__check_config(struct perf_kwork *kwork,
+ struct perf_session *session)
+{
+ int ret;
+ struct evsel *evsel;
+ struct kwork_class *class;
+
+ static struct trace_kwork_handler report_ops = {
+ .entry_event = report_entry_event,
+ .exit_event = report_exit_event,
+ };
+
+ switch (kwork->report) {
+ case KWORK_REPORT_RUNTIME:
+ kwork->tp_handler = &report_ops;
+ break;
+ default:
+ pr_debug("Invalid report type %d\n", kwork->report);
+ break;
+ }
+
+ list_for_each_entry(class, &kwork->class_list, list)
+ if ((class->class_init != NULL) &&
+ (class->class_init(class, session) != 0))
+ return -1;
+
+ if (kwork->cpu_list != NULL) {
+ ret = perf_session__cpu_bitmap(session,
+ kwork->cpu_list,
+ kwork->cpu_bitmap);
+ if (ret < 0) {
+ pr_debug("Invalid cpu bitmap\n");
+ return -1;
+ }
+ }
+
+ if (kwork->time_str != NULL) {
+ ret = perf_time__parse_str(&kwork->ptime, kwork->time_str);
+ if (ret != 0) {
+ pr_debug("Invalid time span\n");
+ return -1;
+ }
+ }
+
+ list_for_each_entry(evsel, &session->evlist->core.entries, core.node) {
+ if (kwork->show_callchain && !evsel__has_callchain(evsel)) {
+ pr_debug("Samples do not have callchains\n");
+ kwork->show_callchain = 0;
+ symbol_conf.use_callchain = 0;
+ }
+ }
+
+ sort_dimension__add(kwork, "id", &kwork->cmp_id);
+ return 0;
+}
+
+static int perf_kwork__read_events(struct perf_kwork *kwork)
+{
+ int ret = -1;
+ struct perf_session *session = NULL;
+
+ struct perf_data data = {
+ .path = input_name,
+ .mode = PERF_DATA_MODE_READ,
+ .force = kwork->force,
+ };
+
+ session = perf_session__new(&data, &kwork->tool);
+ if (IS_ERR(session)) {
+ pr_debug("Error creating perf session\n");
+ return PTR_ERR(session);
+ }
+
+ symbol__init(&session->header.env);
+
+ if (perf_kwork__check_config(kwork, session) != 0)
+ goto out_delete;
+
+ ret = perf_session__process_events(session);
+ if (ret) {
+ pr_debug("Failed to process events, error %d\n", ret);
+ goto out_delete;
+ }
+
+ kwork->nr_events = session->evlist->stats.nr_events[0];
+ kwork->nr_lost_events = session->evlist->stats.total_lost;
+ kwork->nr_lost_chunks = session->evlist->stats.nr_events[PERF_RECORD_LOST];
+
+out_delete:
+ perf_session__delete(session);
+ return ret;
+}
+
+static void process_skipped_events(struct perf_kwork *kwork,
+ struct kwork_cluster *cluster)
+{
+ int i;
+ unsigned long long count;
+
+ for (i = 0; i < KWORK_TRACE_MAX; i++) {
+ count = nr_list_entry(&cluster->atom_list[i]);
+ kwork->nr_skipped_events[i] += count;
+ kwork->nr_skipped_events[KWORK_TRACE_MAX] += count;
+ }
+}
+
+static int perf_kwork__report(struct perf_kwork *kwork)
+{
+ int ret;
+ struct rb_node *next;
+ struct kwork_cluster *cluster;
+
+ setup_pager();
+
+ if (perf_kwork__read_events(kwork) != 0)
+ return -1;
+
+ perf_kwork__sort(kwork);
+
+ ret = report_print_header(kwork);
+ next = rb_first_cached(&kwork->sorted_cluster_root);
+ while (next) {
+ cluster = rb_entry(next, struct kwork_cluster, node);
+ process_skipped_events(kwork, cluster);
+
+ if (cluster->nr_atoms != 0) {
+ report_print_cluster(kwork, cluster);
+ if (kwork->summary) {
+ kwork->all_runtime += cluster->total_runtime;
+ kwork->all_count += cluster->nr_atoms;
+ }
+ }
+ next = rb_next(next);
+ }
+ print_separator(ret);
+
+ if (kwork->summary) {
+ print_summary(kwork);
+ print_separator(ret);
+ }
+
+ print_bad_events(kwork);
+ print_skipped_events(kwork);
+ printf("\n");
+
+ return 0;
+}
+
+typedef int (*tracepoint_handler)(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine);
+
+static int perf_kwork__process_tracepoint_sample(struct perf_tool *tool,
+ union perf_event *event __maybe_unused,
+ struct perf_sample *sample,
+ struct evsel *evsel,
+ struct machine *machine)
+{
+ int err = 0;
+
+ if (evsel->handler != NULL) {
+ tracepoint_handler f = evsel->handler;
+
+ err = f(tool, evsel, sample, machine);
+ }
+
+ return err;
+}
+
static int perf_kwork__record(struct perf_kwork *kwork,
int argc, const char **argv)
{
@@ -203,8 +1117,18 @@ static int perf_kwork__record(struct perf_kwork *kwork,
int cmd_kwork(int argc, const char **argv)
{
+ static const char default_report_sort_order[] = "runtime, max, freq";
static struct perf_kwork kwork = {
+ .tool = {
+ .sample = perf_kwork__process_tracepoint_sample,
+ },
+
.class_list = LIST_HEAD_INIT(kwork.class_list),
+ .atom_page_list = LIST_HEAD_INIT(kwork.atom_page_list),
+ .sort_list = LIST_HEAD_INIT(kwork.sort_list),
+ .cmp_id = LIST_HEAD_INIT(kwork.cmp_id),
+ .sorted_cluster_root = RB_ROOT_CACHED,
+ .tp_handler = NULL,
.profile_name = NULL,
.cpu_list = NULL,
@@ -215,6 +1139,15 @@ int cmd_kwork(int argc, const char **argv)
.show_callchain = false,
.max_stack = 5,
.sort_order = NULL,
+
+ .timestart = 0,
+ .timeend = 0,
+ .nr_events = 0,
+ .nr_lost_chunks = 0,
+ .nr_lost_events = 0,
+ .all_runtime = 0,
+ .all_count = 0,
+ .nr_skipped_events = { 0 },
};
const struct option kwork_options[] = {
@@ -308,11 +1241,15 @@ int cmd_kwork(int argc, const char **argv)
if (strlen(argv[0]) > 2 && strstarts("record", argv[0])) {
return perf_kwork__record(&kwork, argc, argv);
} else if (strlen(argv[0]) > 2 && strstarts("report", argv[0])) {
+ kwork.sort_order = default_report_sort_order;
if (argc > 1) {
argc = parse_options(argc, argv, report_options, report_usage, 0);
if (argc)
usage_with_options(report_usage, report_options);
}
+ kwork.report = KWORK_REPORT_RUNTIME;
+ setup_sorting(&kwork, report_options, report_usage);
+ return perf_kwork__report(&kwork);
} else if (strlen(argv[0]) > 2 && strstarts("latency", argv[0])) {
if (argc > 1) {
argc = parse_options(argc, argv, latency_options, latency_usage, 0);
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 07/13] perf kwork: Add irq report support
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (5 preceding siblings ...)
2022-06-13 9:45 ` [RFC 06/13] perf kwork: Implement perf kwork report Yang Jihong
@ 2022-06-13 9:45 ` Yang Jihong
2022-06-13 9:46 ` [RFC 08/13] perf kwork: Add softirq " Yang Jihong
` (6 subsequent siblings)
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:45 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Implements irq kwork report function.
test case:
# perf kwork rep
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
virtio0-requests:25 | 0000 | 429.202 ms | 7155 | 0.937 ms | 1906657.581035 s | 1906657.581973 s |
eth0:10 | 0002 | 0.136 ms | 5 | 0.045 ms | 1906656.302257 s | 1906656.302301 s |
---------------------------------------------------------------------------------------------------------------------------
#
# perf kwork rep -C 2
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
eth0:10 | 0002 | 0.136 ms | 5 | 0.045 ms | 1906656.302257 s | 1906656.302301 s |
---------------------------------------------------------------------------------------------------------------------------
# perf kwork rep -C 1,2
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
eth0:10 | 0002 | 0.136 ms | 5 | 0.045 ms | 1906656.302257 s | 1906656.302301 s |
---------------------------------------------------------------------------------------------------------------------------
# perf kwork rep -n eth0
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
eth0:10 | 0002 | 0.136 ms | 5 | 0.045 ms | 1906656.302257 s | 1906656.302301 s |
---------------------------------------------------------------------------------------------------------------------------
# perf kwork rep -S
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
virtio0-requests:25 | 0000 | 429.202 ms | 7155 | 0.937 ms | 1906657.581035 s | 1906657.581973 s |
eth0:10 | 0002 | 0.136 ms | 5 | 0.045 ms | 1906656.302257 s | 1906656.302301 s |
---------------------------------------------------------------------------------------------------------------------------
Total count : 7160
Total runtime (msec) : 429.338 (0.142% load average)
Total time span (msec) : 3013.347
---------------------------------------------------------------------------------------------------------------------------
# perf kwork rep --time 1906657,
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
virtio0-requests:25 | 0000 | 228.631 ms | 3855 | 0.937 ms | 1906657.581035 s | 1906657.581973 s |
eth0:10 | 0002 | 0.092 ms | 4 | 0.034 ms | 1906658.614010 s | 1906658.614043 s |
---------------------------------------------------------------------------------------------------------------------------
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 62 ++++++++++++++++++++++++++++++++++++--
1 file changed, 60 insertions(+), 2 deletions(-)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index ec199942150f..5741a8ac3e41 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -639,15 +639,73 @@ static int report_exit_event(struct perf_kwork *kwork,
return 0;
}
+static struct kwork_class kwork_irq;
+static int process_irq_handler_entry_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
+
+ if (kwork->tp_handler->entry_event)
+ return kwork->tp_handler->entry_event(kwork, &kwork_irq,
+ evsel, sample, machine);
+ return 0;
+}
+
+static int process_irq_handler_exit_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
+
+ if (kwork->tp_handler->exit_event)
+ return kwork->tp_handler->exit_event(kwork, &kwork_irq,
+ evsel, sample, machine);
+ return 0;
+}
+
const struct evsel_str_handler irq_tp_handlers[] = {
- { "irq:irq_handler_entry", NULL, },
- { "irq:irq_handler_exit", NULL, },
+ { "irq:irq_handler_entry", process_irq_handler_entry_event, },
+ { "irq:irq_handler_exit", process_irq_handler_exit_event, },
};
+static int irq_class_init(struct kwork_class *class,
+ struct perf_session *session)
+{
+ if (perf_session__set_tracepoints_handlers(session, irq_tp_handlers)) {
+ pr_debug("Failed to set irq tracepoints handlers\n");
+ return -1;
+ }
+
+ class->cluster_root = RB_ROOT_CACHED;
+ return 0;
+}
+
+static void irq_cluster_init(struct kwork_class *class,
+ struct kwork_cluster *cluster,
+ struct evsel *evsel,
+ struct perf_sample *sample)
+{
+ cluster->class = class;
+ cluster->cpu = sample->cpu;
+ cluster->id = evsel__intval(evsel, sample, "irq");
+ cluster->name = evsel__strval(evsel, sample, "name");
+}
+
+static void irq_cluster_name(struct kwork_cluster *cluster, char *buf, int len)
+{
+ snprintf(buf, len, "%s:%" PRIu64 "", cluster->name, cluster->id);
+}
+
static struct kwork_class kwork_irq = {
.name = "irq",
.nr_tracepoints = 2,
.tp_handlers = irq_tp_handlers,
+ .class_init = irq_class_init,
+ .cluster_init = irq_cluster_init,
+ .cluster_name = irq_cluster_name,
};
const struct evsel_str_handler softirq_tp_handlers[] = {
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 08/13] perf kwork: Add softirq report support
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (6 preceding siblings ...)
2022-06-13 9:45 ` [RFC 07/13] perf kwork: Add irq report support Yang Jihong
@ 2022-06-13 9:46 ` Yang Jihong
2022-06-13 9:46 ` [RFC 09/13] perf kwork: Add workqueue " Yang Jihong
` (5 subsequent siblings)
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:46 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Implements softirq kwork report function.
test case:
# perf kwork rep
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
virtio0-requests:25 | 0000 | 1073.208 ms | 19333 | 1.331 ms | 2059360.096926 s | 2059360.098257 s |
(s)RCU:9 | 0001 | 169.534 ms | 3156 | 1.435 ms | 2059361.588639 s | 2059361.590074 s |
(s)TIMER:1 | 0003 | 150.007 ms | 2472 | 0.125 ms | 2059359.989698 s | 2059359.989823 s |
(s)RCU:9 | 0007 | 90.461 ms | 1578 | 0.978 ms | 2059362.073209 s | 2059362.074187 s |
(s)SCHED:7 | 0007 | 81.408 ms | 1984 | 1.120 ms | 2059358.259073 s | 2059358.260193 s |
(s)SCHED:7 | 0001 | 49.071 ms | 1148 | 0.090 ms | 2059364.592682 s | 2059364.592772 s |
(s)RCU:9 | 0003 | 41.725 ms | 1823 | 0.087 ms | 2059358.201654 s | 2059358.201742 s |
(s)SCHED:7 | 0003 | 27.001 ms | 629 | 0.116 ms | 2059358.207263 s | 2059358.207379 s |
(s)SCHED:7 | 0000 | 25.318 ms | 232 | 1.490 ms | 2059361.310045 s | 2059361.311535 s |
(s)RCU:9 | 0004 | 10.983 ms | 94 | 0.981 ms | 2059358.241061 s | 2059358.242042 s |
(s)RCU:9 | 0000 | 3.102 ms | 66 | 1.568 ms | 2059360.853075 s | 2059360.854643 s |
(s)TIMER:1 | 0001 | 2.207 ms | 27 | 0.108 ms | 2059363.117923 s | 2059363.118031 s |
(s)NET_RX:3 | 0002 | 1.065 ms | 6 | 0.903 ms | 2059359.985888 s | 2059359.986792 s |
(s)TIMER:1 | 0007 | 0.740 ms | 6 | 0.192 ms | 2059368.237655 s | 2059368.237847 s |
(s)RCU:9 | 0005 | 0.715 ms | 18 | 0.098 ms | 2059360.002711 s | 2059360.002810 s |
(s)TIMER:1 | 0000 | 0.704 ms | 7 | 0.130 ms | 2059360.850686 s | 2059360.850816 s |
(s)TIMER:1 | 0002 | 0.688 ms | 7 | 0.131 ms | 2059368.237258 s | 2059368.237389 s |
(s)SCHED:7 | 0002 | 0.637 ms | 9 | 0.177 ms | 2059362.689653 s | 2059362.689830 s |
(s)BLOCK:4 | 0007 | 0.586 ms | 4 | 0.174 ms | 2059362.620644 s | 2059362.620818 s |
(s)TIMER:1 | 0005 | 0.414 ms | 1 | 0.414 ms | 2059361.265364 s | 2059361.265778 s |
(s)SCHED:7 | 0005 | 0.406 ms | 7 | 0.078 ms | 2059361.265799 s | 2059361.265878 s |
(s)SCHED:7 | 0004 | 0.237 ms | 4 | 0.084 ms | 2059368.376924 s | 2059368.377008 s |
ata_piix:14 | 0002 | 0.221 ms | 4 | 0.096 ms | 2059362.610172 s | 2059362.610267 s |
(s)RCU:9 | 0002 | 0.208 ms | 9 | 0.030 ms | 2059359.279854 s | 2059359.279884 s |
(s)TIMER:1 | 0004 | 0.199 ms | 1 | 0.199 ms | 2059362.605271 s | 2059362.605471 s |
(s)TIMER:1 | 0006 | 0.196 ms | 2 | 0.108 ms | 2059358.207823 s | 2059358.207931 s |
(s)RCU:9 | 0006 | 0.150 ms | 4 | 0.077 ms | 2059358.209321 s | 2059358.209398 s |
eth0:10 | 0002 | 0.124 ms | 6 | 0.024 ms | 2059359.985835 s | 2059359.985859 s |
(s)SCHED:7 | 0006 | 0.046 ms | 1 | 0.046 ms | 2059360.046630 s | 2059360.046676 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.003% skipped events (3 including 0 entry, 3 exit)
# perf kwork -k softirq rep
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0001 | 169.534 ms | 3156 | 1.435 ms | 2059361.588639 s | 2059361.590074 s |
(s)TIMER:1 | 0003 | 150.007 ms | 2472 | 0.125 ms | 2059359.989698 s | 2059359.989823 s |
(s)RCU:9 | 0007 | 90.461 ms | 1578 | 0.978 ms | 2059362.073209 s | 2059362.074187 s |
(s)SCHED:7 | 0007 | 81.408 ms | 1984 | 1.120 ms | 2059358.259073 s | 2059358.260193 s |
(s)SCHED:7 | 0001 | 49.071 ms | 1148 | 0.090 ms | 2059364.592682 s | 2059364.592772 s |
(s)RCU:9 | 0003 | 41.725 ms | 1823 | 0.087 ms | 2059358.201654 s | 2059358.201742 s |
(s)SCHED:7 | 0003 | 27.001 ms | 629 | 0.116 ms | 2059358.207263 s | 2059358.207379 s |
(s)SCHED:7 | 0000 | 25.318 ms | 232 | 1.490 ms | 2059361.310045 s | 2059361.311535 s |
(s)RCU:9 | 0004 | 10.983 ms | 94 | 0.981 ms | 2059358.241061 s | 2059358.242042 s |
(s)RCU:9 | 0000 | 3.102 ms | 66 | 1.568 ms | 2059360.853075 s | 2059360.854643 s |
(s)TIMER:1 | 0001 | 2.207 ms | 27 | 0.108 ms | 2059363.117923 s | 2059363.118031 s |
(s)NET_RX:3 | 0002 | 1.065 ms | 6 | 0.903 ms | 2059359.985888 s | 2059359.986792 s |
(s)TIMER:1 | 0007 | 0.740 ms | 6 | 0.192 ms | 2059368.237655 s | 2059368.237847 s |
(s)RCU:9 | 0005 | 0.715 ms | 18 | 0.098 ms | 2059360.002711 s | 2059360.002810 s |
(s)TIMER:1 | 0000 | 0.704 ms | 7 | 0.130 ms | 2059360.850686 s | 2059360.850816 s |
(s)TIMER:1 | 0002 | 0.688 ms | 7 | 0.131 ms | 2059368.237258 s | 2059368.237389 s |
(s)SCHED:7 | 0002 | 0.637 ms | 9 | 0.177 ms | 2059362.689653 s | 2059362.689830 s |
(s)BLOCK:4 | 0007 | 0.586 ms | 4 | 0.174 ms | 2059362.620644 s | 2059362.620818 s |
(s)TIMER:1 | 0005 | 0.414 ms | 1 | 0.414 ms | 2059361.265364 s | 2059361.265778 s |
(s)SCHED:7 | 0005 | 0.406 ms | 7 | 0.078 ms | 2059361.265799 s | 2059361.265878 s |
(s)SCHED:7 | 0004 | 0.237 ms | 4 | 0.084 ms | 2059368.376924 s | 2059368.377008 s |
(s)RCU:9 | 0002 | 0.208 ms | 9 | 0.030 ms | 2059359.279854 s | 2059359.279884 s |
(s)TIMER:1 | 0004 | 0.199 ms | 1 | 0.199 ms | 2059362.605271 s | 2059362.605471 s |
(s)TIMER:1 | 0006 | 0.196 ms | 2 | 0.108 ms | 2059358.207823 s | 2059358.207931 s |
(s)RCU:9 | 0006 | 0.150 ms | 4 | 0.077 ms | 2059358.209321 s | 2059358.209398 s |
(s)SCHED:7 | 0006 | 0.046 ms | 1 | 0.046 ms | 2059360.046630 s | 2059360.046676 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.003% skipped events (3 including 0 entry, 3 exit)
# perf kwork -k softirq rep -C 0,2
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
(s)SCHED:7 | 0000 | 25.318 ms | 232 | 1.490 ms | 2059361.310045 s | 2059361.311535 s |
(s)RCU:9 | 0000 | 3.102 ms | 66 | 1.568 ms | 2059360.853075 s | 2059360.854643 s |
(s)NET_RX:3 | 0002 | 1.065 ms | 6 | 0.903 ms | 2059359.985888 s | 2059359.986792 s |
(s)TIMER:1 | 0000 | 0.704 ms | 7 | 0.130 ms | 2059360.850686 s | 2059360.850816 s |
(s)TIMER:1 | 0002 | 0.688 ms | 7 | 0.131 ms | 2059368.237258 s | 2059368.237389 s |
(s)SCHED:7 | 0002 | 0.637 ms | 9 | 0.177 ms | 2059362.689653 s | 2059362.689830 s |
(s)RCU:9 | 0002 | 0.208 ms | 9 | 0.030 ms | 2059359.279854 s | 2059359.279884 s |
---------------------------------------------------------------------------------------------------------------------------
# perf kwork -k softirq rep -n RCU
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0001 | 169.534 ms | 3156 | 1.435 ms | 2059361.588639 s | 2059361.590074 s |
(s)RCU:9 | 0007 | 90.461 ms | 1578 | 0.978 ms | 2059362.073209 s | 2059362.074187 s |
(s)RCU:9 | 0003 | 41.725 ms | 1823 | 0.087 ms | 2059358.201654 s | 2059358.201742 s |
(s)RCU:9 | 0004 | 10.983 ms | 94 | 0.981 ms | 2059358.241061 s | 2059358.242042 s |
(s)RCU:9 | 0000 | 3.102 ms | 66 | 1.568 ms | 2059360.853075 s | 2059360.854643 s |
(s)RCU:9 | 0005 | 0.715 ms | 18 | 0.098 ms | 2059360.002711 s | 2059360.002810 s |
(s)RCU:9 | 0002 | 0.208 ms | 9 | 0.030 ms | 2059359.279854 s | 2059359.279884 s |
(s)RCU:9 | 0006 | 0.150 ms | 4 | 0.077 ms | 2059358.209321 s | 2059358.209398 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.001% skipped events (1 including 0 entry, 1 exit)
# perf kwork -k softirq rep -s max,freq
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0000 | 3.102 ms | 66 | 1.568 ms | 2059360.853075 s | 2059360.854643 s |
(s)SCHED:7 | 0000 | 25.318 ms | 232 | 1.490 ms | 2059361.310045 s | 2059361.311535 s |
(s)RCU:9 | 0001 | 169.534 ms | 3156 | 1.435 ms | 2059361.588639 s | 2059361.590074 s |
(s)SCHED:7 | 0007 | 81.408 ms | 1984 | 1.120 ms | 2059358.259073 s | 2059358.260193 s |
(s)RCU:9 | 0004 | 10.983 ms | 94 | 0.981 ms | 2059358.241061 s | 2059358.242042 s |
(s)RCU:9 | 0007 | 90.461 ms | 1578 | 0.978 ms | 2059362.073209 s | 2059362.074187 s |
(s)NET_RX:3 | 0002 | 1.065 ms | 6 | 0.903 ms | 2059359.985888 s | 2059359.986792 s |
(s)TIMER:1 | 0005 | 0.414 ms | 1 | 0.414 ms | 2059361.265364 s | 2059361.265778 s |
(s)TIMER:1 | 0004 | 0.199 ms | 1 | 0.199 ms | 2059362.605271 s | 2059362.605471 s |
(s)TIMER:1 | 0007 | 0.740 ms | 6 | 0.192 ms | 2059368.237655 s | 2059368.237847 s |
(s)SCHED:7 | 0002 | 0.637 ms | 9 | 0.177 ms | 2059362.689653 s | 2059362.689830 s |
(s)BLOCK:4 | 0007 | 0.586 ms | 4 | 0.174 ms | 2059362.620644 s | 2059362.620818 s |
(s)TIMER:1 | 0002 | 0.688 ms | 7 | 0.131 ms | 2059368.237258 s | 2059368.237389 s |
(s)TIMER:1 | 0000 | 0.704 ms | 7 | 0.130 ms | 2059360.850686 s | 2059360.850816 s |
(s)TIMER:1 | 0003 | 150.007 ms | 2472 | 0.125 ms | 2059359.989698 s | 2059359.989823 s |
(s)SCHED:7 | 0003 | 27.001 ms | 629 | 0.116 ms | 2059358.207263 s | 2059358.207379 s |
(s)TIMER:1 | 0001 | 2.207 ms | 27 | 0.108 ms | 2059363.117923 s | 2059363.118031 s |
(s)TIMER:1 | 0006 | 0.196 ms | 2 | 0.108 ms | 2059358.207823 s | 2059358.207931 s |
(s)RCU:9 | 0005 | 0.715 ms | 18 | 0.098 ms | 2059360.002711 s | 2059360.002810 s |
(s)SCHED:7 | 0001 | 49.071 ms | 1148 | 0.090 ms | 2059364.592682 s | 2059364.592772 s |
(s)RCU:9 | 0003 | 41.725 ms | 1823 | 0.087 ms | 2059358.201654 s | 2059358.201742 s |
(s)SCHED:7 | 0004 | 0.237 ms | 4 | 0.084 ms | 2059368.376924 s | 2059368.377008 s |
(s)SCHED:7 | 0005 | 0.406 ms | 7 | 0.078 ms | 2059361.265799 s | 2059361.265878 s |
(s)RCU:9 | 0006 | 0.150 ms | 4 | 0.077 ms | 2059358.209321 s | 2059358.209398 s |
(s)SCHED:7 | 0006 | 0.046 ms | 1 | 0.046 ms | 2059360.046630 s | 2059360.046676 s |
(s)RCU:9 | 0002 | 0.208 ms | 9 | 0.030 ms | 2059359.279854 s | 2059359.279884 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.003% skipped events (3 including 0 entry, 3 exit)
# perf kwork -k softirq rep --time 2059361,
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0001 | 148.655 ms | 2838 | 1.435 ms | 2059361.588639 s | 2059361.590074 s |
(s)TIMER:1 | 0003 | 109.877 ms | 1811 | 0.121 ms | 2059361.071163 s | 2059361.071284 s |
(s)SCHED:7 | 0001 | 48.681 ms | 1140 | 0.090 ms | 2059364.592682 s | 2059364.592772 s |
(s)SCHED:7 | 0007 | 32.373 ms | 796 | 0.808 ms | 2059361.088583 s | 2059361.089391 s |
(s)RCU:9 | 0003 | 30.198 ms | 1327 | 0.045 ms | 2059363.891611 s | 2059363.891655 s |
(s)RCU:9 | 0007 | 28.735 ms | 524 | 0.978 ms | 2059362.073209 s | 2059362.074187 s |
(s)SCHED:7 | 0003 | 19.399 ms | 457 | 0.055 ms | 2059367.528239 s | 2059367.528295 s |
(s)SCHED:7 | 0000 | 14.284 ms | 143 | 1.490 ms | 2059361.310045 s | 2059361.311535 s |
(s)TIMER:1 | 0001 | 1.716 ms | 21 | 0.108 ms | 2059363.117923 s | 2059363.118031 s |
(s)RCU:9 | 0004 | 1.061 ms | 10 | 0.766 ms | 2059368.385058 s | 2059368.385824 s |
(s)RCU:9 | 0000 | 1.001 ms | 43 | 0.043 ms | 2059364.147987 s | 2059364.148031 s |
(s)SCHED:7 | 0002 | 0.591 ms | 8 | 0.177 ms | 2059362.689653 s | 2059362.689830 s |
(s)BLOCK:4 | 0007 | 0.586 ms | 4 | 0.174 ms | 2059362.620644 s | 2059362.620818 s |
(s)TIMER:1 | 0002 | 0.578 ms | 6 | 0.131 ms | 2059368.237258 s | 2059368.237389 s |
(s)TIMER:1 | 0007 | 0.491 ms | 4 | 0.192 ms | 2059368.237655 s | 2059368.237847 s |
(s)TIMER:1 | 0000 | 0.485 ms | 5 | 0.122 ms | 2059366.586542 s | 2059366.586665 s |
(s)TIMER:1 | 0005 | 0.414 ms | 1 | 0.414 ms | 2059361.265364 s | 2059361.265778 s |
(s)SCHED:7 | 0004 | 0.199 ms | 3 | 0.084 ms | 2059368.376924 s | 2059368.377008 s |
(s)TIMER:1 | 0004 | 0.199 ms | 1 | 0.199 ms | 2059362.605271 s | 2059362.605471 s |
(s)SCHED:7 | 0005 | 0.185 ms | 3 | 0.078 ms | 2059361.265799 s | 2059361.265878 s |
(s)RCU:9 | 0002 | 0.132 ms | 6 | 0.023 ms | 2059367.469375 s | 2059367.469398 s |
(s)RCU:9 | 0005 | 0.128 ms | 4 | 0.036 ms | 2059361.267615 s | 2059361.267652 s |
(s)NET_RX:3 | 0002 | 0.125 ms | 4 | 0.035 ms | 2059365.423649 s | 2059365.423684 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.003% skipped events (3 including 0 entry, 3 exit)
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 97 +++++++++++++++++++++++++++++++++++++-
1 file changed, 95 insertions(+), 2 deletions(-)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index 5741a8ac3e41..1eb416faf8ef 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -708,16 +708,109 @@ static struct kwork_class kwork_irq = {
.cluster_name = irq_cluster_name,
};
+static struct kwork_class kwork_softirq;
+static int process_softirq_entry_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
+
+ if (kwork->tp_handler->entry_event)
+ return kwork->tp_handler->entry_event(kwork, &kwork_softirq,
+ evsel, sample, machine);
+
+ return 0;
+}
+
+static int process_softirq_exit_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
+
+ if (kwork->tp_handler->exit_event)
+ return kwork->tp_handler->exit_event(kwork, &kwork_softirq,
+ evsel, sample, machine);
+
+ return 0;
+}
+
const struct evsel_str_handler softirq_tp_handlers[] = {
{ "irq:softirq_raise", NULL, },
- { "irq:softirq_entry", NULL, },
- { "irq:softirq_exit", NULL, },
+ { "irq:softirq_entry", process_softirq_entry_event, },
+ { "irq:softirq_exit", process_softirq_exit_event, },
};
+static int softirq_class_init(struct kwork_class *class,
+ struct perf_session *session)
+{
+ if (perf_session__set_tracepoints_handlers(session,
+ softirq_tp_handlers)) {
+ pr_debug("Failed to set softirq tracepoints handlers\n");
+ return -1;
+ }
+
+ class->cluster_root = RB_ROOT_CACHED;
+ return 0;
+}
+
+static char *evsel__softirq_name(struct evsel *evsel, u64 num)
+{
+ char *name = NULL;
+ bool found = false;
+ struct tep_print_flag_sym *sym = NULL;
+ struct tep_print_arg *args = evsel->tp_format->print_fmt.args;
+
+ if ((args == NULL) || (args->next == NULL))
+ return NULL;
+
+ /* skip softirq field: "REC->vec" */
+ for (sym = args->next->symbol.symbols; sym != NULL; sym = sym->next) {
+ if ((eval_flag(sym->value) == (unsigned long long)num) &&
+ (strlen(sym->str) != 0)) {
+ found = true;
+ break;
+ }
+ }
+
+ if (!found)
+ return NULL;
+
+ name = strdup(sym->str);
+ if (name == NULL) {
+ pr_debug("Failed to copy symbol name\n");
+ return NULL;
+ }
+ return name;
+}
+
+static void softirq_cluster_init(struct kwork_class *class,
+ struct kwork_cluster *cluster,
+ struct evsel *evsel,
+ struct perf_sample *sample)
+{
+ u64 num = evsel__intval(evsel, sample, "vec");
+
+ cluster->id = num;
+ cluster->class = class;
+ cluster->cpu = sample->cpu;
+ cluster->name = evsel__softirq_name(evsel, num);
+}
+
+static void softirq_cluster_name(struct kwork_cluster *cluster, char *buf, int len)
+{
+ snprintf(buf, len, "(s)%s:%" PRIu64 "", cluster->name, cluster->id);
+}
+
static struct kwork_class kwork_softirq = {
.name = "softirq",
.nr_tracepoints = 3,
.tp_handlers = softirq_tp_handlers,
+ .class_init = softirq_class_init,
+ .cluster_init = softirq_cluster_init,
+ .cluster_name = softirq_cluster_name,
};
const struct evsel_str_handler workqueue_tp_handlers[] = {
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 09/13] perf kwork: Add workqueue report support
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (7 preceding siblings ...)
2022-06-13 9:46 ` [RFC 08/13] perf kwork: Add softirq " Yang Jihong
@ 2022-06-13 9:46 ` Yang Jihong
2022-06-14 21:54 ` Namhyung Kim
2022-06-13 9:46 ` [RFC 10/13] perf kwork: Implement perf kwork latency Yang Jihong
` (4 subsequent siblings)
13 siblings, 1 reply; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:46 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Implements workqueue report function.
test case:
# perf kwork -k workqueue rep
Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
---------------------------------------------------------------------------------------------------------------------------
(w)0xffffffff83e09fa0 | 0001 | 2152.678 ms | 194 | 12.376 ms | 2059361.546621 s | 2059361.558997 s |
(w)0xffff888332fea180 | 0000 | 17.125 ms | 301 | 1.018 ms | 2059358.441070 s | 2059358.442089 s |
(w)0xffff8881035a83d8 | 0007 | 7.556 ms | 3 | 3.212 ms | 2059362.614643 s | 2059362.617855 s |
(w)0xffff888102fc14a0 | 0002 | 7.080 ms | 5 | 1.962 ms | 2059365.421753 s | 2059365.423714 s |
(w)0xffffffff82f7da00 | 0000 | 4.277 ms | 7 | 3.778 ms | 2059360.851063 s | 2059360.854841 s |
(w)0xffffffff8305d680 | 0006 | 1.796 ms | 1 | 1.796 ms | 2059360.046818 s | 2059360.048613 s |
(w)0xffff8883339e9040 | 0005 | 1.659 ms | 2 | 1.619 ms | 2059361.266051 s | 2059361.267670 s |
(w)0xffff888333de9040 | 0007 | 1.121 ms | 5 | 0.783 ms | 2059368.238059 s | 2059368.238842 s |
(w)0xffff888332fe9040 | 0000 | 0.990 ms | 4 | 0.911 ms | 2059359.604075 s | 2059359.604986 s |
(w)0xffff8883331e9040 | 0001 | 0.244 ms | 6 | 0.046 ms | 2059362.689277 s | 2059362.689323 s |
(w)0xffff888102e44400 | 0007 | 0.239 ms | 2 | 0.137 ms | 2059363.117537 s | 2059363.117674 s |
(w)0xffff8883333ea180 | 0002 | 0.141 ms | 5 | 0.049 ms | 2059365.423784 s | 2059365.423833 s |
(w)0xffffffff83062f28 | 0006 | 0.084 ms | 2 | 0.047 ms | 2059358.208033 s | 2059358.208080 s |
(w)0xffffffff8305ca48 | 0003 | 0.078 ms | 2 | 0.041 ms | 2059361.071371 s | 2059361.071412 s |
(w)0xffff8883337e9040 | 0004 | 0.062 ms | 1 | 0.062 ms | 2059362.605723 s | 2059362.605785 s |
(w)0xffff8881035a81e8 | 0001 | 0.056 ms | 1 | 0.056 ms | 2059363.118231 s | 2059363.118287 s |
(w)0xffff8883335e9040 | 0003 | 0.026 ms | 1 | 0.026 ms | 2059358.573397 s | 2059358.573423 s |
(w)0xffffffff83062e70 | 0006 | 0.023 ms | 1 | 0.023 ms | 2059368.398864 s | 2059368.398888 s |
(w)0xffffffff83e06480 | 0002 | 0.000 ms | 1 | 0.000 ms | 2059359.986792 s | 2059359.986792 s |
---------------------------------------------------------------------------------------------------------------------------
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 65 ++++++++++++++++++++++++++++++++++++--
1 file changed, 63 insertions(+), 2 deletions(-)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index 1eb416faf8ef..f27ffad223a3 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -813,16 +813,77 @@ static struct kwork_class kwork_softirq = {
.cluster_name = softirq_cluster_name,
};
+static struct kwork_class kwork_workqueue;
+static int process_workqueue_execute_start_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
+
+ if (kwork->tp_handler->entry_event)
+ return kwork->tp_handler->entry_event(kwork, &kwork_workqueue,
+ evsel, sample, machine);
+
+ return 0;
+}
+
+static int process_workqueue_execute_end_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
+
+ if (kwork->tp_handler->exit_event)
+ return kwork->tp_handler->exit_event(kwork, &kwork_workqueue,
+ evsel, sample, machine);
+
+ return 0;
+}
+
const struct evsel_str_handler workqueue_tp_handlers[] = {
{ "workqueue:workqueue_activate_work", NULL, },
- { "workqueue:workqueue_execute_start", NULL, },
- { "workqueue:workqueue_execute_end", NULL, },
+ { "workqueue:workqueue_execute_start", process_workqueue_execute_start_event, },
+ { "workqueue:workqueue_execute_end", process_workqueue_execute_end_event, },
};
+static int workqueue_class_init(struct kwork_class *class,
+ struct perf_session *session)
+{
+ if (perf_session__set_tracepoints_handlers(session,
+ workqueue_tp_handlers)) {
+ pr_debug("Failed to set workqueue tracepoints handlers\n");
+ return -1;
+ }
+
+ class->cluster_root = RB_ROOT_CACHED;
+ return 0;
+}
+
+static void workqueue_cluster_init(struct kwork_class *class,
+ struct kwork_cluster *cluster,
+ struct evsel *evsel,
+ struct perf_sample *sample)
+{
+ cluster->name = NULL;
+ cluster->class = class;
+ cluster->cpu = sample->cpu;
+ cluster->id = evsel__intval(evsel, sample, "work");
+}
+
+static void workqueue_cluster_name(struct kwork_cluster *cluster, char *buf, int len)
+{
+ snprintf(buf, len, "(w)0x%" PRIx64, cluster->id);
+}
+
static struct kwork_class kwork_workqueue = {
.name = "workqueue",
.nr_tracepoints = 3,
.tp_handlers = workqueue_tp_handlers,
+ .class_init = workqueue_class_init,
+ .cluster_init = workqueue_cluster_init,
+ .cluster_name = workqueue_cluster_name,
};
static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] = {
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 10/13] perf kwork: Implement perf kwork latency
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (8 preceding siblings ...)
2022-06-13 9:46 ` [RFC 09/13] perf kwork: Add workqueue " Yang Jihong
@ 2022-06-13 9:46 ` Yang Jihong
2022-06-13 9:46 ` [RFC 11/13] perf kwork: Add softirq latency support Yang Jihong
` (3 subsequent siblings)
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:46 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Implements framework of perf kwork latency, which is used to report time
properties such as delay time and frequency.
test case:
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------------------------------------------------------
INFO: 37.324% skipped events (33174 including 0 raise, 33174 entry, 0 exit)
Since there are no latency-enabled events, the output is empty.
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 153 +++++++++++++++++++++++++++++++++++++
1 file changed, 153 insertions(+)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index f27ffad223a3..84e318eea832 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -32,6 +32,7 @@ enum kwork_class_type {
};
enum kwork_trace_type {
+ KWORK_TRACE_RAISE,
KWORK_TRACE_ENTRY,
KWORK_TRACE_EXIT,
KWORK_TRACE_MAX,
@@ -39,6 +40,7 @@ enum kwork_trace_type {
enum kwork_report_type {
KWORK_REPORT_RUNTIME,
+ KWORK_REPORT_LATENCY,
};
/*
@@ -104,6 +106,14 @@ struct kwork_cluster {
u64 max_runtime_start;
u64 max_runtime_end;
u64 total_runtime;
+
+ /*
+ * latency report
+ */
+ u64 max_latency;
+ u64 max_latency_start;
+ u64 max_latency_end;
+ u64 total_latency;
};
struct kwork_class {
@@ -128,6 +138,10 @@ struct kwork_class {
struct perf_kwork;
struct trace_kwork_handler {
+ int (*raise_event)(struct perf_kwork *kwork,
+ struct kwork_class *class, struct evsel *evsel,
+ struct perf_sample *sample, struct machine *machine);
+
int (*entry_event)(struct perf_kwork *kwork,
struct kwork_class *class, struct evsel *evsel,
struct perf_sample *sample, struct machine *machine);
@@ -195,12 +209,14 @@ struct perf_kwork {
#define PRINT_CPU_WIDTH 4
#define PRINT_FREQ_WIDTH 9
#define PRINT_RUNTIME_WIDTH 10
+#define PRINT_LATENCY_WIDTH 10
#define PRINT_TIMESTAMP_WIDTH 17
#define PRINT_KWORK_NAME_WIDTH 25
#define RPINT_DECIMAL_WIDTH 3
#define PRINT_TIME_UNIT_SEC_WIDTH 2
#define PRINT_TIME_UNIT_MESC_WIDTH 3
#define PRINT_RUNTIME_HEADER_WIDTH (PRINT_RUNTIME_WIDTH + PRINT_TIME_UNIT_MESC_WIDTH)
+#define PRINT_LATENCY_HEADER_WIDTH (PRINT_LATENCY_WIDTH + PRINT_TIME_UNIT_MESC_WIDTH)
#define PRINT_TIMESTAMP_HEADER_WIDTH (PRINT_TIMESTAMP_WIDTH + PRINT_TIME_UNIT_SEC_WIDTH)
struct sort_dimension {
@@ -254,6 +270,36 @@ static int max_runtime_cmp(struct kwork_cluster *l, struct kwork_cluster *r)
return 0;
}
+static int avg_latency_cmp(struct kwork_cluster *l, struct kwork_cluster *r)
+{
+ u64 avgl, avgr;
+
+ if (!r->nr_atoms)
+ return 1;
+ if (!l->nr_atoms)
+ return -1;
+
+ avgl = l->total_latency / l->nr_atoms;
+ avgr = r->total_latency / r->nr_atoms;
+
+ if (avgl > avgr)
+ return 1;
+ if (avgl < avgr)
+ return -1;
+
+ return 0;
+}
+
+static int max_latency_cmp(struct kwork_cluster *l, struct kwork_cluster *r)
+{
+ if (l->max_latency > r->max_latency)
+ return 1;
+ if (l->max_latency < r->max_latency)
+ return -1;
+
+ return 0;
+}
+
static int sort_dimension__add(struct perf_kwork *kwork __maybe_unused,
const char *tok, struct list_head *list)
{
@@ -274,13 +320,21 @@ static int sort_dimension__add(struct perf_kwork *kwork __maybe_unused,
.name = "freq",
.cmp = freq_cmp,
};
+ static struct sort_dimension avg_sort_dimension = {
+ .name = "avg",
+ .cmp = avg_latency_cmp,
+ };
struct sort_dimension *available_sorts[] = {
&id_sort_dimension,
&max_sort_dimension,
&freq_sort_dimension,
&runtime_sort_dimension,
+ &avg_sort_dimension,
};
+ if (kwork->report == KWORK_REPORT_LATENCY)
+ max_sort_dimension.cmp = max_latency_cmp;
+
for (i = 0; i < ARRAY_SIZE(available_sorts); i++) {
if (!strcmp(available_sorts[i]->name, tok)) {
list_add_tail(&available_sorts[i]->list, list);
@@ -639,6 +693,59 @@ static int report_exit_event(struct perf_kwork *kwork,
return 0;
}
+static void latency_update_entry_event(struct kwork_cluster *cluster,
+ struct kwork_atom *atom,
+ struct perf_sample *sample)
+{
+ u64 delta;
+ u64 entry_time = sample->time;
+ u64 raise_time = atom->time;
+
+ if ((raise_time != 0) && (entry_time >= raise_time)) {
+ delta = entry_time - raise_time;
+ if ((delta > cluster->max_latency) ||
+ (cluster->max_latency == 0)) {
+ cluster->max_latency = delta;
+ cluster->max_latency_start = raise_time;
+ cluster->max_latency_end = entry_time;
+ }
+ cluster->total_latency += delta;
+ cluster->nr_atoms++;
+ }
+}
+
+static int latency_raise_event(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ return cluster_push_atom(kwork, class, KWORK_TRACE_RAISE,
+ KWORK_TRACE_MAX, evsel, sample, NULL);
+}
+
+static int latency_entry_event(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ struct kwork_atom *atom = NULL;
+ struct kwork_cluster *cluster = NULL;
+
+ atom = cluster_pop_atom(kwork, class, KWORK_TRACE_ENTRY,
+ KWORK_TRACE_RAISE, evsel, sample, &cluster);
+ if (cluster == NULL)
+ return -1;
+
+ if (atom != NULL) {
+ latency_update_entry_event(cluster, atom, sample);
+ atom_del(atom);
+ }
+
+ return 0;
+}
+
static struct kwork_class kwork_irq;
static int process_irq_handler_entry_event(struct perf_tool *tool,
struct evsel *evsel,
@@ -903,6 +1010,7 @@ static void report_print_cluster(struct perf_kwork *kwork,
int ret = 0;
char kwork_name[PRINT_KWORK_NAME_WIDTH];
char max_runtime_start[32], max_runtime_end[32];
+ char max_latency_start[32], max_latency_end[32];
printf(" ");
@@ -928,6 +1036,14 @@ static void report_print_cluster(struct perf_kwork *kwork,
ret += printf(" %*.*f ms |",
PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH,
(double)cluster->total_runtime / NSEC_PER_MSEC);
+ /*
+ * avg delay
+ */
+ else if (kwork->report == KWORK_REPORT_LATENCY)
+ ret += printf(" %*.*f ms |",
+ PRINT_LATENCY_WIDTH, RPINT_DECIMAL_WIDTH,
+ (double)cluster->total_latency /
+ cluster->nr_atoms / NSEC_PER_MSEC);
/*
* frequency
@@ -951,6 +1067,22 @@ static void report_print_cluster(struct perf_kwork *kwork,
PRINT_TIMESTAMP_WIDTH, max_runtime_start,
PRINT_TIMESTAMP_WIDTH, max_runtime_end);
}
+ /*
+ * max delay, max delay start, max delay end
+ */
+ else if (kwork->report == KWORK_REPORT_LATENCY) {
+ timestamp__scnprintf_usec(cluster->max_latency_start,
+ max_latency_start,
+ sizeof(max_latency_start));
+ timestamp__scnprintf_usec(cluster->max_latency_end,
+ max_latency_end,
+ sizeof(max_latency_end));
+ ret += printf(" %*.*f ms | %*s s | %*s s |",
+ PRINT_LATENCY_WIDTH, RPINT_DECIMAL_WIDTH,
+ (double)cluster->max_latency / NSEC_PER_MSEC,
+ PRINT_TIMESTAMP_WIDTH, max_latency_start,
+ PRINT_TIMESTAMP_WIDTH, max_latency_end);
+ }
printf("\n");
}
@@ -967,6 +1099,9 @@ static int report_print_header(struct perf_kwork *kwork)
if (kwork->report == KWORK_REPORT_RUNTIME)
ret += printf(" %-*s |",
PRINT_RUNTIME_HEADER_WIDTH, "Total Runtime");
+ else if (kwork->report == KWORK_REPORT_LATENCY)
+ ret += printf(" %-*s |",
+ PRINT_LATENCY_HEADER_WIDTH, "Avg delay");
ret += printf(" %-*s |", PRINT_FREQ_WIDTH, "Frequency");
@@ -975,6 +1110,11 @@ static int report_print_header(struct perf_kwork *kwork)
PRINT_RUNTIME_HEADER_WIDTH, "Max runtime",
PRINT_TIMESTAMP_HEADER_WIDTH, "Max runtime start",
PRINT_TIMESTAMP_HEADER_WIDTH, "Max runtime end");
+ else if (kwork->report == KWORK_REPORT_LATENCY)
+ ret += printf(" %-*s | %-*s | %-*s |",
+ PRINT_LATENCY_HEADER_WIDTH, "Max delay",
+ PRINT_TIMESTAMP_HEADER_WIDTH, "Max delay start",
+ PRINT_TIMESTAMP_HEADER_WIDTH, "Max delay end");
printf("\n");
print_separator(ret);
@@ -1008,6 +1148,7 @@ static void print_skipped_events(struct perf_kwork *kwork)
{
int i;
const char *const kwork_event_str[] = {
+ [KWORK_TRACE_RAISE] = "raise",
[KWORK_TRACE_ENTRY] = "entry",
[KWORK_TRACE_EXIT] = "exit",
};
@@ -1121,11 +1262,18 @@ static int perf_kwork__check_config(struct perf_kwork *kwork,
.entry_event = report_entry_event,
.exit_event = report_exit_event,
};
+ static struct trace_kwork_handler latency_ops = {
+ .raise_event = latency_raise_event,
+ .entry_event = latency_entry_event,
+ };
switch (kwork->report) {
case KWORK_REPORT_RUNTIME:
kwork->tp_handler = &report_ops;
break;
+ case KWORK_REPORT_LATENCY:
+ kwork->tp_handler = &latency_ops;
+ break;
default:
pr_debug("Invalid report type %d\n", kwork->report);
break;
@@ -1330,6 +1478,7 @@ static int perf_kwork__record(struct perf_kwork *kwork,
int cmd_kwork(int argc, const char **argv)
{
static const char default_report_sort_order[] = "runtime, max, freq";
+ static const char default_latency_sort_order[] = "avg, max, freq";
static struct perf_kwork kwork = {
.tool = {
.sample = perf_kwork__process_tracepoint_sample,
@@ -1463,11 +1612,15 @@ int cmd_kwork(int argc, const char **argv)
setup_sorting(&kwork, report_options, report_usage);
return perf_kwork__report(&kwork);
} else if (strlen(argv[0]) > 2 && strstarts("latency", argv[0])) {
+ kwork.sort_order = default_latency_sort_order;
if (argc > 1) {
argc = parse_options(argc, argv, latency_options, latency_usage, 0);
if (argc)
usage_with_options(latency_usage, latency_options);
}
+ kwork.report = KWORK_REPORT_LATENCY;
+ setup_sorting(&kwork, latency_options, latency_usage);
+ return perf_kwork__report(&kwork);
} else if (strlen(argv[0]) > 2 && strstarts("timehist", argv[0])) {
if (argc > 1) {
argc = parse_options(argc, argv, timehist_options, timehist_usage, 0);
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 11/13] perf kwork: Add softirq latency support
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (9 preceding siblings ...)
2022-06-13 9:46 ` [RFC 10/13] perf kwork: Implement perf kwork latency Yang Jihong
@ 2022-06-13 9:46 ` Yang Jihong
2022-06-13 9:46 ` [RFC 12/13] perf kwork: Add workqueue " Yang Jihong
` (2 subsequent siblings)
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:46 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Implements softirq latency function.
test case:
# perf kwork lat
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0006 | 1.338 ms | 1 | 1.338 ms | 2072616.369122 s | 2072616.370461 s |
(s)RCU:9 | 0005 | 0.945 ms | 2 | 1.757 ms | 2072616.368262 s | 2072616.370020 s |
(s)RCU:9 | 0002 | 0.575 ms | 73 | 1.884 ms | 2072616.423139 s | 2072616.425023 s |
(s)RCU:9 | 0000 | 0.327 ms | 105 | 1.365 ms | 2072620.344392 s | 2072620.345757 s |
(s)RCU:9 | 0001 | 0.233 ms | 711 | 2.862 ms | 2072620.639022 s | 2072620.641885 s |
(s)NET_RX:3 | 0002 | 0.219 ms | 5 | 0.762 ms | 2072624.174209 s | 2072624.174971 s |
(s)RCU:9 | 0004 | 0.176 ms | 4 | 0.265 ms | 2072620.333206 s | 2072620.333472 s |
(s)RCU:9 | 0007 | 0.172 ms | 3165 | 2.890 ms | 2072616.385706 s | 2072616.388595 s |
(s)TIMER:1 | 0000 | 0.168 ms | 11 | 0.307 ms | 2072620.638399 s | 2072620.638706 s |
(s)RCU:9 | 0003 | 0.149 ms | 194 | 1.127 ms | 2072620.617286 s | 2072620.618413 s |
(s)SCHED:7 | 0002 | 0.136 ms | 12 | 0.384 ms | 2072617.261300 s | 2072617.261684 s |
(s)BLOCK:4 | 0001 | 0.131 ms | 79 | 2.734 ms | 2072620.639022 s | 2072620.641756 s |
(s)SCHED:7 | 0000 | 0.127 ms | 360 | 0.989 ms | 2072616.386068 s | 2072616.387057 s |
(s)BLOCK:4 | 0000 | 0.125 ms | 13 | 0.209 ms | 2072620.354356 s | 2072620.354564 s |
(s)SCHED:7 | 0004 | 0.121 ms | 3 | 0.172 ms | 2072620.333236 s | 2072620.333408 s |
(s)SCHED:7 | 0003 | 0.113 ms | 82 | 0.226 ms | 2072618.917223 s | 2072618.917449 s |
(s)SCHED:7 | 0001 | 0.098 ms | 209 | 0.986 ms | 2072620.392020 s | 2072620.393007 s |
(s)TIMER:1 | 0007 | 0.095 ms | 1550 | 1.274 ms | 2072625.965379 s | 2072625.966653 s |
(s)TIMER:1 | 0004 | 0.081 ms | 2 | 0.082 ms | 2072620.333187 s | 2072620.333269 s |
(s)TIMER:1 | 0002 | 0.076 ms | 10 | 0.104 ms | 2072617.261239 s | 2072617.261344 s |
(s)TIMER:1 | 0003 | 0.065 ms | 245 | 1.023 ms | 2072620.617286 s | 2072620.618309 s |
(s)SCHED:7 | 0006 | 0.064 ms | 2 | 0.081 ms | 2072616.370310 s | 2072616.370391 s |
(s)SCHED:7 | 0007 | 0.062 ms | 2753 | 0.473 ms | 2072621.357987 s | 2072621.358460 s |
(s)TIMER:1 | 0001 | 0.055 ms | 774 | 0.396 ms | 2072617.523145 s | 2072617.523540 s |
(s)SCHED:7 | 0005 | 0.040 ms | 2 | 0.042 ms | 2072616.369895 s | 2072616.369937 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 28.605% skipped events (25424 including 2617 raise, 22807 entry, 0 exit)
# perf kwork lat -C 0,1
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0000 | 0.327 ms | 105 | 1.365 ms | 2072620.344392 s | 2072620.345757 s |
(s)RCU:9 | 0001 | 0.233 ms | 711 | 2.862 ms | 2072620.639022 s | 2072620.641885 s |
(s)TIMER:1 | 0000 | 0.168 ms | 11 | 0.307 ms | 2072620.638399 s | 2072620.638706 s |
(s)BLOCK:4 | 0001 | 0.131 ms | 79 | 2.734 ms | 2072620.639022 s | 2072620.641756 s |
(s)SCHED:7 | 0000 | 0.127 ms | 360 | 0.989 ms | 2072616.386068 s | 2072616.387057 s |
(s)BLOCK:4 | 0000 | 0.125 ms | 13 | 0.209 ms | 2072620.354356 s | 2072620.354564 s |
(s)SCHED:7 | 0001 | 0.098 ms | 209 | 0.986 ms | 2072620.392020 s | 2072620.393007 s |
(s)TIMER:1 | 0001 | 0.055 ms | 774 | 0.396 ms | 2072617.523145 s | 2072617.523540 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 26.410% skipped events (23473 including 795 raise, 22678 entry, 0 exit)
# perf kwork lat -n SCHED
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(s)SCHED:7 | 0002 | 0.136 ms | 12 | 0.384 ms | 2072617.261300 s | 2072617.261684 s |
(s)SCHED:7 | 0000 | 0.127 ms | 360 | 0.989 ms | 2072616.386068 s | 2072616.387057 s |
(s)SCHED:7 | 0004 | 0.121 ms | 3 | 0.172 ms | 2072620.333236 s | 2072620.333408 s |
(s)SCHED:7 | 0003 | 0.113 ms | 82 | 0.226 ms | 2072618.917223 s | 2072618.917449 s |
(s)SCHED:7 | 0001 | 0.098 ms | 209 | 0.986 ms | 2072620.392020 s | 2072620.393007 s |
(s)SCHED:7 | 0006 | 0.064 ms | 2 | 0.081 ms | 2072616.370310 s | 2072616.370391 s |
(s)SCHED:7 | 0007 | 0.062 ms | 2753 | 0.473 ms | 2072621.357987 s | 2072621.358460 s |
(s)SCHED:7 | 0005 | 0.040 ms | 2 | 0.042 ms | 2072616.369895 s | 2072616.369937 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.006% skipped events (5 including 5 raise, 0 entry, 0 exit)
# perf kwork lat -s freq,max
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0007 | 0.172 ms | 3165 | 2.890 ms | 2072616.385706 s | 2072616.388595 s |
(s)SCHED:7 | 0007 | 0.062 ms | 2753 | 0.473 ms | 2072621.357987 s | 2072621.358460 s |
(s)TIMER:1 | 0007 | 0.095 ms | 1550 | 1.274 ms | 2072625.965379 s | 2072625.966653 s |
(s)TIMER:1 | 0001 | 0.055 ms | 774 | 0.396 ms | 2072617.523145 s | 2072617.523540 s |
(s)RCU:9 | 0001 | 0.233 ms | 711 | 2.862 ms | 2072620.639022 s | 2072620.641885 s |
(s)SCHED:7 | 0000 | 0.127 ms | 360 | 0.989 ms | 2072616.386068 s | 2072616.387057 s |
(s)TIMER:1 | 0003 | 0.065 ms | 245 | 1.023 ms | 2072620.617286 s | 2072620.618309 s |
(s)SCHED:7 | 0001 | 0.098 ms | 209 | 0.986 ms | 2072620.392020 s | 2072620.393007 s |
(s)RCU:9 | 0003 | 0.149 ms | 194 | 1.127 ms | 2072620.617286 s | 2072620.618413 s |
(s)RCU:9 | 0000 | 0.327 ms | 105 | 1.365 ms | 2072620.344392 s | 2072620.345757 s |
(s)SCHED:7 | 0003 | 0.113 ms | 82 | 0.226 ms | 2072618.917223 s | 2072618.917449 s |
(s)BLOCK:4 | 0001 | 0.131 ms | 79 | 2.734 ms | 2072620.639022 s | 2072620.641756 s |
(s)RCU:9 | 0002 | 0.575 ms | 73 | 1.884 ms | 2072616.423139 s | 2072616.425023 s |
(s)BLOCK:4 | 0000 | 0.125 ms | 13 | 0.209 ms | 2072620.354356 s | 2072620.354564 s |
(s)SCHED:7 | 0002 | 0.136 ms | 12 | 0.384 ms | 2072617.261300 s | 2072617.261684 s |
(s)TIMER:1 | 0000 | 0.168 ms | 11 | 0.307 ms | 2072620.638399 s | 2072620.638706 s |
(s)TIMER:1 | 0002 | 0.076 ms | 10 | 0.104 ms | 2072617.261239 s | 2072617.261344 s |
(s)NET_RX:3 | 0002 | 0.219 ms | 5 | 0.762 ms | 2072624.174209 s | 2072624.174971 s |
(s)RCU:9 | 0004 | 0.176 ms | 4 | 0.265 ms | 2072620.333206 s | 2072620.333472 s |
(s)SCHED:7 | 0004 | 0.121 ms | 3 | 0.172 ms | 2072620.333236 s | 2072620.333408 s |
(s)RCU:9 | 0005 | 0.945 ms | 2 | 1.757 ms | 2072616.368262 s | 2072616.370020 s |
(s)TIMER:1 | 0004 | 0.081 ms | 2 | 0.082 ms | 2072620.333187 s | 2072620.333269 s |
(s)SCHED:7 | 0006 | 0.064 ms | 2 | 0.081 ms | 2072616.370310 s | 2072616.370391 s |
(s)SCHED:7 | 0005 | 0.040 ms | 2 | 0.042 ms | 2072616.369895 s | 2072616.369937 s |
(s)RCU:9 | 0006 | 1.338 ms | 1 | 1.338 ms | 2072616.369122 s | 2072616.370461 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 28.605% skipped events (25424 including 2617 raise, 22807 entry, 0 exit)
# perf kwork lat --time 2072620.333236,
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(s)RCU:9 | 0001 | 0.699 ms | 130 | 2.862 ms | 2072620.639022 s | 2072620.641885 s |
(s)RCU:9 | 0000 | 0.320 ms | 70 | 1.365 ms | 2072620.344392 s | 2072620.345757 s |
(s)NET_RX:3 | 0002 | 0.298 ms | 3 | 0.762 ms | 2072624.174209 s | 2072624.174971 s |
(s)RCU:9 | 0002 | 0.297 ms | 13 | 0.687 ms | 2072622.126201 s | 2072622.126888 s |
(s)RCU:9 | 0003 | 0.271 ms | 17 | 1.127 ms | 2072620.617286 s | 2072620.618413 s |
(s)TIMER:1 | 0000 | 0.166 ms | 8 | 0.307 ms | 2072620.638399 s | 2072620.638706 s |
(s)RCU:9 | 0004 | 0.146 ms | 3 | 0.253 ms | 2072621.357331 s | 2072621.357584 s |
(s)SCHED:7 | 0003 | 0.143 ms | 15 | 0.197 ms | 2072625.973321 s | 2072625.973519 s |
(s)TIMER:1 | 0003 | 0.137 ms | 16 | 1.023 ms | 2072620.617286 s | 2072620.618309 s |
(s)RCU:9 | 0005 | 0.133 ms | 1 | 0.133 ms | 2072626.530482 s | 2072626.530615 s |
(s)BLOCK:4 | 0001 | 0.131 ms | 79 | 2.734 ms | 2072620.639022 s | 2072620.641756 s |
(s)BLOCK:4 | 0000 | 0.125 ms | 13 | 0.209 ms | 2072620.354356 s | 2072620.354564 s |
(s)SCHED:7 | 0001 | 0.121 ms | 15 | 0.986 ms | 2072620.392020 s | 2072620.393007 s |
(s)SCHED:7 | 0004 | 0.121 ms | 3 | 0.172 ms | 2072620.333236 s | 2072620.333408 s |
(s)SCHED:7 | 0000 | 0.115 ms | 269 | 0.987 ms | 2072624.176905 s | 2072624.177892 s |
(s)SCHED:7 | 0002 | 0.109 ms | 7 | 0.140 ms | 2072625.966227 s | 2072625.966368 s |
(s)RCU:9 | 0007 | 0.095 ms | 1526 | 1.333 ms | 2072620.616224 s | 2072620.617557 s |
(s)TIMER:1 | 0007 | 0.094 ms | 1546 | 1.274 ms | 2072625.965379 s | 2072625.966653 s |
(s)TIMER:1 | 0004 | 0.079 ms | 1 | 0.079 ms | 2072621.357313 s | 2072621.357393 s |
(s)TIMER:1 | 0002 | 0.072 ms | 7 | 0.082 ms | 2072620.845190 s | 2072620.845272 s |
(s)TIMER:1 | 0001 | 0.070 ms | 9 | 0.149 ms | 2072620.360584 s | 2072620.360734 s |
(s)SCHED:7 | 0007 | 0.068 ms | 1959 | 0.473 ms | 2072621.357987 s | 2072621.358460 s |
(s)SCHED:7 | 0005 | 0.038 ms | 1 | 0.038 ms | 2072626.530536 s | 2072626.530573 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 17.800% skipped events (15821 including 1602 raise, 14219 entry, 0 exit)
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 16 +++++++++++++++-
1 file changed, 15 insertions(+), 1 deletion(-)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index 84e318eea832..e0ffd3291b3a 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -816,6 +816,20 @@ static struct kwork_class kwork_irq = {
};
static struct kwork_class kwork_softirq;
+static int process_softirq_raise_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
+
+ if (kwork->tp_handler->raise_event)
+ return kwork->tp_handler->raise_event(kwork, &kwork_softirq,
+ evsel, sample, machine);
+
+ return 0;
+}
+
static int process_softirq_entry_event(struct perf_tool *tool,
struct evsel *evsel,
struct perf_sample *sample,
@@ -845,7 +859,7 @@ static int process_softirq_exit_event(struct perf_tool *tool,
}
const struct evsel_str_handler softirq_tp_handlers[] = {
- { "irq:softirq_raise", NULL, },
+ { "irq:softirq_raise", process_softirq_raise_event, },
{ "irq:softirq_entry", process_softirq_entry_event, },
{ "irq:softirq_exit", process_softirq_exit_event, },
};
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 12/13] perf kwork: Add workqueue latency support
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (10 preceding siblings ...)
2022-06-13 9:46 ` [RFC 11/13] perf kwork: Add softirq latency support Yang Jihong
@ 2022-06-13 9:46 ` Yang Jihong
2022-06-13 9:46 ` [RFC 13/13] perf kwork: Implement perf kwork timehist Yang Jihong
2022-06-22 14:59 ` [RFC 00/13] perf: Add perf kwork Paul A. Clarke
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:46 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Implements workqueue latency function.
test case:
# perf kwork -k workqueue lat
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(w)0xffff888101c5cc00 | 0001 | 5120.387 ms | 1 | 5120.387 ms | 2072619.309237 s | 2072624.429624 s |
(w)0xffff8883333e9040 | 0002 | 2.331 ms | 1 | 2.331 ms | 2072618.029512 s | 2072618.031844 s |
(w)0xffff888332fe9040 | 0000 | 0.724 ms | 5 | 1.628 ms | 2072620.638985 s | 2072620.640613 s |
(w)0xffff8883333ea180 | 0002 | 0.675 ms | 6 | 2.007 ms | 2072624.174209 s | 2072624.176216 s |
(w)0xffff888102e44400 | 0001 | 0.400 ms | 1 | 0.400 ms | 2072625.965284 s | 2072625.965684 s |
(w)0xffffffff82f7da00 | 0000 | 0.392 ms | 7 | 0.822 ms | 2072621.627843 s | 2072621.628665 s |
(w)0xffff8881035a83d8 | 0000 | 0.352 ms | 3 | 0.827 ms | 2072620.650451 s | 2072620.651278 s |
(w)0xffff888100e65c80 | 0001 | 0.318 ms | 78 | 1.228 ms | 2072620.504051 s | 2072620.505279 s |
(w)0xffff8881035a81e8 | 0004 | 0.285 ms | 1 | 0.285 ms | 2072621.357437 s | 2072621.357722 s |
(w)0xffff888102fc14a0 | 0002 | 0.279 ms | 5 | 0.319 ms | 2072618.029425 s | 2072618.029744 s |
(w)0xffff8883335e9040 | 0003 | 0.271 ms | 2 | 0.293 ms | 2072618.917354 s | 2072618.917647 s |
(w)0xffffffff8305ca48 | 0003 | 0.268 ms | 2 | 0.292 ms | 2072618.917407 s | 2072618.917699 s |
(w)0xffffffff8305c990 | 0003 | 0.256 ms | 1 | 0.256 ms | 2072625.973445 s | 2072625.973701 s |
(w)0xffff888102e444b8 | 0001 | 0.254 ms | 1 | 0.254 ms | 2072626.173289 s | 2072626.173542 s |
(w)0xffff888332fea180 | 0000 | 0.252 ms | 346 | 2.237 ms | 2072620.339623 s | 2072620.341860 s |
(w)0xffff8883331e9040 | 0001 | 0.226 ms | 2 | 0.234 ms | 2072625.965354 s | 2072625.965588 s |
(w)0xffff888100e65c80 | 0000 | 0.217 ms | 10 | 0.705 ms | 2072620.339040 s | 2072620.339745 s |
(w)0xffff888333de9040 | 0007 | 0.179 ms | 8 | 0.374 ms | 2072619.565271 s | 2072619.565645 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.024% skipped events (21 including 11 raise, 10 entry, 0 exit)
# perf kwork -k workqueue lat -s freq,avg
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(w)0xffff888332fea180 | 0000 | 0.252 ms | 346 | 2.237 ms | 2072620.339623 s | 2072620.341860 s |
(w)0xffff888100e65c80 | 0001 | 0.318 ms | 78 | 1.228 ms | 2072620.504051 s | 2072620.505279 s |
(w)0xffff888100e65c80 | 0000 | 0.217 ms | 10 | 0.705 ms | 2072620.339040 s | 2072620.339745 s |
(w)0xffff888333de9040 | 0007 | 0.179 ms | 8 | 0.374 ms | 2072619.565271 s | 2072619.565645 s |
(w)0xffffffff82f7da00 | 0000 | 0.392 ms | 7 | 0.822 ms | 2072621.627843 s | 2072621.628665 s |
(w)0xffff8883333ea180 | 0002 | 0.675 ms | 6 | 2.007 ms | 2072624.174209 s | 2072624.176216 s |
(w)0xffff888332fe9040 | 0000 | 0.724 ms | 5 | 1.628 ms | 2072620.638985 s | 2072620.640613 s |
(w)0xffff888102fc14a0 | 0002 | 0.279 ms | 5 | 0.319 ms | 2072618.029425 s | 2072618.029744 s |
(w)0xffff8881035a83d8 | 0000 | 0.352 ms | 3 | 0.827 ms | 2072620.650451 s | 2072620.651278 s |
(w)0xffff8883335e9040 | 0003 | 0.271 ms | 2 | 0.293 ms | 2072618.917354 s | 2072618.917647 s |
(w)0xffffffff8305ca48 | 0003 | 0.268 ms | 2 | 0.292 ms | 2072618.917407 s | 2072618.917699 s |
(w)0xffff8883331e9040 | 0001 | 0.226 ms | 2 | 0.234 ms | 2072625.965354 s | 2072625.965588 s |
(w)0xffff888101c5cc00 | 0001 | 5120.387 ms | 1 | 5120.387 ms | 2072619.309237 s | 2072624.429624 s |
(w)0xffff8883333e9040 | 0002 | 2.331 ms | 1 | 2.331 ms | 2072618.029512 s | 2072618.031844 s |
(w)0xffff888102e44400 | 0001 | 0.400 ms | 1 | 0.400 ms | 2072625.965284 s | 2072625.965684 s |
(w)0xffff8881035a81e8 | 0004 | 0.285 ms | 1 | 0.285 ms | 2072621.357437 s | 2072621.357722 s |
(w)0xffffffff8305c990 | 0003 | 0.256 ms | 1 | 0.256 ms | 2072625.973445 s | 2072625.973701 s |
(w)0xffff888102e444b8 | 0001 | 0.254 ms | 1 | 0.254 ms | 2072626.173289 s | 2072626.173542 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.024% skipped events (21 including 11 raise, 10 entry, 0 exit)
# perf kwork -k workqueue lat -C 1
Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
---------------------------------------------------------------------------------------------------------------------------
(w)0xffff888101c5cc00 | 0001 | 5120.387 ms | 1 | 5120.387 ms | 2072619.309237 s | 2072624.429624 s |
(w)0xffff888102e44400 | 0001 | 0.400 ms | 1 | 0.400 ms | 2072625.965284 s | 2072625.965684 s |
(w)0xffff888100e65c80 | 0001 | 0.318 ms | 78 | 1.228 ms | 2072620.504051 s | 2072620.505279 s |
(w)0xffff888102e444b8 | 0001 | 0.254 ms | 1 | 0.254 ms | 2072626.173289 s | 2072626.173542 s |
(w)0xffff8883331e9040 | 0001 | 0.226 ms | 2 | 0.234 ms | 2072625.965354 s | 2072625.965588 s |
---------------------------------------------------------------------------------------------------------------------------
INFO: 0.006% skipped events (5 including 3 raise, 2 entry, 0 exit)
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 16 +++++++++++++++-
1 file changed, 15 insertions(+), 1 deletion(-)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index e0ffd3291b3a..7e3da243ccd8 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -935,6 +935,20 @@ static struct kwork_class kwork_softirq = {
};
static struct kwork_class kwork_workqueue;
+static int process_workqueue_activate_work_event(struct perf_tool *tool,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
+
+ if (kwork->tp_handler->raise_event)
+ return kwork->tp_handler->raise_event(kwork, &kwork_workqueue,
+ evsel, sample, machine);
+
+ return 0;
+}
+
static int process_workqueue_execute_start_event(struct perf_tool *tool,
struct evsel *evsel,
struct perf_sample *sample,
@@ -964,7 +978,7 @@ static int process_workqueue_execute_end_event(struct perf_tool *tool,
}
const struct evsel_str_handler workqueue_tp_handlers[] = {
- { "workqueue:workqueue_activate_work", NULL, },
+ { "workqueue:workqueue_activate_work", process_workqueue_activate_work_event, },
{ "workqueue:workqueue_execute_start", process_workqueue_execute_start_event, },
{ "workqueue:workqueue_execute_end", process_workqueue_execute_end_event, },
};
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* [RFC 13/13] perf kwork: Implement perf kwork timehist
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (11 preceding siblings ...)
2022-06-13 9:46 ` [RFC 12/13] perf kwork: Add workqueue " Yang Jihong
@ 2022-06-13 9:46 ` Yang Jihong
2022-06-22 14:59 ` [RFC 00/13] perf: Add perf kwork Paul A. Clarke
13 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-13 9:46 UTC (permalink / raw)
To: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Cc: yangjihong1
Implements framework of perf kwork timehist, to provide an analysis of kernel work events.
test case:
# perf kwork tim
Runtime start Runtime end Cpu Kwork name Runtime Delaytime
(TYPE)NAME:NUM (msec) (msec)
----------------- ----------------- ------ ------------------------- ---------- ----------
2072616.355256 2072616.355295 [0000] (s)SCHED:7 0.040 0.062
2072616.356794 2072616.356865 [0001] (s)RCU:9 0.071 0.083
2072616.358362 2072616.358406 [0002] (s)RCU:9 0.044 0.108
2072616.360179 2072616.360211 [0000] (s)SCHED:7 0.032 0.032
2072616.360608 2072616.360729 [0003] (s)TIMER:1 0.120 0.311
2072616.360753 2072616.360803 [0003] (s)SCHED:7 0.050 0.199
2072616.362232 2072616.362295 [0001] (s)RCU:9 0.063 0.071
2072616.363177 2072616.363229 [0000] (s)SCHED:7 0.052 0.030
2072616.365407 2072616.365502 [0003] (s)TIMER:1 0.096 0.106
2072616.365527 2072616.365595 [0003] (s)SCHED:7 0.068 0.162
2072616.365616 2072616.365670 [0003] (s)RCU:9 0.053 0.290
2072616.366171 2072616.366211 [0000] (s)SCHED:7 0.040 0.029
2072616.366372 2072616.366435 [0001] (s)SCHED:7 0.063 0.053
2072616.369351 2072616.369434 [0003] (s)TIMER:1 0.083 0.060
2072616.369937 2072616.369998 [0005] (s)SCHED:7 0.061 0.042
2072616.370391 2072616.370440 [0006] (s)SCHED:7 0.049 0.081
2072616.370461 2072616.370510 [0006] (s)RCU:9 0.049 1.338
2072616.370020 2072616.372415 [0005] (s)RCU:9 2.395 1.757
2072616.372624 2072616.372689 [0006] (s)SCHED:7 0.065 0.047
2072616.373171 2072616.373226 [0000] (s)SCHED:7 0.055 0.029
2072616.373589 2072616.373621 [0003] (s)TIMER:1 0.032 0.375
2072616.375176 2072616.375353 [0000] (s)SCHED:7 0.177 0.031
2072616.375539 2072616.375587 [0001] (s)RCU:9 0.048 0.082
2072616.377183 2072616.377215 [0000] (s)SCHED:7 0.032 0.032
2072616.379190 2072616.379222 [0000] (s)SCHED:7 0.033 0.032
2072616.379475 2072616.379579 [0007] (s)RCU:9 0.105 0.288
2072616.379832 2072616.379923 [0000] virtio0-requests:25 0.090
2072616.380339 2072616.380392 [0007] (s)SCHED:7 0.054 0.064
2072616.382425 2072616.382486 [0007] (s)RCU:9 0.061 1.181
2072616.383339 2072616.383387 [0002] (s)RCU:9 0.047 1.222
2072616.384265 2072616.384314 [0003] (s)SCHED:7 0.050 0.082
2072616.384824 2072616.384875 [0007] (s)RCU:9 0.051 1.506
2072616.385319 2072616.385361 [0002] (s)RCU:9 0.042 1.088
2072616.386321 2072616.386413 [0003] (s)TIMER:1 0.091 0.107
2072616.386438 2072616.386515 [0003] (s)SCHED:7 0.078 0.159
2072616.386537 2072616.386575 [0003] (s)RCU:9 0.038 0.298
2072616.386068 2072616.387057 [0000] virtio0-requests:25 0.989
2072616.387057 2072616.387057 [0000] (s)SCHED:7 0.000 0.989
2072616.387057 2072616.387057 [0000] (s)SCHED:7 0.000 0.989
2072616.387726 2072616.387781 [0002] (s)RCU:9 0.055 1.512
2072616.387025 2072616.388331 [0007] (s)SCHED:7 1.306 0.052
2072616.388358 2072616.388404 [0007] (s)RCU:9 0.046 0.409
2072616.388527 2072616.388573 [0007] (s)SCHED:7 0.046 0.264
2072616.388595 2072616.388619 [0007] (s)RCU:9 0.024 2.890
2072616.390267 2072616.390353 [0003] (s)TIMER:1 0.086 0.066
2072616.390949 2072616.391060 [0007] (s)RCU:9 0.111 1.711
2072616.391290 2072616.391340 [0002] (s)RCU:9 0.050 1.125
2072616.392304 2072616.392353 [0007] (s)RCU:9 0.049 0.456
...
Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
---
tools/perf/builtin-kwork.c | 253 +++++++++++++++++++++++++++++++++++++
1 file changed, 253 insertions(+)
diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
index 7e3da243ccd8..0ab34e3480fe 100644
--- a/tools/perf/builtin-kwork.c
+++ b/tools/perf/builtin-kwork.c
@@ -41,6 +41,7 @@ enum kwork_trace_type {
enum kwork_report_type {
KWORK_REPORT_RUNTIME,
KWORK_REPORT_LATENCY,
+ KWORK_REPORT_TIMEHIST,
};
/*
@@ -213,10 +214,12 @@ struct perf_kwork {
#define PRINT_TIMESTAMP_WIDTH 17
#define PRINT_KWORK_NAME_WIDTH 25
#define RPINT_DECIMAL_WIDTH 3
+#define PRINT_BRACKETPAIR_WIDTH 2
#define PRINT_TIME_UNIT_SEC_WIDTH 2
#define PRINT_TIME_UNIT_MESC_WIDTH 3
#define PRINT_RUNTIME_HEADER_WIDTH (PRINT_RUNTIME_WIDTH + PRINT_TIME_UNIT_MESC_WIDTH)
#define PRINT_LATENCY_HEADER_WIDTH (PRINT_LATENCY_WIDTH + PRINT_TIME_UNIT_MESC_WIDTH)
+#define PRINT_TIMEHIST_CPU_WIDTH (PRINT_CPU_WIDTH + PRINT_BRACKETPAIR_WIDTH)
#define PRINT_TIMESTAMP_HEADER_WIDTH (PRINT_TIMESTAMP_WIDTH + PRINT_TIME_UNIT_SEC_WIDTH)
struct sort_dimension {
@@ -746,6 +749,181 @@ static int latency_entry_event(struct perf_kwork *kwork,
return 0;
}
+static void timehist_save_callchain(struct perf_kwork *kwork,
+ struct perf_sample *sample,
+ struct evsel *evsel,
+ struct machine *machine)
+{
+ struct symbol *sym;
+ struct thread *thread;
+ struct callchain_cursor_node *node;
+ struct callchain_cursor *cursor = &callchain_cursor;
+
+ if (!kwork->show_callchain || sample->callchain == NULL)
+ return;
+
+ /* want main thread for process - has maps */
+ thread = machine__findnew_thread(machine, sample->pid, sample->pid);
+ if (thread == NULL) {
+ pr_debug("Failed to get thread for pid %d\n", sample->pid);
+ return;
+ }
+
+ if (thread__resolve_callchain(thread, cursor, evsel, sample,
+ NULL, NULL, kwork->max_stack + 2) != 0) {
+ pr_debug("Failed to resolve callchain, skipping\n");
+ goto out_put;
+ }
+
+ callchain_cursor_commit(cursor);
+
+ while (true) {
+ node = callchain_cursor_current(cursor);
+ if (node == NULL)
+ break;
+
+ sym = node->ms.sym;
+ if (sym) {
+ if (!strcmp(sym->name, "__softirqentry_text_start"))
+ sym->ignore = 1;
+ }
+
+ callchain_cursor_advance(cursor);
+ }
+
+out_put:
+ thread__put(thread);
+}
+
+static void timehist_print_event(struct perf_kwork *kwork,
+ struct kwork_cluster *cluster,
+ struct kwork_atom *atom,
+ struct perf_sample *sample,
+ struct addr_location *al)
+{
+ char entrytime[32], exittime[32];
+ char kwork_name[PRINT_KWORK_NAME_WIDTH];
+
+ /*
+ * runtime start
+ */
+ timestamp__scnprintf_usec(atom->time,
+ entrytime, sizeof(entrytime));
+ printf(" %*s ", PRINT_TIMESTAMP_WIDTH, entrytime);
+
+ /*
+ * runtime end
+ */
+ timestamp__scnprintf_usec(sample->time,
+ exittime, sizeof(exittime));
+ printf(" %*s ", PRINT_TIMESTAMP_WIDTH, exittime);
+
+ /*
+ * cpu
+ */
+ printf(" [%0*d] ", PRINT_CPU_WIDTH, cluster->cpu);
+
+ /*
+ * kwork name
+ */
+ if (cluster->class && cluster->class->cluster_name) {
+ cluster->class->cluster_name(cluster, kwork_name,
+ PRINT_KWORK_NAME_WIDTH);
+ printf(" %-*s ", PRINT_KWORK_NAME_WIDTH, kwork_name);
+ } else
+ printf(" %-*s ", PRINT_KWORK_NAME_WIDTH, "");
+
+ /*
+ *runtime
+ */
+ printf(" %*.*f ",
+ PRINT_RUNTIME_WIDTH, RPINT_DECIMAL_WIDTH,
+ (double)(sample->time - atom->time) / NSEC_PER_MSEC);
+
+ /*
+ * delaytime
+ */
+ if (atom->prev != NULL)
+ printf(" %*.*f ", PRINT_LATENCY_WIDTH, RPINT_DECIMAL_WIDTH,
+ (double)(atom->time - atom->prev->time) / NSEC_PER_MSEC);
+ else
+ printf(" %*s ", PRINT_LATENCY_WIDTH, " ");
+
+ /*
+ * callchain
+ */
+ if (kwork->show_callchain) {
+ printf(" ");
+ sample__fprintf_sym(sample, al, 0,
+ EVSEL__PRINT_SYM | EVSEL__PRINT_ONELINE |
+ EVSEL__PRINT_CALLCHAIN_ARROW |
+ EVSEL__PRINT_SKIP_IGNORED,
+ &callchain_cursor, symbol_conf.bt_stop_list,
+ stdout);
+ }
+
+ printf("\n");
+}
+
+static int timehist_raise_event(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine __maybe_unused)
+{
+ return cluster_push_atom(kwork, class, KWORK_TRACE_RAISE,
+ KWORK_TRACE_MAX, evsel, sample, NULL);
+}
+
+static int timehist_entry_event(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ int ret;
+ struct kwork_cluster *cluster = NULL;
+
+ ret = cluster_push_atom(kwork, class, KWORK_TRACE_ENTRY,
+ KWORK_TRACE_RAISE, evsel, sample, &cluster);
+ if (ret)
+ return ret;
+
+ if (cluster != NULL)
+ timehist_save_callchain(kwork, sample, evsel, machine);
+
+ return 0;
+}
+
+static int timehist_exit_event(struct perf_kwork *kwork,
+ struct kwork_class *class,
+ struct evsel *evsel,
+ struct perf_sample *sample,
+ struct machine *machine)
+{
+ struct kwork_atom *atom = NULL;
+ struct kwork_cluster *cluster = NULL;
+ struct addr_location al;
+
+ if (machine__resolve(machine, &al, sample) < 0) {
+ pr_debug("Problem processing event, skipping it\n");
+ return -1;
+ }
+
+ atom = cluster_pop_atom(kwork, class, KWORK_TRACE_EXIT,
+ KWORK_TRACE_ENTRY, evsel, sample, &cluster);
+ if (cluster == NULL)
+ return -1;
+
+ if (atom != NULL) {
+ cluster->nr_atoms++;
+ timehist_print_event(kwork, cluster, atom, sample, &al);
+ atom_del(atom);
+ }
+
+ return 0;
+}
+
static struct kwork_class kwork_irq;
static int process_irq_handler_entry_event(struct perf_tool *tool,
struct evsel *evsel,
@@ -1149,6 +1327,42 @@ static int report_print_header(struct perf_kwork *kwork)
return ret;
}
+static void timehist_print_header(void)
+{
+ /*
+ * header row
+ */
+ printf(" %-*s %-*s %-*s %-*s %-*s %-*s\n",
+ PRINT_TIMESTAMP_WIDTH, "Runtime start",
+ PRINT_TIMESTAMP_WIDTH, "Runtime end",
+ PRINT_TIMEHIST_CPU_WIDTH, "Cpu",
+ PRINT_KWORK_NAME_WIDTH, "Kwork name",
+ PRINT_RUNTIME_WIDTH, "Runtime",
+ PRINT_RUNTIME_WIDTH, "Delaytime");
+
+ /*
+ * units row
+ */
+ printf(" %-*s %-*s %-*s %-*s %-*s %-*s\n",
+ PRINT_TIMESTAMP_WIDTH, "",
+ PRINT_TIMESTAMP_WIDTH, "",
+ PRINT_TIMEHIST_CPU_WIDTH, "",
+ PRINT_KWORK_NAME_WIDTH, "(TYPE)NAME:NUM",
+ PRINT_RUNTIME_WIDTH, "(msec)",
+ PRINT_RUNTIME_WIDTH, "(msec)");
+
+ /*
+ * separator
+ */
+ printf(" %.*s %.*s %.*s %.*s %.*s %.*s\n",
+ PRINT_TIMESTAMP_WIDTH, graph_dotted_line,
+ PRINT_TIMESTAMP_WIDTH, graph_dotted_line,
+ PRINT_TIMEHIST_CPU_WIDTH, graph_dotted_line,
+ PRINT_KWORK_NAME_WIDTH, graph_dotted_line,
+ PRINT_RUNTIME_WIDTH, graph_dotted_line,
+ PRINT_RUNTIME_WIDTH, graph_dotted_line);
+}
+
static void print_summary(struct perf_kwork *kwork)
{
u64 time = kwork->timeend - kwork->timestart;
@@ -1294,6 +1508,11 @@ static int perf_kwork__check_config(struct perf_kwork *kwork,
.raise_event = latency_raise_event,
.entry_event = latency_entry_event,
};
+ static struct trace_kwork_handler timehist_ops = {
+ .raise_event = timehist_raise_event,
+ .entry_event = timehist_entry_event,
+ .exit_event = timehist_exit_event,
+ };
switch (kwork->report) {
case KWORK_REPORT_RUNTIME:
@@ -1302,6 +1521,9 @@ static int perf_kwork__check_config(struct perf_kwork *kwork,
case KWORK_REPORT_LATENCY:
kwork->tp_handler = &latency_ops;
break;
+ case KWORK_REPORT_TIMEHIST:
+ kwork->tp_handler = &timehist_ops;
+ break;
default:
pr_debug("Invalid report type %d\n", kwork->report);
break;
@@ -1364,6 +1586,9 @@ static int perf_kwork__read_events(struct perf_kwork *kwork)
if (perf_kwork__check_config(kwork, session) != 0)
goto out_delete;
+ if (kwork->report == KWORK_REPORT_TIMEHIST)
+ timehist_print_header();
+
ret = perf_session__process_events(session);
if (ret) {
pr_debug("Failed to process events, error %d\n", ret);
@@ -1379,6 +1604,28 @@ static int perf_kwork__read_events(struct perf_kwork *kwork)
return ret;
}
+static int perf_kwork__timehist(struct perf_kwork *kwork)
+{
+ /*
+ * event handlers for timehist option
+ */
+ kwork->tool.mmap = perf_event__process_mmap;
+ kwork->tool.mmap2 = perf_event__process_mmap2;
+ kwork->tool.comm = perf_event__process_comm;
+ kwork->tool.exit = perf_event__process_exit;
+ kwork->tool.fork = perf_event__process_fork;
+ kwork->tool.attr = perf_event__process_attr;
+ kwork->tool.tracing_data = perf_event__process_tracing_data;
+ kwork->tool.build_id = perf_event__process_build_id;
+ kwork->tool.ordered_events = true;
+ kwork->tool.ordering_requires_timestamps = true;
+ symbol_conf.use_callchain = kwork->show_callchain;
+
+ setup_pager();
+
+ return perf_kwork__read_events(kwork);
+}
+
static void process_skipped_events(struct perf_kwork *kwork,
struct kwork_cluster *cluster)
{
@@ -1505,6 +1752,7 @@ static int perf_kwork__record(struct perf_kwork *kwork,
int cmd_kwork(int argc, const char **argv)
{
+ int ret;
static const char default_report_sort_order[] = "runtime, max, freq";
static const char default_latency_sort_order[] = "avg, max, freq";
static struct perf_kwork kwork = {
@@ -1655,6 +1903,11 @@ int cmd_kwork(int argc, const char **argv)
if (argc)
usage_with_options(timehist_usage, timehist_options);
}
+ ret = symbol__validate_sym_arguments();
+ if (ret)
+ return ret;
+ kwork.report = KWORK_REPORT_TIMEHIST;
+ return perf_kwork__timehist(&kwork);
} else
usage_with_options(kwork_usage, kwork_options);
--
2.30.GIT
^ permalink raw reply related [flat|nested] 28+ messages in thread
* Re: [RFC 01/13] perf kwork: New tool
2022-06-13 9:45 ` [RFC 01/13] perf kwork: New tool Yang Jihong
@ 2022-06-14 21:43 ` Namhyung Kim
2022-06-15 1:38 ` Yang Jihong
0 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2022-06-14 21:43 UTC (permalink / raw)
To: Yang Jihong
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
Hello,
On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
>
> 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:
>
> # perf kwork -h
>
> Usage: perf kwork [<options>] {record|report|latency|timehist}
>
> -D, --dump-raw-trace dump raw trace in ASCII
> -f, --force don't complain, do it
> -k, --kwork <kwork> list of kwork to profile (irq, softirq, workqueue etc)
> -v, --verbose be more verbose (show symbol address, etc)
>
> # perf kwork record -- sleep 1
> [ perf record: Woken up 0 times to write data ]
> [ perf record: Captured and wrote 1.696 MB perf.data ]
>
> # perf kwork report -h
>
> Usage: perf kwork report [<options>]
>
> -C, --cpu <cpu> list of cpus to profile
> -i, --input <file> input file name
> -n, --name <name> event name to profile
> -s, --sort <key[,key2...]>
> sort by key(s): runtime, max, freq
> -S, --with-summary Show summary with statistics
> --time <str> Time span for analysis (start,stop)
>
> # perf kwork latency -h
>
> Usage: perf kwork latency [<options>]
>
> -C, --cpu <cpu> list of cpus to profile
> -i, --input <file> input file name
> -n, --name <name> event name to profile
> -s, --sort <key[,key2...]>
> sort by key(s): avg, max, freq
> --time <str> Time span for analysis (start,stop)
>
> # perf kwork timehist -h
>
> Usage: perf kwork timehist [<options>]
>
> -C, --cpu <cpu> list of cpus to profile
> -g, --call-graph Display call chains if present
> -i, --input <file> input file name
> -k, --vmlinux <file> vmlinux pathname
> -n, --name <name> event name to profile
> --kallsyms <file>
> kallsyms pathname
> --max-stack <n> Maximum number of functions to display backtrace.
> --symfs <directory>
> Look for files with symbols relative to this directory
> --time <str> Time span for analysis (start,stop)
I think you can add this and the documentation when you
actually add the functionality later.
Thanks,
Namhyung
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 06/13] perf kwork: Implement perf kwork report
2022-06-13 9:45 ` [RFC 06/13] perf kwork: Implement perf kwork report Yang Jihong
@ 2022-06-14 21:49 ` Namhyung Kim
2022-06-15 3:12 ` Yang Jihong
0 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2022-06-14 21:49 UTC (permalink / raw)
To: Yang Jihong
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
>
> Implements framework of perf kwork report, which is used to report time
> properties such as run time and frequency:
>
> test case:
>
> Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
> ---------------------------------------------------------------------------------------------------------------------------
> ---------------------------------------------------------------------------------------------------------------------------
>
> Since there are no report supported events, the output is empty.
>
> Briefly describe the data structure:
> 1. "class" indicates event type. For example, irq and softiq correspond
> to different types.
> 2. "cluster" refers to a specific event corresponding to a type. For
> example, RCU and TIMER in softirq correspond to different clusters,
> which contains three types of events: raise, entry, and exit.
I'm not good at naming but how about calling it "work" instead?
It's all about kernel works anyway..
Thanks,
Namhyung
> 3. "atom" includes time of each sample and sample of the previous phase.
> (For example, exit corresponds to entry, which is used for timehist.)
>
> Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 09/13] perf kwork: Add workqueue report support
2022-06-13 9:46 ` [RFC 09/13] perf kwork: Add workqueue " Yang Jihong
@ 2022-06-14 21:54 ` Namhyung Kim
2022-06-15 3:22 ` Yang Jihong
0 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2022-06-14 21:54 UTC (permalink / raw)
To: Yang Jihong
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
>
> Implements workqueue report function.
>
> test case:
>
> # perf kwork -k workqueue rep
>
> Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
> ---------------------------------------------------------------------------------------------------------------------------
> (w)0xffffffff83e09fa0 | 0001 | 2152.678 ms | 194 | 12.376 ms | 2059361.546621 s | 2059361.558997 s |
> (w)0xffff888332fea180 | 0000 | 17.125 ms | 301 | 1.018 ms | 2059358.441070 s | 2059358.442089 s |
> (w)0xffff8881035a83d8 | 0007 | 7.556 ms | 3 | 3.212 ms | 2059362.614643 s | 2059362.617855 s |
> (w)0xffff888102fc14a0 | 0002 | 7.080 ms | 5 | 1.962 ms | 2059365.421753 s | 2059365.423714 s |
> (w)0xffffffff82f7da00 | 0000 | 4.277 ms | 7 | 3.778 ms | 2059360.851063 s | 2059360.854841 s |
> (w)0xffffffff8305d680 | 0006 | 1.796 ms | 1 | 1.796 ms | 2059360.046818 s | 2059360.048613 s |
> (w)0xffff8883339e9040 | 0005 | 1.659 ms | 2 | 1.619 ms | 2059361.266051 s | 2059361.267670 s |
> (w)0xffff888333de9040 | 0007 | 1.121 ms | 5 | 0.783 ms | 2059368.238059 s | 2059368.238842 s |
> (w)0xffff888332fe9040 | 0000 | 0.990 ms | 4 | 0.911 ms | 2059359.604075 s | 2059359.604986 s |
> (w)0xffff8883331e9040 | 0001 | 0.244 ms | 6 | 0.046 ms | 2059362.689277 s | 2059362.689323 s |
> (w)0xffff888102e44400 | 0007 | 0.239 ms | 2 | 0.137 ms | 2059363.117537 s | 2059363.117674 s |
> (w)0xffff8883333ea180 | 0002 | 0.141 ms | 5 | 0.049 ms | 2059365.423784 s | 2059365.423833 s |
> (w)0xffffffff83062f28 | 0006 | 0.084 ms | 2 | 0.047 ms | 2059358.208033 s | 2059358.208080 s |
> (w)0xffffffff8305ca48 | 0003 | 0.078 ms | 2 | 0.041 ms | 2059361.071371 s | 2059361.071412 s |
> (w)0xffff8883337e9040 | 0004 | 0.062 ms | 1 | 0.062 ms | 2059362.605723 s | 2059362.605785 s |
> (w)0xffff8881035a81e8 | 0001 | 0.056 ms | 1 | 0.056 ms | 2059363.118231 s | 2059363.118287 s |
> (w)0xffff8883335e9040 | 0003 | 0.026 ms | 1 | 0.026 ms | 2059358.573397 s | 2059358.573423 s |
> (w)0xffffffff83062e70 | 0006 | 0.023 ms | 1 | 0.023 ms | 2059368.398864 s | 2059368.398888 s |
> (w)0xffffffff83e06480 | 0002 | 0.000 ms | 1 | 0.000 ms | 2059359.986792 s | 2059359.986792 s |
Using "function" in the tracepoint and symbolizing it would be
far more intuitive.
Thanks,
Namhyung
> ---------------------------------------------------------------------------------------------------------------------------
>
> Signed-off-by: Yang Jihong <yangjihong1@huawei.com>
> ---
> tools/perf/builtin-kwork.c | 65 ++++++++++++++++++++++++++++++++++++--
> 1 file changed, 63 insertions(+), 2 deletions(-)
>
> diff --git a/tools/perf/builtin-kwork.c b/tools/perf/builtin-kwork.c
> index 1eb416faf8ef..f27ffad223a3 100644
> --- a/tools/perf/builtin-kwork.c
> +++ b/tools/perf/builtin-kwork.c
> @@ -813,16 +813,77 @@ static struct kwork_class kwork_softirq = {
> .cluster_name = softirq_cluster_name,
> };
>
> +static struct kwork_class kwork_workqueue;
> +static int process_workqueue_execute_start_event(struct perf_tool *tool,
> + struct evsel *evsel,
> + struct perf_sample *sample,
> + struct machine *machine)
> +{
> + struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
> +
> + if (kwork->tp_handler->entry_event)
> + return kwork->tp_handler->entry_event(kwork, &kwork_workqueue,
> + evsel, sample, machine);
> +
> + return 0;
> +}
> +
> +static int process_workqueue_execute_end_event(struct perf_tool *tool,
> + struct evsel *evsel,
> + struct perf_sample *sample,
> + struct machine *machine)
> +{
> + struct perf_kwork *kwork = container_of(tool, struct perf_kwork, tool);
> +
> + if (kwork->tp_handler->exit_event)
> + return kwork->tp_handler->exit_event(kwork, &kwork_workqueue,
> + evsel, sample, machine);
> +
> + return 0;
> +}
> +
> const struct evsel_str_handler workqueue_tp_handlers[] = {
> { "workqueue:workqueue_activate_work", NULL, },
> - { "workqueue:workqueue_execute_start", NULL, },
> - { "workqueue:workqueue_execute_end", NULL, },
> + { "workqueue:workqueue_execute_start", process_workqueue_execute_start_event, },
> + { "workqueue:workqueue_execute_end", process_workqueue_execute_end_event, },
> };
>
> +static int workqueue_class_init(struct kwork_class *class,
> + struct perf_session *session)
> +{
> + if (perf_session__set_tracepoints_handlers(session,
> + workqueue_tp_handlers)) {
> + pr_debug("Failed to set workqueue tracepoints handlers\n");
> + return -1;
> + }
> +
> + class->cluster_root = RB_ROOT_CACHED;
> + return 0;
> +}
> +
> +static void workqueue_cluster_init(struct kwork_class *class,
> + struct kwork_cluster *cluster,
> + struct evsel *evsel,
> + struct perf_sample *sample)
> +{
> + cluster->name = NULL;
> + cluster->class = class;
> + cluster->cpu = sample->cpu;
> + cluster->id = evsel__intval(evsel, sample, "work");
> +}
> +
> +static void workqueue_cluster_name(struct kwork_cluster *cluster, char *buf, int len)
> +{
> + snprintf(buf, len, "(w)0x%" PRIx64, cluster->id);
> +}
> +
> static struct kwork_class kwork_workqueue = {
> .name = "workqueue",
> .nr_tracepoints = 3,
> .tp_handlers = workqueue_tp_handlers,
> + .class_init = workqueue_class_init,
> + .cluster_init = workqueue_cluster_init,
> + .cluster_name = workqueue_cluster_name,
> };
>
> static struct kwork_class *kwork_class_supported_list[KWORK_CLASS_MAX] = {
> --
> 2.30.GIT
>
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 01/13] perf kwork: New tool
2022-06-14 21:43 ` Namhyung Kim
@ 2022-06-15 1:38 ` Yang Jihong
0 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-15 1:38 UTC (permalink / raw)
To: Namhyung Kim
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
Hello, Namhyung
On 2022/6/15 5:43, Namhyung Kim wrote:
> Hello,
>
> On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
>>
>> 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:
>>
>> # perf kwork -h
>>
>> Usage: perf kwork [<options>] {record|report|latency|timehist}
>>
>> -D, --dump-raw-trace dump raw trace in ASCII
>> -f, --force don't complain, do it
>> -k, --kwork <kwork> list of kwork to profile (irq, softirq, workqueue etc)
>> -v, --verbose be more verbose (show symbol address, etc)
>>
>> # perf kwork record -- sleep 1
>> [ perf record: Woken up 0 times to write data ]
>> [ perf record: Captured and wrote 1.696 MB perf.data ]
>>
>> # perf kwork report -h
>>
>> Usage: perf kwork report [<options>]
>>
>> -C, --cpu <cpu> list of cpus to profile
>> -i, --input <file> input file name
>> -n, --name <name> event name to profile
>> -s, --sort <key[,key2...]>
>> sort by key(s): runtime, max, freq
>> -S, --with-summary Show summary with statistics
>> --time <str> Time span for analysis (start,stop)
>>
>> # perf kwork latency -h
>>
>> Usage: perf kwork latency [<options>]
>>
>> -C, --cpu <cpu> list of cpus to profile
>> -i, --input <file> input file name
>> -n, --name <name> event name to profile
>> -s, --sort <key[,key2...]>
>> sort by key(s): avg, max, freq
>> --time <str> Time span for analysis (start,stop)
>>
>> # perf kwork timehist -h
>>
>> Usage: perf kwork timehist [<options>]
>>
>> -C, --cpu <cpu> list of cpus to profile
>> -g, --call-graph Display call chains if present
>> -i, --input <file> input file name
>> -k, --vmlinux <file> vmlinux pathname
>> -n, --name <name> event name to profile
>> --kallsyms <file>
>> kallsyms pathname
>> --max-stack <n> Maximum number of functions to display backtrace.
>> --symfs <directory>
>> Look for files with symbols relative to this directory
>> --time <str> Time span for analysis (start,stop)
>
> I think you can add this and the documentation when you
> actually add the functionality later.
>
OK, I'll fix in next version.
Thanks，
Jihong
.
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 06/13] perf kwork: Implement perf kwork report
2022-06-14 21:49 ` Namhyung Kim
@ 2022-06-15 3:12 ` Yang Jihong
2022-06-15 22:01 ` Namhyung Kim
0 siblings, 1 reply; 28+ messages in thread
From: Yang Jihong @ 2022-06-15 3:12 UTC (permalink / raw)
To: Namhyung Kim
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
Hello,
On 2022/6/15 5:49, Namhyung Kim wrote:
> On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
>>
>> Implements framework of perf kwork report, which is used to report time
>> properties such as run time and frequency:
>>
>> test case:
>>
>> Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
>> ---------------------------------------------------------------------------------------------------------------------------
>> ---------------------------------------------------------------------------------------------------------------------------
>>
>> Since there are no report supported events, the output is empty.
>>
>> Briefly describe the data structure:
>> 1. "class" indicates event type. For example, irq and softiq correspond
>> to different types.
>> 2. "cluster" refers to a specific event corresponding to a type. For
>> example, RCU and TIMER in softirq correspond to different clusters,
>> which contains three types of events: raise, entry, and exit.
>
> I'm not good at naming but how about calling it "work" instead?
> It's all about kernel works anyway..
>
How about calling it "work_atoms" ?
Otherwise, "work" feels a little similar to kwork_class in the first step.
Thanks,
Jihong
.
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 09/13] perf kwork: Add workqueue report support
2022-06-14 21:54 ` Namhyung Kim
@ 2022-06-15 3:22 ` Yang Jihong
2022-06-15 21:56 ` Namhyung Kim
0 siblings, 1 reply; 28+ messages in thread
From: Yang Jihong @ 2022-06-15 3:22 UTC (permalink / raw)
To: Namhyung Kim
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
Hello,
On 2022/6/15 5:54, Namhyung Kim wrote:
> On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
>>
>> Implements workqueue report function.
>>
>> test case:
>>
>> # perf kwork -k workqueue rep
>>
>> Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
>> ---------------------------------------------------------------------------------------------------------------------------
>> (w)0xffffffff83e09fa0 | 0001 | 2152.678 ms | 194 | 12.376 ms | 2059361.546621 s | 2059361.558997 s |
>> (w)0xffff888332fea180 | 0000 | 17.125 ms | 301 | 1.018 ms | 2059358.441070 s | 2059358.442089 s |
>> (w)0xffff8881035a83d8 | 0007 | 7.556 ms | 3 | 3.212 ms | 2059362.614643 s | 2059362.617855 s |
>> (w)0xffff888102fc14a0 | 0002 | 7.080 ms | 5 | 1.962 ms | 2059365.421753 s | 2059365.423714 s |
>> (w)0xffffffff82f7da00 | 0000 | 4.277 ms | 7 | 3.778 ms | 2059360.851063 s | 2059360.854841 s |
>> (w)0xffffffff8305d680 | 0006 | 1.796 ms | 1 | 1.796 ms | 2059360.046818 s | 2059360.048613 s |
>> (w)0xffff8883339e9040 | 0005 | 1.659 ms | 2 | 1.619 ms | 2059361.266051 s | 2059361.267670 s |
>> (w)0xffff888333de9040 | 0007 | 1.121 ms | 5 | 0.783 ms | 2059368.238059 s | 2059368.238842 s |
>> (w)0xffff888332fe9040 | 0000 | 0.990 ms | 4 | 0.911 ms | 2059359.604075 s | 2059359.604986 s |
>> (w)0xffff8883331e9040 | 0001 | 0.244 ms | 6 | 0.046 ms | 2059362.689277 s | 2059362.689323 s |
>> (w)0xffff888102e44400 | 0007 | 0.239 ms | 2 | 0.137 ms | 2059363.117537 s | 2059363.117674 s |
>> (w)0xffff8883333ea180 | 0002 | 0.141 ms | 5 | 0.049 ms | 2059365.423784 s | 2059365.423833 s |
>> (w)0xffffffff83062f28 | 0006 | 0.084 ms | 2 | 0.047 ms | 2059358.208033 s | 2059358.208080 s |
>> (w)0xffffffff8305ca48 | 0003 | 0.078 ms | 2 | 0.041 ms | 2059361.071371 s | 2059361.071412 s |
>> (w)0xffff8883337e9040 | 0004 | 0.062 ms | 1 | 0.062 ms | 2059362.605723 s | 2059362.605785 s |
>> (w)0xffff8881035a81e8 | 0001 | 0.056 ms | 1 | 0.056 ms | 2059363.118231 s | 2059363.118287 s |
>> (w)0xffff8883335e9040 | 0003 | 0.026 ms | 1 | 0.026 ms | 2059358.573397 s | 2059358.573423 s |
>> (w)0xffffffff83062e70 | 0006 | 0.023 ms | 1 | 0.023 ms | 2059368.398864 s | 2059368.398888 s |
>> (w)0xffffffff83e06480 | 0002 | 0.000 ms | 1 | 0.000 ms | 2059359.986792 s | 2059359.986792 s |
>
> Using "function" in the tracepoint and symbolizing it would be
> far more intuitive.
>
OK，This is a simplified version that will be improved in the next
version, and I'd like to add the following features:
1. Supports the kthread profile.
2. Save runtime and latency in kernel using ebpf(similar to "perf
record: Implement off-cpu profiling with BPF") . This reduces the number
of interruptions caused by writing files to hard disks, which is closer
to the actual scenario.
This RFC is sent to discuss to see if this function is useful to the
community and can be accepted by the community. :)
Thanks,
Jihong
.
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 09/13] perf kwork: Add workqueue report support
2022-06-15 3:22 ` Yang Jihong
@ 2022-06-15 21:56 ` Namhyung Kim
2022-06-16 1:42 ` Yang Jihong
0 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2022-06-15 21:56 UTC (permalink / raw)
To: Yang Jihong
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
On Tue, Jun 14, 2022 at 8:22 PM Yang Jihong <yangjihong1@huawei.com> wrote:
>
> Hello,
>
> On 2022/6/15 5:54, Namhyung Kim wrote:
> > On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
> >>
> >> Implements workqueue report function.
> >>
> >> test case:
> >>
> >> # perf kwork -k workqueue rep
> >>
> >> Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
> >> ---------------------------------------------------------------------------------------------------------------------------
> >> (w)0xffffffff83e09fa0 | 0001 | 2152.678 ms | 194 | 12.376 ms | 2059361.546621 s | 2059361.558997 s |
> >> (w)0xffff888332fea180 | 0000 | 17.125 ms | 301 | 1.018 ms | 2059358.441070 s | 2059358.442089 s |
> >> (w)0xffff8881035a83d8 | 0007 | 7.556 ms | 3 | 3.212 ms | 2059362.614643 s | 2059362.617855 s |
> >> (w)0xffff888102fc14a0 | 0002 | 7.080 ms | 5 | 1.962 ms | 2059365.421753 s | 2059365.423714 s |
> >> (w)0xffffffff82f7da00 | 0000 | 4.277 ms | 7 | 3.778 ms | 2059360.851063 s | 2059360.854841 s |
> >> (w)0xffffffff8305d680 | 0006 | 1.796 ms | 1 | 1.796 ms | 2059360.046818 s | 2059360.048613 s |
> >> (w)0xffff8883339e9040 | 0005 | 1.659 ms | 2 | 1.619 ms | 2059361.266051 s | 2059361.267670 s |
> >> (w)0xffff888333de9040 | 0007 | 1.121 ms | 5 | 0.783 ms | 2059368.238059 s | 2059368.238842 s |
> >> (w)0xffff888332fe9040 | 0000 | 0.990 ms | 4 | 0.911 ms | 2059359.604075 s | 2059359.604986 s |
> >> (w)0xffff8883331e9040 | 0001 | 0.244 ms | 6 | 0.046 ms | 2059362.689277 s | 2059362.689323 s |
> >> (w)0xffff888102e44400 | 0007 | 0.239 ms | 2 | 0.137 ms | 2059363.117537 s | 2059363.117674 s |
> >> (w)0xffff8883333ea180 | 0002 | 0.141 ms | 5 | 0.049 ms | 2059365.423784 s | 2059365.423833 s |
> >> (w)0xffffffff83062f28 | 0006 | 0.084 ms | 2 | 0.047 ms | 2059358.208033 s | 2059358.208080 s |
> >> (w)0xffffffff8305ca48 | 0003 | 0.078 ms | 2 | 0.041 ms | 2059361.071371 s | 2059361.071412 s |
> >> (w)0xffff8883337e9040 | 0004 | 0.062 ms | 1 | 0.062 ms | 2059362.605723 s | 2059362.605785 s |
> >> (w)0xffff8881035a81e8 | 0001 | 0.056 ms | 1 | 0.056 ms | 2059363.118231 s | 2059363.118287 s |
> >> (w)0xffff8883335e9040 | 0003 | 0.026 ms | 1 | 0.026 ms | 2059358.573397 s | 2059358.573423 s |
> >> (w)0xffffffff83062e70 | 0006 | 0.023 ms | 1 | 0.023 ms | 2059368.398864 s | 2059368.398888 s |
> >> (w)0xffffffff83e06480 | 0002 | 0.000 ms | 1 | 0.000 ms | 2059359.986792 s | 2059359.986792 s |
> >
> > Using "function" in the tracepoint and symbolizing it would be
> > far more intuitive.
> >
> OK，This is a simplified version that will be improved in the next
> version, and I'd like to add the following features:
> 1. Supports the kthread profile.
Could you elaborate more?
> 2. Save runtime and latency in kernel using ebpf(similar to "perf
> record: Implement off-cpu profiling with BPF") . This reduces the number
> of interruptions caused by writing files to hard disks, which is closer
> to the actual scenario.
Sounds great.
>
> This RFC is sent to discuss to see if this function is useful to the
> community and can be accepted by the community. :)
Yeah I think it'd be useful.
Thanks,
Namhyung
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 06/13] perf kwork: Implement perf kwork report
2022-06-15 3:12 ` Yang Jihong
@ 2022-06-15 22:01 ` Namhyung Kim
2022-06-16 1:31 ` Yang Jihong
0 siblings, 1 reply; 28+ messages in thread
From: Namhyung Kim @ 2022-06-15 22:01 UTC (permalink / raw)
To: Yang Jihong
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
On Tue, Jun 14, 2022 at 8:12 PM Yang Jihong <yangjihong1@huawei.com> wrote:
>
> Hello,
>
> On 2022/6/15 5:49, Namhyung Kim wrote:
> > On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
> >>
> >> Implements framework of perf kwork report, which is used to report time
> >> properties such as run time and frequency:
> >>
> >> test case:
> >>
> >> Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
> >> ---------------------------------------------------------------------------------------------------------------------------
> >> ---------------------------------------------------------------------------------------------------------------------------
> >>
> >> Since there are no report supported events, the output is empty.
> >>
> >> Briefly describe the data structure:
> >> 1. "class" indicates event type. For example, irq and softiq correspond
> >> to different types.
> >> 2. "cluster" refers to a specific event corresponding to a type. For
> >> example, RCU and TIMER in softirq correspond to different clusters,
> >> which contains three types of events: raise, entry, and exit.
> >
> > I'm not good at naming but how about calling it "work" instead?
> > It's all about kernel works anyway..
> >
> How about calling it "work_atoms" ?
> Otherwise, "work" feels a little similar to kwork_class in the first step.
Didn't you already have "atom"? I think we can have a hierarchy like
class (IRQ) - work (eth0) - atom.
Thanks,
Namhyung
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 06/13] perf kwork: Implement perf kwork report
2022-06-15 22:01 ` Namhyung Kim
@ 2022-06-16 1:31 ` Yang Jihong
0 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-16 1:31 UTC (permalink / raw)
To: Namhyung Kim
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
Hello,
On 2022/6/16 6:01, Namhyung Kim wrote:
> On Tue, Jun 14, 2022 at 8:12 PM Yang Jihong <yangjihong1@huawei.com> wrote:
>>
>> Hello,
>>
>> On 2022/6/15 5:49, Namhyung Kim wrote:
>>> On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
>>>>
>>>> Implements framework of perf kwork report, which is used to report time
>>>> properties such as run time and frequency:
>>>>
>>>> test case:
>>>>
>>>> Kwork Name | Cpu | Avg delay | Frequency | Max delay | Max delay start | Max delay end |
>>>> ---------------------------------------------------------------------------------------------------------------------------
>>>> ---------------------------------------------------------------------------------------------------------------------------
>>>>
>>>> Since there are no report supported events, the output is empty.
>>>>
>>>> Briefly describe the data structure:
>>>> 1. "class" indicates event type. For example, irq and softiq correspond
>>>> to different types.
>>>> 2. "cluster" refers to a specific event corresponding to a type. For
>>>> example, RCU and TIMER in softirq correspond to different clusters,
>>>> which contains three types of events: raise, entry, and exit.
>>>
>>> I'm not good at naming but how about calling it "work" instead?
>>> It's all about kernel works anyway..
>>>
>> How about calling it "work_atoms" ?
>> Otherwise, "work" feels a little similar to kwork_class in the first step.
>
> Didn't you already have "atom"? I think we can have a hierarchy like
> class (IRQ) - work (eth0) - atom.
OK, I'll modify it in next version according to this hierarchy.
Thanks,
Jihong
.
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 09/13] perf kwork: Add workqueue report support
2022-06-15 21:56 ` Namhyung Kim
@ 2022-06-16 1:42 ` Yang Jihong
0 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-16 1:42 UTC (permalink / raw)
To: Namhyung Kim
Cc: Peter Zijlstra, Ingo Molnar, Arnaldo Carvalho de Melo,
Mark Rutland, Alexander Shishkin, Jiri Olsa, linux-kernel,
linux-perf-users
Hello,
On 2022/6/16 5:56, Namhyung Kim wrote:
> On Tue, Jun 14, 2022 at 8:22 PM Yang Jihong <yangjihong1@huawei.com> wrote:
>>
>> Hello,
>>
>> On 2022/6/15 5:54, Namhyung Kim wrote:
>>> On Mon, Jun 13, 2022 at 2:48 AM Yang Jihong <yangjihong1@huawei.com> wrote:
>>>>
>>>> Implements workqueue report function.
>>>>
>>>> test case:
>>>>
>>>> # perf kwork -k workqueue rep
>>>>
>>>> Kwork Name | Cpu | Total Runtime | Frequency | Max runtime | Max runtime start | Max runtime end |
>>>> ---------------------------------------------------------------------------------------------------------------------------
>>>> (w)0xffffffff83e09fa0 | 0001 | 2152.678 ms | 194 | 12.376 ms | 2059361.546621 s | 2059361.558997 s |
>>>> (w)0xffff888332fea180 | 0000 | 17.125 ms | 301 | 1.018 ms | 2059358.441070 s | 2059358.442089 s |
>>>> (w)0xffff8881035a83d8 | 0007 | 7.556 ms | 3 | 3.212 ms | 2059362.614643 s | 2059362.617855 s |
>>>> (w)0xffff888102fc14a0 | 0002 | 7.080 ms | 5 | 1.962 ms | 2059365.421753 s | 2059365.423714 s |
>>>> (w)0xffffffff82f7da00 | 0000 | 4.277 ms | 7 | 3.778 ms | 2059360.851063 s | 2059360.854841 s |
>>>> (w)0xffffffff8305d680 | 0006 | 1.796 ms | 1 | 1.796 ms | 2059360.046818 s | 2059360.048613 s |
>>>> (w)0xffff8883339e9040 | 0005 | 1.659 ms | 2 | 1.619 ms | 2059361.266051 s | 2059361.267670 s |
>>>> (w)0xffff888333de9040 | 0007 | 1.121 ms | 5 | 0.783 ms | 2059368.238059 s | 2059368.238842 s |
>>>> (w)0xffff888332fe9040 | 0000 | 0.990 ms | 4 | 0.911 ms | 2059359.604075 s | 2059359.604986 s |
>>>> (w)0xffff8883331e9040 | 0001 | 0.244 ms | 6 | 0.046 ms | 2059362.689277 s | 2059362.689323 s |
>>>> (w)0xffff888102e44400 | 0007 | 0.239 ms | 2 | 0.137 ms | 2059363.117537 s | 2059363.117674 s |
>>>> (w)0xffff8883333ea180 | 0002 | 0.141 ms | 5 | 0.049 ms | 2059365.423784 s | 2059365.423833 s |
>>>> (w)0xffffffff83062f28 | 0006 | 0.084 ms | 2 | 0.047 ms | 2059358.208033 s | 2059358.208080 s |
>>>> (w)0xffffffff8305ca48 | 0003 | 0.078 ms | 2 | 0.041 ms | 2059361.071371 s | 2059361.071412 s |
>>>> (w)0xffff8883337e9040 | 0004 | 0.062 ms | 1 | 0.062 ms | 2059362.605723 s | 2059362.605785 s |
>>>> (w)0xffff8881035a81e8 | 0001 | 0.056 ms | 1 | 0.056 ms | 2059363.118231 s | 2059363.118287 s |
>>>> (w)0xffff8883335e9040 | 0003 | 0.026 ms | 1 | 0.026 ms | 2059358.573397 s | 2059358.573423 s |
>>>> (w)0xffffffff83062e70 | 0006 | 0.023 ms | 1 | 0.023 ms | 2059368.398864 s | 2059368.398888 s |
>>>> (w)0xffffffff83e06480 | 0002 | 0.000 ms | 1 | 0.000 ms | 2059359.986792 s | 2059359.986792 s |
>>>
>>> Using "function" in the tracepoint and symbolizing it would be
>>> far more intuitive.
>>>
>> OK，This is a simplified version that will be improved in the next
>> version, and I'd like to add the following features:
>> 1. Supports the kthread profile.
>
> Could you elaborate more?
trace kthread tracepoints (sched:sched_kthread_work_queue_work, sched:
sched_kthread_work_execute_start and
sched:sched_kthread_work_execute_end) can support kthread profile,
because framework has been set up. we only need to add a new kthread
class class.
>
>> 2. Save runtime and latency in kernel using ebpf(similar to "perf
>> record: Implement off-cpu profiling with BPF") . This reduces the number
>> of interruptions caused by writing files to hard disks, which is closer
>> to the actual scenario.
>
> Sounds great.
OK, I'll add it in next version.
>
>>
>> This RFC is sent to discuss to see if this function is useful to the
>> community and can be accepted by the community. :)
>
> Yeah I think it'd be useful.
Thanks for your affirmation.
Thanks,
Jihong
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 00/13] perf: Add perf kwork
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
` (12 preceding siblings ...)
2022-06-13 9:46 ` [RFC 13/13] perf kwork: Implement perf kwork timehist Yang Jihong
@ 2022-06-22 14:59 ` Paul A. Clarke
2022-06-23 1:02 ` Yang Jihong
13 siblings, 1 reply; 28+ messages in thread
From: Paul A. Clarke @ 2022-06-22 14:59 UTC (permalink / raw)
To: Yang Jihong
Cc: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
On Mon, Jun 13, 2022 at 05:45:52PM +0800, Yang Jihong wrote:
> 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 |
What units are used for "Frequency"? It would be helpful to include somewhere.
PC
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 00/13] perf: Add perf kwork
2022-06-22 14:59 ` [RFC 00/13] perf: Add perf kwork Paul A. Clarke
@ 2022-06-23 1:02 ` Yang Jihong
2022-06-23 14:25 ` Paul A. Clarke
0 siblings, 1 reply; 28+ messages in thread
From: Yang Jihong @ 2022-06-23 1:02 UTC (permalink / raw)
To: Paul A. Clarke
Cc: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Hello,
On 2022/6/22 22:59, Paul A. Clarke wrote:
> On Mon, Jun 13, 2022 at 05:45:52PM +0800, Yang Jihong wrote:
>> 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 |
>
> What units are used for "Frequency"? It would be helpful to include somewhere.
This refers to the number of event in the trace period.
Thanks，
Jihong
>
> PC
> .
>
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 00/13] perf: Add perf kwork
2022-06-23 1:02 ` Yang Jihong
@ 2022-06-23 14:25 ` Paul A. Clarke
2022-06-24 1:26 ` Yang Jihong
0 siblings, 1 reply; 28+ messages in thread
From: Paul A. Clarke @ 2022-06-23 14:25 UTC (permalink / raw)
To: Yang Jihong
Cc: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
On Thu, Jun 23, 2022 at 09:02:45AM +0800, Yang Jihong wrote:
> On 2022/6/22 22:59, Paul A. Clarke wrote:
> > On Mon, Jun 13, 2022 at 05:45:52PM +0800, Yang Jihong wrote:
> > > 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 |
> >
> > What units are used for "Frequency"? It would be helpful to include somewhere.
> This refers to the number of event in the trace period.
I see. I suggest changing the column heading to say that.
"Count", "Number of Events", "Occurrences", something like that.
"Frequency" is a count-per-time-unit, like hertz, which doesn't
match well here.
PC
^ permalink raw reply [flat|nested] 28+ messages in thread
* Re: [RFC 00/13] perf: Add perf kwork
2022-06-23 14:25 ` Paul A. Clarke
@ 2022-06-24 1:26 ` Yang Jihong
0 siblings, 0 replies; 28+ messages in thread
From: Yang Jihong @ 2022-06-24 1:26 UTC (permalink / raw)
To: Paul A. Clarke
Cc: peterz, mingo, acme, mark.rutland, alexander.shishkin, jolsa,
namhyung, linux-kernel, linux-perf-users
Hello,
On 2022/6/23 22:25, Paul A. Clarke wrote:
> On Thu, Jun 23, 2022 at 09:02:45AM +0800, Yang Jihong wrote:
>> On 2022/6/22 22:59, Paul A. Clarke wrote:
>>> On Mon, Jun 13, 2022 at 05:45:52PM +0800, Yang Jihong wrote:
>>>> 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 |
>>>
>>> What units are used for "Frequency"? It would be helpful to include somewhere.
>
>> This refers to the number of event in the trace period.
>
> I see. I suggest changing the column heading to say that.
> "Count", "Number of Events", "Occurrences", something like that.
>
> "Frequency" is a count-per-time-unit, like hertz, which doesn't
> match well here.
OK, I'll fix in next version.
Thanks,
Jihong
^ permalink raw reply [flat|nested] 28+ messages in thread
end of thread, other threads:[~2022-06-24 1:27 UTC | newest]
Thread overview: 28+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-06-13 9:45 [RFC 00/13] perf: Add perf kwork Yang Jihong
2022-06-13 9:45 ` [RFC 01/13] perf kwork: New tool Yang Jihong
2022-06-14 21:43 ` Namhyung Kim
2022-06-15 1:38 ` Yang Jihong
2022-06-13 9:45 ` [RFC 02/13] perf kwork: Add irq record support Yang Jihong
2022-06-13 9:45 ` [RFC 03/13] perf kwork: Add softirq " Yang Jihong
2022-06-13 9:45 ` [RFC 04/13] perf kwork: Add workqueue " Yang Jihong
2022-06-13 9:45 ` [RFC 05/13] tools lib: Add list_last_entry_or_null Yang Jihong
2022-06-13 9:45 ` [RFC 06/13] perf kwork: Implement perf kwork report Yang Jihong
2022-06-14 21:49 ` Namhyung Kim
2022-06-15 3:12 ` Yang Jihong
2022-06-15 22:01 ` Namhyung Kim
2022-06-16 1:31 ` Yang Jihong
2022-06-13 9:45 ` [RFC 07/13] perf kwork: Add irq report support Yang Jihong
2022-06-13 9:46 ` [RFC 08/13] perf kwork: Add softirq " Yang Jihong
2022-06-13 9:46 ` [RFC 09/13] perf kwork: Add workqueue " Yang Jihong
2022-06-14 21:54 ` Namhyung Kim
2022-06-15 3:22 ` Yang Jihong
2022-06-15 21:56 ` Namhyung Kim
2022-06-16 1:42 ` Yang Jihong
2022-06-13 9:46 ` [RFC 10/13] perf kwork: Implement perf kwork latency Yang Jihong
2022-06-13 9:46 ` [RFC 11/13] perf kwork: Add softirq latency support Yang Jihong
2022-06-13 9:46 ` [RFC 12/13] perf kwork: Add workqueue " Yang Jihong
2022-06-13 9:46 ` [RFC 13/13] perf kwork: Implement perf kwork timehist Yang Jihong
2022-06-22 14:59 ` [RFC 00/13] perf: Add perf kwork Paul A. Clarke
2022-06-23 1:02 ` Yang Jihong
2022-06-23 14:25 ` Paul A. Clarke
2022-06-24 1:26 ` Yang Jihong
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.