LinuxLists.cc - [RFC 00/13] perf: Add perf kwork

2022-06-13 12:54:17

Subject: [RFC 00/13] perf: Add perf kwork

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

2022-06-13 12:57:39

by Yang Jihong

[permalink] [raw]

Subject: [RFC 13/13] perf kwork: Implement perf kwork timehist

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 <[email protected]>
---
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

2022-06-13 13:00:52

by Yang Jihong

[permalink] [raw]

Subject: [RFC 05/13] tools lib: Add list_last_entry_or_null

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 <[email protected]>
---
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

2022-06-13 13:01:19

by Yang Jihong

[permalink] [raw]

Subject: [RFC 11/13] perf kwork: Add softirq latency support

2022-06-22 15:35:04

by Paul A. Clarke

[permalink] [raw]

Subject: Re: [RFC 00/13] perf: Add perf kwork

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

2022-06-23 01:29:03

by Yang Jihong

[permalink] [raw]

Subject: Re: [RFC 00/13] perf: Add perf kwork

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
> .
>

2022-06-23 14:29:07

by Paul A. Clarke

[permalink] [raw]

Subject: Re: [RFC 00/13] perf: Add perf kwork

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

2022-06-24 01:37:45

by Yang Jihong

[permalink] [raw]

Subject: Re: [RFC 00/13] perf: Add perf kwork

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