* [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2)
@ 2023-06-28 20:01 Namhyung Kim
2023-06-28 20:01 ` [PATCH 1/4] perf lock: Remove stale comments Namhyung Kim
` (4 more replies)
0 siblings, 5 replies; 11+ messages in thread
From: Namhyung Kim @ 2023-06-28 20:01 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, Jiri Olsa
Cc: Ian Rogers, Adrian Hunter, Peter Zijlstra, Ingo Molnar, LKML,
linux-perf-users, Song Liu, Hao Luo
Hello,
This is v2 of perf lock contention CSV output change.
I've added --output option and a test case according to Ian's feedback.
Sometimes we want to process the output by external programs. Let's add
the -x option to specify the field separator like perf stat.
$ sudo ./perf lock con -ab -x, sleep 1
# output: contended, total wait, max wait, avg wait, type, caller
19, 194232, 21415, 10222, spinlock, process_one_work+0x1f0
15, 162748, 23843, 10849, rwsem:R, do_user_addr_fault+0x40e
4, 86740, 23415, 21685, rwlock:R, ep_poll_callback+0x2d
1, 84281, 84281, 84281, mutex, iwl_mvm_async_handlers_wk+0x135
8, 67608, 27404, 8451, spinlock, __queue_work+0x174
3, 58616, 31125, 19538, rwsem:W, do_mprotect_pkey+0xff
3, 52953, 21172, 17651, rwlock:W, do_epoll_wait+0x248
2, 30324, 19704, 15162, rwsem:R, do_madvise+0x3ad
1, 24619, 24619, 24619, spinlock, rcu_core+0xd4
The first line is a comment that shows the output format. Each line is
separated by the given string ("," in this case). The time is printed
in nsec without the unit so that it can be parsed easily.
The code is available at 'perf/lock-con-csv-v2' branch in
git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
Thanks,
Namhyung
Namhyung Kim (4):
perf lock: Remove stale comments
perf lock contention: Add -x option for CSV style output
perf lock contention: Add --output option
perf test: Test perf lock contention CSV output
tools/perf/Documentation/perf-lock.txt | 5 +
tools/perf/builtin-lock.c | 383 ++++++++++++++++------
tools/perf/tests/shell/lock_contention.sh | 36 ++
3 files changed, 328 insertions(+), 96 deletions(-)
--
2.41.0.255.g8b1d071c50-goog
^ permalink raw reply [flat|nested] 11+ messages in thread
* [PATCH 1/4] perf lock: Remove stale comments
2023-06-28 20:01 [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
@ 2023-06-28 20:01 ` Namhyung Kim
2023-06-30 16:03 ` Ian Rogers
2023-06-28 20:01 ` [PATCH 2/4] perf lock contention: Add -x option for CSV style output Namhyung Kim
` (3 subsequent siblings)
4 siblings, 1 reply; 11+ messages in thread
From: Namhyung Kim @ 2023-06-28 20:01 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, Jiri Olsa
Cc: Ian Rogers, Adrian Hunter, Peter Zijlstra, Ingo Molnar, LKML,
linux-perf-users, Song Liu, Hao Luo
The comment was for symbol_conf.sort_by_name which was deleted already.
Let's get rid of the stale comments as well.
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/builtin-lock.c | 2 --
1 file changed, 2 deletions(-)
diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index da36ace66d68..187efb651436 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -1773,7 +1773,6 @@ static int __cmd_report(bool display_info)
return PTR_ERR(session);
}
- /* for lock function check */
symbol_conf.allow_aliases = true;
symbol__init(&session->header.env);
@@ -1902,7 +1901,6 @@ static int __cmd_contention(int argc, const char **argv)
if (con.aggr_mode == LOCK_AGGR_CALLER)
con.save_callstack = true;
- /* for lock function check */
symbol_conf.allow_aliases = true;
symbol__init(&session->header.env);
--
2.41.0.255.g8b1d071c50-goog
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 2/4] perf lock contention: Add -x option for CSV style output
2023-06-28 20:01 [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
2023-06-28 20:01 ` [PATCH 1/4] perf lock: Remove stale comments Namhyung Kim
@ 2023-06-28 20:01 ` Namhyung Kim
2023-06-30 16:02 ` Ian Rogers
2023-06-28 20:01 ` [PATCH 3/4] perf lock contention: Add --output option Namhyung Kim
` (2 subsequent siblings)
4 siblings, 1 reply; 11+ messages in thread
From: Namhyung Kim @ 2023-06-28 20:01 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, Jiri Olsa
Cc: Ian Rogers, Adrian Hunter, Peter Zijlstra, Ingo Molnar, LKML,
linux-perf-users, Song Liu, Hao Luo
Sometimes we want to process the output by external programs. Let's add
the -x option to specify the field separator like perf stat.
$ sudo ./perf lock con -ab -x, sleep 1
# output: contended, total wait, max wait, avg wait, type, caller
19, 194232, 21415, 10222, spinlock, process_one_work+0x1f0
15, 162748, 23843, 10849, rwsem:R, do_user_addr_fault+0x40e
4, 86740, 23415, 21685, rwlock:R, ep_poll_callback+0x2d
1, 84281, 84281, 84281, mutex, iwl_mvm_async_handlers_wk+0x135
8, 67608, 27404, 8451, spinlock, __queue_work+0x174
3, 58616, 31125, 19538, rwsem:W, do_mprotect_pkey+0xff
3, 52953, 21172, 17651, rwlock:W, do_epoll_wait+0x248
2, 30324, 19704, 15162, rwsem:R, do_madvise+0x3ad
1, 24619, 24619, 24619, spinlock, rcu_core+0xd4
The first line is a comment that shows the output format. Each line is
separated by the given string ("," in this case). The time is printed
in nsec without the unit so that it can be parsed easily.
The characters can be used in the output like (":", "+" and ".") are not
allowed for the -x option.
$ ./perf lock con -x:
Cannot use the separator that is already used
Usage: perf lock contention [<options>]
-x, --field-separator <separator>
print result in CSV format with custom separator
The stacktraces are printed in the same line separated by ":". The
header is updated to show the stacktrace. Also the debug output is
added at the end as a comment.
$ sudo ./perf lock con -abv -x, -F wait_total sleep 1
Looking at the vmlinux_path (8 entries long)
symsrc__init: cannot get elf header.
Using /proc/kcore for kernel data
Using /proc/kallsyms for symbols
# output: total wait, type, caller, stacktrace
37134, spinlock, rcu_core+0xd4, 0xffffffff9d0401e4 _raw_spin_lock_irqsave+0x44: 0xffffffff9c738114 rcu_core+0xd4: ...
21213, spinlock, raw_spin_rq_lock_nested+0x1b, 0xffffffff9d0407c0 _raw_spin_lock+0x30: 0xffffffff9c6d9cfb raw_spin_rq_lock_nested+0x1b: ...
20506, rwlock:W, ep_done_scan+0x2d, 0xffffffff9c9bc4dd ep_done_scan+0x2d: 0xffffffff9c9bd5f1 do_epoll_wait+0x6d1: ...
18044, rwlock:R, ep_poll_callback+0x2d, 0xffffffff9d040555 _raw_read_lock_irqsave+0x45: 0xffffffff9c9bc81d ep_poll_callback+0x2d: ...
17890, rwlock:W, do_epoll_wait+0x47b, 0xffffffff9c9bd39b do_epoll_wait+0x47b: 0xffffffff9c9be9ef __x64_sys_epoll_wait+0x6d1: ...
12114, spinlock, futex_wait_queue+0x60, 0xffffffff9d0407c0 _raw_spin_lock+0x30: 0xffffffff9d037cae __schedule+0xbe: ...
# debug: total=7, bad=0, bad_task=0, bad_stack=0, bad_time=0, bad_data=0
Also note that some field (like lock symbols) can be empty.
$ sudo ./perf lock con -abl -x, -E 10 sleep 1
# output: contended, total wait, max wait, avg wait, address, symbol, type
6, 275025, 61764, 45837, ffff9dcc9f7d60d0, , spinlock
18, 87716, 11196, 4873, ffff9dc540059000, , spinlock
2, 6472, 5499, 3236, ffff9dcc7f730e00, rq_lock, spinlock
3, 4429, 2341, 1476, ffff9dcc7f7b0e00, rq_lock, spinlock
3, 3974, 1635, 1324, ffff9dcc7f7f0e00, rq_lock, spinlock
4, 3290, 1326, 822, ffff9dc5f4e2cde0, , rwlock
3, 2894, 1023, 964, ffffffff9e0d7700, rcu_state, spinlock
1, 2567, 2567, 2567, ffff9dcc7f6b0e00, rq_lock, spinlock
4, 1259, 596, 314, ffff9dc69c2adde0, , rwlock
1, 934, 934, 934, ffff9dcc7f670e00, rq_lock, spinlock
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ian Rogers <irogers@google.com>
---
tools/perf/Documentation/perf-lock.txt | 5 +
tools/perf/builtin-lock.c | 303 +++++++++++++++++++------
2 files changed, 241 insertions(+), 67 deletions(-)
diff --git a/tools/perf/Documentation/perf-lock.txt b/tools/perf/Documentation/perf-lock.txt
index 6e5ba3cd2b72..d1efcbe7a470 100644
--- a/tools/perf/Documentation/perf-lock.txt
+++ b/tools/perf/Documentation/perf-lock.txt
@@ -200,6 +200,11 @@ CONTENTION OPTIONS
Note that it matches the substring so 'rq' would match both 'raw_spin_rq_lock'
and 'irq_enter_rcu'.
+-x::
+--field-separator=<SEP>::
+ Show results using a CSV-style output to make it easy to import directly
+ into spreadsheets. Columns are separated by the string specified in SEP.
+
SEE ALSO
--------
diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 187efb651436..98b0c0b1b307 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -225,6 +225,12 @@ static void lock_stat_key_print_time(unsigned long long nsec, int len)
{ 0, NULL },
};
+ /* for CSV output */
+ if (len == 0) {
+ pr_info("%llu", nsec);
+ return;
+ }
+
for (int i = 0; table[i].unit; i++) {
if (nsec < table[i].base)
continue;
@@ -1626,11 +1632,179 @@ static void sort_contention_result(void)
sort_result();
}
-static void print_bpf_events(int total, struct lock_contention_fails *fails)
+static void print_header_stdio(void)
+{
+ struct lock_key *key;
+
+ list_for_each_entry(key, &lock_keys, list)
+ pr_info("%*s ", key->len, key->header);
+
+ switch (aggr_mode) {
+ case LOCK_AGGR_TASK:
+ pr_info(" %10s %s\n\n", "pid",
+ show_lock_owner ? "owner" : "comm");
+ break;
+ case LOCK_AGGR_CALLER:
+ pr_info(" %10s %s\n\n", "type", "caller");
+ break;
+ case LOCK_AGGR_ADDR:
+ pr_info(" %16s %s\n\n", "address", "symbol");
+ break;
+ default:
+ break;
+ }
+}
+
+static void print_header_csv(const char *sep)
+{
+ struct lock_key *key;
+
+ pr_info("# output: ");
+ list_for_each_entry(key, &lock_keys, list)
+ pr_info("%s%s ", key->header, sep);
+
+ switch (aggr_mode) {
+ case LOCK_AGGR_TASK:
+ pr_info("%s%s %s\n", "pid", sep,
+ show_lock_owner ? "owner" : "comm");
+ break;
+ case LOCK_AGGR_CALLER:
+ pr_info("%s%s %s", "type", sep, "caller");
+ if (verbose > 0)
+ pr_info("%s %s", sep, "stacktrace");
+ pr_info("\n");
+ break;
+ case LOCK_AGGR_ADDR:
+ pr_info("%s%s %s%s %s\n", "address", sep, "symbol", sep, "type");
+ break;
+ default:
+ break;
+ }
+}
+
+static void print_header(void)
+{
+ if (!quiet) {
+ if (symbol_conf.field_sep)
+ print_header_csv(symbol_conf.field_sep);
+ else
+ print_header_stdio();
+ }
+}
+
+static void print_lock_stat_stdio(struct lock_contention *con, struct lock_stat *st)
+{
+ struct lock_key *key;
+ struct thread *t;
+ int pid;
+
+ list_for_each_entry(key, &lock_keys, list) {
+ key->print(key, st);
+ pr_info(" ");
+ }
+
+ switch (aggr_mode) {
+ case LOCK_AGGR_CALLER:
+ pr_info(" %10s %s\n", get_type_str(st->flags), st->name);
+ break;
+ case LOCK_AGGR_TASK:
+ pid = st->addr;
+ t = perf_session__findnew(session, pid);
+ pr_info(" %10d %s\n",
+ pid, pid == -1 ? "Unknown" : thread__comm_str(t));
+ break;
+ case LOCK_AGGR_ADDR:
+ pr_info(" %016llx %s (%s)\n", (unsigned long long)st->addr,
+ st->name, get_type_name(st->flags));
+ break;
+ default:
+ break;
+ }
+
+ if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
+ struct map *kmap;
+ struct symbol *sym;
+ char buf[128];
+ u64 ip;
+
+ for (int i = 0; i < max_stack_depth; i++) {
+ if (!st->callstack || !st->callstack[i])
+ break;
+
+ ip = st->callstack[i];
+ sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
+ get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
+ pr_info("\t\t\t%#lx %s\n", (unsigned long)ip, buf);
+ }
+ }
+}
+
+static void print_lock_stat_csv(struct lock_contention *con, struct lock_stat *st,
+ const char *sep)
+{
+ struct lock_key *key;
+ struct thread *t;
+ int pid;
+
+ list_for_each_entry(key, &lock_keys, list) {
+ key->print(key, st);
+ pr_info("%s ", sep);
+ }
+
+ switch (aggr_mode) {
+ case LOCK_AGGR_CALLER:
+ pr_info("%s%s %s", get_type_str(st->flags), sep, st->name);
+ if (verbose <= 0)
+ pr_info("\n");
+ break;
+ case LOCK_AGGR_TASK:
+ pid = st->addr;
+ t = perf_session__findnew(session, pid);
+ pr_info("%d%s %s\n", pid, sep, pid == -1 ? "Unknown" : thread__comm_str(t));
+ break;
+ case LOCK_AGGR_ADDR:
+ pr_info("%llx%s %s%s %s\n", (unsigned long long)st->addr, sep,
+ st->name, sep, get_type_name(st->flags));
+ break;
+ default:
+ break;
+ }
+
+ if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
+ struct map *kmap;
+ struct symbol *sym;
+ char buf[128];
+ u64 ip;
+
+ for (int i = 0; i < max_stack_depth; i++) {
+ if (!st->callstack || !st->callstack[i])
+ break;
+
+ ip = st->callstack[i];
+ sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
+ get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
+ pr_info("%s %#lx %s", i ? ":" : sep, (unsigned long) ip, buf);
+ }
+ pr_info("\n");
+ }
+}
+
+static void print_lock_stat(struct lock_contention *con, struct lock_stat *st)
+{
+ if (symbol_conf.field_sep)
+ print_lock_stat_csv(con, st, symbol_conf.field_sep);
+ else
+ print_lock_stat_stdio(con, st);
+}
+
+static void print_footer_stdio(int total, int bad, struct lock_contention_fails *fails)
{
/* Output for debug, this have to be removed */
int broken = fails->task + fails->stack + fails->time + fails->data;
+ if (!use_bpf)
+ print_bad_events(bad, total);
+
if (quiet || total == 0 || (broken == 0 && verbose <= 0))
return;
@@ -1646,38 +1820,53 @@ static void print_bpf_events(int total, struct lock_contention_fails *fails)
pr_info(" %10s: %d\n", "data", fails->data);
}
+static void print_footer_csv(int total, int bad, struct lock_contention_fails *fails,
+ const char *sep)
+{
+ /* Output for debug, this have to be removed */
+ if (use_bpf)
+ bad = fails->task + fails->stack + fails->time + fails->data;
+
+ if (quiet || total == 0 || (bad == 0 && verbose <= 0))
+ return;
+
+ total += bad;
+ pr_info("# debug: total=%d%s bad=%d", total, sep, bad);
+
+ if (use_bpf) {
+ pr_info("%s bad_%s=%d", sep, "task", fails->task);
+ pr_info("%s bad_%s=%d", sep, "stack", fails->stack);
+ pr_info("%s bad_%s=%d", sep, "time", fails->time);
+ pr_info("%s bad_%s=%d", sep, "data", fails->data);
+ } else {
+ int i;
+ const char *name[4] = { "acquire", "acquired", "contended", "release" };
+
+ for (i = 0; i < BROKEN_MAX; i++)
+ pr_info("%s bad_%s=%d", sep, name[i], bad_hist[i]);
+ }
+ pr_info("\n");
+}
+
+static void print_footer(int total, int bad, struct lock_contention_fails *fails)
+{
+ if (symbol_conf.field_sep)
+ print_footer_csv(total, bad, fails, symbol_conf.field_sep);
+ else
+ print_footer_stdio(total, bad, fails);
+}
+
static void print_contention_result(struct lock_contention *con)
{
struct lock_stat *st;
- struct lock_key *key;
int bad, total, printed;
- if (!quiet) {
- list_for_each_entry(key, &lock_keys, list)
- pr_info("%*s ", key->len, key->header);
-
- switch (aggr_mode) {
- case LOCK_AGGR_TASK:
- pr_info(" %10s %s\n\n", "pid",
- show_lock_owner ? "owner" : "comm");
- break;
- case LOCK_AGGR_CALLER:
- pr_info(" %10s %s\n\n", "type", "caller");
- break;
- case LOCK_AGGR_ADDR:
- pr_info(" %16s %s\n\n", "address", "symbol");
- break;
- default:
- break;
- }
- }
+ if (!quiet)
+ print_header();
bad = total = printed = 0;
while ((st = pop_from_result())) {
- struct thread *t;
- int pid;
-
total += use_bpf ? st->nr_contended : 1;
if (st->broken)
bad++;
@@ -1685,45 +1874,7 @@ static void print_contention_result(struct lock_contention *con)
if (!st->wait_time_total)
continue;
- list_for_each_entry(key, &lock_keys, list) {
- key->print(key, st);
- pr_info(" ");
- }
-
- switch (aggr_mode) {
- case LOCK_AGGR_CALLER:
- pr_info(" %10s %s\n", get_type_str(st->flags), st->name);
- break;
- case LOCK_AGGR_TASK:
- pid = st->addr;
- t = perf_session__findnew(session, pid);
- pr_info(" %10d %s\n",
- pid, pid == -1 ? "Unknown" : thread__comm_str(t));
- break;
- case LOCK_AGGR_ADDR:
- pr_info(" %016llx %s (%s)\n", (unsigned long long)st->addr,
- st->name, get_type_name(st->flags));
- break;
- default:
- break;
- }
-
- if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
- struct map *kmap;
- struct symbol *sym;
- char buf[128];
- u64 ip;
-
- for (int i = 0; i < max_stack_depth; i++) {
- if (!st->callstack || !st->callstack[i])
- break;
-
- ip = st->callstack[i];
- sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
- get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
- pr_info("\t\t\t%#lx %s\n", (unsigned long)ip, buf);
- }
- }
+ print_lock_stat(con, st);
if (++printed >= print_nr_entries)
break;
@@ -1740,10 +1891,7 @@ static void print_contention_result(struct lock_contention *con)
/* some entries are collected but hidden by the callstack filter */
total += con->nr_filtered;
- if (use_bpf)
- print_bpf_events(total, &con->fails);
- else
- print_bad_events(bad, total);
+ print_footer(total, bad, &con->fails);
}
static bool force;
@@ -1847,6 +1995,16 @@ static int check_lock_contention_options(const struct option *options,
return -1;
}
+ if (symbol_conf.field_sep) {
+ if (strstr(symbol_conf.field_sep, ":") || /* part of type flags */
+ strstr(symbol_conf.field_sep, "+") || /* part of caller offset */
+ strstr(symbol_conf.field_sep, ".")) { /* can be in a symbol name */
+ pr_err("Cannot use the separator that is already used\n");
+ parse_options_usage(usage, options, "x", 1);
+ return -1;
+ }
+ }
+
if (show_lock_owner)
show_thread_stats = true;
@@ -1962,6 +2120,15 @@ static int __cmd_contention(int argc, const char **argv)
if (select_key(true))
goto out_delete;
+ if (symbol_conf.field_sep) {
+ int i;
+ struct lock_key *keys = contention_keys;
+
+ /* do not align output in CSV format */
+ for (i = 0; keys[i].name; i++)
+ keys[i].len = 0;
+ }
+
if (use_bpf) {
lock_contention_start();
if (argc)
@@ -2330,6 +2497,8 @@ int cmd_lock(int argc, const char **argv)
OPT_CALLBACK('S', "callstack-filter", NULL, "NAMES",
"Filter specific function in the callstack", parse_call_stack),
OPT_BOOLEAN('o', "lock-owner", &show_lock_owner, "show lock owners instead of waiters"),
+ OPT_STRING_NOEMPTY('x', "field-separator", &symbol_conf.field_sep, "separator",
+ "print result in CSV format with custom separator"),
OPT_PARENT(lock_options)
};
--
2.41.0.255.g8b1d071c50-goog
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 3/4] perf lock contention: Add --output option
2023-06-28 20:01 [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
2023-06-28 20:01 ` [PATCH 1/4] perf lock: Remove stale comments Namhyung Kim
2023-06-28 20:01 ` [PATCH 2/4] perf lock contention: Add -x option for CSV style output Namhyung Kim
@ 2023-06-28 20:01 ` Namhyung Kim
2023-06-30 16:13 ` Ian Rogers
2023-06-28 20:01 ` [PATCH 4/4] perf test: Test perf lock contention CSV output Namhyung Kim
2023-07-02 1:02 ` [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
4 siblings, 1 reply; 11+ messages in thread
From: Namhyung Kim @ 2023-06-28 20:01 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, Jiri Olsa
Cc: Ian Rogers, Adrian Hunter, Peter Zijlstra, Ingo Molnar, LKML,
linux-perf-users, Song Liu, Hao Luo
To avoid formatting failures for example in CSV output due to debug
messages, add --output option to put the result in a file.
Unfortunately the short -o option was taken by the --owner already.
$ sudo ./perf lock con -ab --output lock-out.txt -v sleep 1
Looking at the vmlinux_path (8 entries long)
symsrc__init: cannot get elf header.
Using /proc/kcore for kernel data
Using /proc/kallsyms for symbols
$ head lock-out.txt
contended total wait max wait avg wait type caller
3 76.79 us 26.89 us 25.60 us rwlock:R ep_poll_callback+0x2d
0xffffffff9a23f4b5 _raw_read_lock_irqsave+0x45
0xffffffff99bbd4dd ep_poll_callback+0x2d
0xffffffff999029f3 __wake_up_common+0x73
0xffffffff99902b82 __wake_up_common_lock+0x82
0xffffffff99fa5b1c sock_def_readable+0x3c
0xffffffff9a11521d unix_stream_sendmsg+0x18d
0xffffffff99f9fc9c sock_sendmsg+0x5c
Suggested-by: Ian Rogers <irogers@google.com>
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/Documentation/perf-lock.txt | 3 +
tools/perf/builtin-lock.c | 140 +++++++++++++++----------
2 files changed, 85 insertions(+), 58 deletions(-)
diff --git a/tools/perf/Documentation/perf-lock.txt b/tools/perf/Documentation/perf-lock.txt
index d1efcbe7a470..30eea576721f 100644
--- a/tools/perf/Documentation/perf-lock.txt
+++ b/tools/perf/Documentation/perf-lock.txt
@@ -36,6 +36,9 @@ COMMON OPTIONS
--input=<file>::
Input file name. (default: perf.data unless stdin is a fifo)
+--output=<file>::
+ Output file name for perf lock contention and report.
+
-v::
--verbose::
Be more verbose (show symbol address, etc).
diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 98b0c0b1b307..c15386cb1033 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -27,6 +27,7 @@
#include "util/map.h"
#include "util/util.h"
+#include <stdio.h>
#include <sys/types.h>
#include <sys/prctl.h>
#include <semaphore.h>
@@ -65,6 +66,8 @@ static int max_stack_depth = CONTENTION_STACK_DEPTH;
static int stack_skip = CONTENTION_STACK_SKIP;
static int print_nr_entries = INT_MAX / 2;
static LIST_HEAD(callstack_filters);
+static const char *output_name = NULL;
+static FILE *lock_output;
struct callstack_filter {
struct list_head list;
@@ -227,7 +230,7 @@ static void lock_stat_key_print_time(unsigned long long nsec, int len)
/* for CSV output */
if (len == 0) {
- pr_info("%llu", nsec);
+ fprintf(lock_output, "%llu", nsec);
return;
}
@@ -235,18 +238,18 @@ static void lock_stat_key_print_time(unsigned long long nsec, int len)
if (nsec < table[i].base)
continue;
- pr_info("%*.2f %s", len - 3, nsec / table[i].base, table[i].unit);
+ fprintf(lock_output, "%*.2f %s", len - 3, nsec / table[i].base, table[i].unit);
return;
}
- pr_info("%*llu %s", len - 3, nsec, "ns");
+ fprintf(lock_output, "%*llu %s", len - 3, nsec, "ns");
}
#define PRINT_KEY(member) \
static void lock_stat_key_print_ ## member(struct lock_key *key, \
struct lock_stat *ls) \
{ \
- pr_info("%*llu", key->len, (unsigned long long)ls->member); \
+ fprintf(lock_output, "%*llu", key->len, (unsigned long long)ls->member);\
}
#define PRINT_TIME(member) \
@@ -1335,12 +1338,12 @@ static void print_bad_events(int bad, int total)
if (quiet || total == 0 || (broken == 0 && verbose <= 0))
return;
- pr_info("\n=== output for debug ===\n\n");
- pr_info("bad: %d, total: %d\n", bad, total);
- pr_info("bad rate: %.2f %%\n", (double)bad / (double)total * 100);
- pr_info("histogram of events caused bad sequence\n");
+ fprintf(lock_output, "\n=== output for debug ===\n\n");
+ fprintf(lock_output, "bad: %d, total: %d\n", bad, total);
+ fprintf(lock_output, "bad rate: %.2f %%\n", (double)bad / (double)total * 100);
+ fprintf(lock_output, "histogram of events caused bad sequence\n");
for (i = 0; i < BROKEN_MAX; i++)
- pr_info(" %10s: %d\n", name[i], bad_hist[i]);
+ fprintf(lock_output, " %10s: %d\n", name[i], bad_hist[i]);
}
/* TODO: various way to print, coloring, nano or milli sec */
@@ -1352,10 +1355,10 @@ static void print_result(void)
int bad, total, printed;
if (!quiet) {
- pr_info("%20s ", "Name");
+ fprintf(lock_output, "%20s ", "Name");
list_for_each_entry(key, &lock_keys, list)
- pr_info("%*s ", key->len, key->header);
- pr_info("\n\n");
+ fprintf(lock_output, "%*s ", key->len, key->header);
+ fprintf(lock_output, "\n\n");
}
bad = total = printed = 0;
@@ -1380,7 +1383,7 @@ static void print_result(void)
name = thread__comm_str(t);
}
- pr_info("%20s ", name);
+ fprintf(lock_output, "%20s ", name);
} else {
strncpy(cut_name, st->name, 16);
cut_name[16] = '.';
@@ -1388,14 +1391,14 @@ static void print_result(void)
cut_name[18] = '.';
cut_name[19] = '\0';
/* cut off name for saving output style */
- pr_info("%20s ", cut_name);
+ fprintf(lock_output, "%20s ", cut_name);
}
list_for_each_entry(key, &lock_keys, list) {
key->print(key, st);
- pr_info(" ");
+ fprintf(lock_output, " ");
}
- pr_info("\n");
+ fprintf(lock_output, "\n");
if (++printed >= print_nr_entries)
break;
@@ -1412,13 +1415,13 @@ static void dump_threads(void)
struct rb_node *node;
struct thread *t;
- pr_info("%10s: comm\n", "Thread ID");
+ fprintf(lock_output, "%10s: comm\n", "Thread ID");
node = rb_first(&thread_stats);
while (node) {
st = container_of(node, struct thread_stat, rb);
t = perf_session__findnew(session, st->tid);
- pr_info("%10d: %s\n", st->tid, thread__comm_str(t));
+ fprintf(lock_output, "%10d: %s\n", st->tid, thread__comm_str(t));
node = rb_next(node);
thread__put(t);
}
@@ -1444,7 +1447,7 @@ static void dump_map(void)
unsigned int i;
struct lock_stat *st;
- pr_info("Address of instance: name of class\n");
+ fprintf(lock_output, "Address of instance: name of class\n");
for (i = 0; i < LOCKHASH_SIZE; i++) {
hlist_for_each_entry(st, &lockhash_table[i], hash_entry) {
insert_to_result(st, compare_maps);
@@ -1452,7 +1455,7 @@ static void dump_map(void)
}
while ((st = pop_from_result()))
- pr_info(" %#llx: %s\n", (unsigned long long)st->addr, st->name);
+ fprintf(lock_output, " %#llx: %s\n", (unsigned long long)st->addr, st->name);
}
static int dump_info(void)
@@ -1637,18 +1640,18 @@ static void print_header_stdio(void)
struct lock_key *key;
list_for_each_entry(key, &lock_keys, list)
- pr_info("%*s ", key->len, key->header);
+ fprintf(lock_output, "%*s ", key->len, key->header);
switch (aggr_mode) {
case LOCK_AGGR_TASK:
- pr_info(" %10s %s\n\n", "pid",
+ fprintf(lock_output, " %10s %s\n\n", "pid",
show_lock_owner ? "owner" : "comm");
break;
case LOCK_AGGR_CALLER:
- pr_info(" %10s %s\n\n", "type", "caller");
+ fprintf(lock_output, " %10s %s\n\n", "type", "caller");
break;
case LOCK_AGGR_ADDR:
- pr_info(" %16s %s\n\n", "address", "symbol");
+ fprintf(lock_output, " %16s %s\n\n", "address", "symbol");
break;
default:
break;
@@ -1659,23 +1662,23 @@ static void print_header_csv(const char *sep)
{
struct lock_key *key;
- pr_info("# output: ");
+ fprintf(lock_output, "# output: ");
list_for_each_entry(key, &lock_keys, list)
- pr_info("%s%s ", key->header, sep);
+ fprintf(lock_output, "%s%s ", key->header, sep);
switch (aggr_mode) {
case LOCK_AGGR_TASK:
- pr_info("%s%s %s\n", "pid", sep,
+ fprintf(lock_output, "%s%s %s\n", "pid", sep,
show_lock_owner ? "owner" : "comm");
break;
case LOCK_AGGR_CALLER:
- pr_info("%s%s %s", "type", sep, "caller");
+ fprintf(lock_output, "%s%s %s", "type", sep, "caller");
if (verbose > 0)
- pr_info("%s %s", sep, "stacktrace");
- pr_info("\n");
+ fprintf(lock_output, "%s %s", sep, "stacktrace");
+ fprintf(lock_output, "\n");
break;
case LOCK_AGGR_ADDR:
- pr_info("%s%s %s%s %s\n", "address", sep, "symbol", sep, "type");
+ fprintf(lock_output, "%s%s %s%s %s\n", "address", sep, "symbol", sep, "type");
break;
default:
break;
@@ -1700,21 +1703,21 @@ static void print_lock_stat_stdio(struct lock_contention *con, struct lock_stat
list_for_each_entry(key, &lock_keys, list) {
key->print(key, st);
- pr_info(" ");
+ fprintf(lock_output, " ");
}
switch (aggr_mode) {
case LOCK_AGGR_CALLER:
- pr_info(" %10s %s\n", get_type_str(st->flags), st->name);
+ fprintf(lock_output, " %10s %s\n", get_type_str(st->flags), st->name);
break;
case LOCK_AGGR_TASK:
pid = st->addr;
t = perf_session__findnew(session, pid);
- pr_info(" %10d %s\n",
+ fprintf(lock_output, " %10d %s\n",
pid, pid == -1 ? "Unknown" : thread__comm_str(t));
break;
case LOCK_AGGR_ADDR:
- pr_info(" %016llx %s (%s)\n", (unsigned long long)st->addr,
+ fprintf(lock_output, " %016llx %s (%s)\n", (unsigned long long)st->addr,
st->name, get_type_name(st->flags));
break;
default:
@@ -1734,7 +1737,7 @@ static void print_lock_stat_stdio(struct lock_contention *con, struct lock_stat
ip = st->callstack[i];
sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
- pr_info("\t\t\t%#lx %s\n", (unsigned long)ip, buf);
+ fprintf(lock_output, "\t\t\t%#lx %s\n", (unsigned long)ip, buf);
}
}
}
@@ -1748,22 +1751,23 @@ static void print_lock_stat_csv(struct lock_contention *con, struct lock_stat *s
list_for_each_entry(key, &lock_keys, list) {
key->print(key, st);
- pr_info("%s ", sep);
+ fprintf(lock_output, "%s ", sep);
}
switch (aggr_mode) {
case LOCK_AGGR_CALLER:
- pr_info("%s%s %s", get_type_str(st->flags), sep, st->name);
+ fprintf(lock_output, "%s%s %s", get_type_str(st->flags), sep, st->name);
if (verbose <= 0)
- pr_info("\n");
+ fprintf(lock_output, "\n");
break;
case LOCK_AGGR_TASK:
pid = st->addr;
t = perf_session__findnew(session, pid);
- pr_info("%d%s %s\n", pid, sep, pid == -1 ? "Unknown" : thread__comm_str(t));
+ fprintf(lock_output, "%d%s %s\n", pid, sep,
+ pid == -1 ? "Unknown" : thread__comm_str(t));
break;
case LOCK_AGGR_ADDR:
- pr_info("%llx%s %s%s %s\n", (unsigned long long)st->addr, sep,
+ fprintf(lock_output, "%llx%s %s%s %s\n", (unsigned long long)st->addr, sep,
st->name, sep, get_type_name(st->flags));
break;
default:
@@ -1783,9 +1787,9 @@ static void print_lock_stat_csv(struct lock_contention *con, struct lock_stat *s
ip = st->callstack[i];
sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
- pr_info("%s %#lx %s", i ? ":" : sep, (unsigned long) ip, buf);
+ fprintf(lock_output, "%s %#lx %s", i ? ":" : sep, (unsigned long) ip, buf);
}
- pr_info("\n");
+ fprintf(lock_output, "\n");
}
}
@@ -1809,15 +1813,15 @@ static void print_footer_stdio(int total, int bad, struct lock_contention_fails
return;
total += broken;
- pr_info("\n=== output for debug ===\n\n");
- pr_info("bad: %d, total: %d\n", broken, total);
- pr_info("bad rate: %.2f %%\n", (double)broken / (double)total * 100);
+ fprintf(lock_output, "\n=== output for debug ===\n\n");
+ fprintf(lock_output, "bad: %d, total: %d\n", broken, total);
+ fprintf(lock_output, "bad rate: %.2f %%\n", 100.0 * broken / total);
- pr_info("histogram of failure reasons\n");
- pr_info(" %10s: %d\n", "task", fails->task);
- pr_info(" %10s: %d\n", "stack", fails->stack);
- pr_info(" %10s: %d\n", "time", fails->time);
- pr_info(" %10s: %d\n", "data", fails->data);
+ fprintf(lock_output, "histogram of failure reasons\n");
+ fprintf(lock_output, " %10s: %d\n", "task", fails->task);
+ fprintf(lock_output, " %10s: %d\n", "stack", fails->stack);
+ fprintf(lock_output, " %10s: %d\n", "time", fails->time);
+ fprintf(lock_output, " %10s: %d\n", "data", fails->data);
}
static void print_footer_csv(int total, int bad, struct lock_contention_fails *fails,
@@ -1831,21 +1835,21 @@ static void print_footer_csv(int total, int bad, struct lock_contention_fails *f
return;
total += bad;
- pr_info("# debug: total=%d%s bad=%d", total, sep, bad);
+ fprintf(lock_output, "# debug: total=%d%s bad=%d", total, sep, bad);
if (use_bpf) {
- pr_info("%s bad_%s=%d", sep, "task", fails->task);
- pr_info("%s bad_%s=%d", sep, "stack", fails->stack);
- pr_info("%s bad_%s=%d", sep, "time", fails->time);
- pr_info("%s bad_%s=%d", sep, "data", fails->data);
+ fprintf(lock_output, "%s bad_%s=%d", sep, "task", fails->task);
+ fprintf(lock_output, "%s bad_%s=%d", sep, "stack", fails->stack);
+ fprintf(lock_output, "%s bad_%s=%d", sep, "time", fails->time);
+ fprintf(lock_output, "%s bad_%s=%d", sep, "data", fails->data);
} else {
int i;
const char *name[4] = { "acquire", "acquired", "contended", "release" };
for (i = 0; i < BROKEN_MAX; i++)
- pr_info("%s bad_%s=%d", sep, name[i], bad_hist[i]);
+ fprintf(lock_output, "%s bad_%s=%d", sep, name[i], bad_hist[i]);
}
- pr_info("\n");
+ fprintf(lock_output, "\n");
}
static void print_footer(int total, int bad, struct lock_contention_fails *fails)
@@ -2427,10 +2431,29 @@ static int parse_call_stack(const struct option *opt __maybe_unused, const char
return ret;
}
+static int parse_output(const struct option *opt __maybe_unused, const char *str,
+ int unset __maybe_unused)
+{
+ const char **name = (const char **)opt->value;
+
+ if (str == NULL)
+ return -1;
+
+ lock_output = fopen(str, "w");
+ if (lock_output == NULL) {
+ pr_err("Cannot open %s\n", str);
+ return -1;
+ }
+
+ *name = str;
+ return 0;
+}
+
int cmd_lock(int argc, const char **argv)
{
const struct option lock_options[] = {
OPT_STRING('i', "input", &input_name, "file", "input file name"),
+ OPT_CALLBACK(0, "output", &output_name, "file", "output file name", parse_output),
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_BOOLEAN('f', "force", &force, "don't complain, do it"),
@@ -2530,6 +2553,7 @@ int cmd_lock(int argc, const char **argv)
for (i = 0; i < LOCKHASH_SIZE; i++)
INIT_HLIST_HEAD(lockhash_table + i);
+ lock_output = stderr;
argc = parse_options_subcommand(argc, argv, lock_options, lock_subcommands,
lock_usage, PARSE_OPT_STOP_AT_NON_OPTION);
if (!argc)
--
2.41.0.255.g8b1d071c50-goog
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 4/4] perf test: Test perf lock contention CSV output
2023-06-28 20:01 [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
` (2 preceding siblings ...)
2023-06-28 20:01 ` [PATCH 3/4] perf lock contention: Add --output option Namhyung Kim
@ 2023-06-28 20:01 ` Namhyung Kim
2023-06-30 16:14 ` Ian Rogers
2023-07-02 1:02 ` [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
4 siblings, 1 reply; 11+ messages in thread
From: Namhyung Kim @ 2023-06-28 20:01 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, Jiri Olsa
Cc: Ian Rogers, Adrian Hunter, Peter Zijlstra, Ingo Molnar, LKML,
linux-perf-users, Song Liu, Hao Luo
To verify CSV output, just check the number of separators (",") using
the tr and wc commands like this.
grep -v "^#" ${result} | tr -d -c | wc -c
Now it expects 6 columns (and 5 separators) in the output, but it may
be changed later so count the field in the header first and compare it
to the actual output lines.
$ cat ${result}
# output: contended, total wait, max wait, avg wait, type, caller
1, 28787, 28787, 28787, spinlock, raw_spin_rq_lock_nested+0x1b
The test looks like below now:
$ sudo ./perf test -v contention
86: kernel lock contention analysis test :
--- start ---
test child forked, pid 2705822
Testing perf lock record and perf lock contention
Testing perf lock contention --use-bpf
Testing perf lock record and perf lock contention at the same time
Testing perf lock contention --threads
Testing perf lock contention --lock-addr
Testing perf lock contention --type-filter (w/ spinlock)
Testing perf lock contention --lock-filter (w/ tasklist_lock)
Testing perf lock contention --callstack-filter (w/ unix_stream)
Testing perf lock contention --callstack-filter with task aggregation
Testing perf lock contention CSV output
test child finished with 0
---- end ----
kernel lock contention analysis test: Ok
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
tools/perf/tests/shell/lock_contention.sh | 36 +++++++++++++++++++++++
1 file changed, 36 insertions(+)
diff --git a/tools/perf/tests/shell/lock_contention.sh b/tools/perf/tests/shell/lock_contention.sh
index f2cc187b6186..4a194420416e 100755
--- a/tools/perf/tests/shell/lock_contention.sh
+++ b/tools/perf/tests/shell/lock_contention.sh
@@ -233,6 +233,41 @@ test_aggr_task_stack_filter()
fi
}
+test_csv_output()
+{
+ echo "Testing perf lock contention CSV output"
+ perf lock contention -i ${perfdata} -E 1 -x , --output ${result}
+ # count the number of commas in the header
+ # it should have 5: contended, total-wait, max-wait, avg-wait, type, caller
+ header=$(grep "# output:" ${result} | tr -d -c , | wc -c)
+ if [ "${header}" != "5" ]; then
+ echo "[Fail] Recorded result does not have enough output columns: ${header} != 5"
+ err=1
+ exit
+ fi
+ # count the number of commas in the output
+ output=$(grep -v "^#" ${result} | tr -d -c , | wc -c)
+ if [ "${header}" != "${output}" ]; then
+ echo "[Fail] Recorded result does not match the number of commas: ${header} != ${output}"
+ err=1
+ exit
+ fi
+
+ if ! perf lock con -b true > /dev/null 2>&1 ; then
+ echo "[Skip] No BPF support"
+ return
+ fi
+
+ # the perf lock contention output goes to the stderr
+ perf lock con -a -b -E 1 -x , --output ${result} -- perf bench sched messaging > /dev/null 2>&1
+ output=$(grep -v "^#" ${result} | tr -d -c , | wc -c)
+ if [ "${header}" != "${output}" ]; then
+ echo "[Fail] BPF result does not match the number of commas: ${header} != ${output}"
+ err=1
+ exit
+ fi
+}
+
check
test_record
@@ -244,5 +279,6 @@ test_type_filter
test_lock_filter
test_stack_filter
test_aggr_task_stack_filter
+test_csv_output
exit ${err}
--
2.41.0.255.g8b1d071c50-goog
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: [PATCH 2/4] perf lock contention: Add -x option for CSV style output
2023-06-28 20:01 ` [PATCH 2/4] perf lock contention: Add -x option for CSV style output Namhyung Kim
@ 2023-06-30 16:02 ` Ian Rogers
2023-07-01 17:39 ` Namhyung Kim
0 siblings, 1 reply; 11+ messages in thread
From: Ian Rogers @ 2023-06-30 16:02 UTC (permalink / raw)
To: Namhyung Kim
Cc: Arnaldo Carvalho de Melo, Jiri Olsa, Adrian Hunter,
Peter Zijlstra, Ingo Molnar, LKML, linux-perf-users, Song Liu,
Hao Luo
On Wed, Jun 28, 2023 at 1:01 PM Namhyung Kim <namhyung@kernel.org> wrote:
>
> Sometimes we want to process the output by external programs. Let's add
> the -x option to specify the field separator like perf stat.
>
> $ sudo ./perf lock con -ab -x, sleep 1
> # output: contended, total wait, max wait, avg wait, type, caller
> 19, 194232, 21415, 10222, spinlock, process_one_work+0x1f0
> 15, 162748, 23843, 10849, rwsem:R, do_user_addr_fault+0x40e
> 4, 86740, 23415, 21685, rwlock:R, ep_poll_callback+0x2d
> 1, 84281, 84281, 84281, mutex, iwl_mvm_async_handlers_wk+0x135
> 8, 67608, 27404, 8451, spinlock, __queue_work+0x174
> 3, 58616, 31125, 19538, rwsem:W, do_mprotect_pkey+0xff
> 3, 52953, 21172, 17651, rwlock:W, do_epoll_wait+0x248
> 2, 30324, 19704, 15162, rwsem:R, do_madvise+0x3ad
> 1, 24619, 24619, 24619, spinlock, rcu_core+0xd4
>
> The first line is a comment that shows the output format. Each line is
> separated by the given string ("," in this case). The time is printed
> in nsec without the unit so that it can be parsed easily.
>
> The characters can be used in the output like (":", "+" and ".") are not
> allowed for the -x option.
>
> $ ./perf lock con -x:
> Cannot use the separator that is already used
>
> Usage: perf lock contention [<options>]
>
> -x, --field-separator <separator>
> print result in CSV format with custom separator
>
> The stacktraces are printed in the same line separated by ":". The
> header is updated to show the stacktrace. Also the debug output is
> added at the end as a comment.
>
> $ sudo ./perf lock con -abv -x, -F wait_total sleep 1
> Looking at the vmlinux_path (8 entries long)
> symsrc__init: cannot get elf header.
> Using /proc/kcore for kernel data
> Using /proc/kallsyms for symbols
> # output: total wait, type, caller, stacktrace
> 37134, spinlock, rcu_core+0xd4, 0xffffffff9d0401e4 _raw_spin_lock_irqsave+0x44: 0xffffffff9c738114 rcu_core+0xd4: ...
> 21213, spinlock, raw_spin_rq_lock_nested+0x1b, 0xffffffff9d0407c0 _raw_spin_lock+0x30: 0xffffffff9c6d9cfb raw_spin_rq_lock_nested+0x1b: ...
> 20506, rwlock:W, ep_done_scan+0x2d, 0xffffffff9c9bc4dd ep_done_scan+0x2d: 0xffffffff9c9bd5f1 do_epoll_wait+0x6d1: ...
> 18044, rwlock:R, ep_poll_callback+0x2d, 0xffffffff9d040555 _raw_read_lock_irqsave+0x45: 0xffffffff9c9bc81d ep_poll_callback+0x2d: ...
> 17890, rwlock:W, do_epoll_wait+0x47b, 0xffffffff9c9bd39b do_epoll_wait+0x47b: 0xffffffff9c9be9ef __x64_sys_epoll_wait+0x6d1: ...
> 12114, spinlock, futex_wait_queue+0x60, 0xffffffff9d0407c0 _raw_spin_lock+0x30: 0xffffffff9d037cae __schedule+0xbe: ...
> # debug: total=7, bad=0, bad_task=0, bad_stack=0, bad_time=0, bad_data=0
>
> Also note that some field (like lock symbols) can be empty.
>
> $ sudo ./perf lock con -abl -x, -E 10 sleep 1
> # output: contended, total wait, max wait, avg wait, address, symbol, type
> 6, 275025, 61764, 45837, ffff9dcc9f7d60d0, , spinlock
> 18, 87716, 11196, 4873, ffff9dc540059000, , spinlock
> 2, 6472, 5499, 3236, ffff9dcc7f730e00, rq_lock, spinlock
> 3, 4429, 2341, 1476, ffff9dcc7f7b0e00, rq_lock, spinlock
> 3, 3974, 1635, 1324, ffff9dcc7f7f0e00, rq_lock, spinlock
> 4, 3290, 1326, 822, ffff9dc5f4e2cde0, , rwlock
> 3, 2894, 1023, 964, ffffffff9e0d7700, rcu_state, spinlock
> 1, 2567, 2567, 2567, ffff9dcc7f6b0e00, rq_lock, spinlock
> 4, 1259, 596, 314, ffff9dc69c2adde0, , rwlock
> 1, 934, 934, 934, ffff9dcc7f670e00, rq_lock, spinlock
>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> Acked-by: Ian Rogers <irogers@google.com>
> ---
> tools/perf/Documentation/perf-lock.txt | 5 +
> tools/perf/builtin-lock.c | 303 +++++++++++++++++++------
> 2 files changed, 241 insertions(+), 67 deletions(-)
>
> diff --git a/tools/perf/Documentation/perf-lock.txt b/tools/perf/Documentation/perf-lock.txt
> index 6e5ba3cd2b72..d1efcbe7a470 100644
> --- a/tools/perf/Documentation/perf-lock.txt
> +++ b/tools/perf/Documentation/perf-lock.txt
> @@ -200,6 +200,11 @@ CONTENTION OPTIONS
> Note that it matches the substring so 'rq' would match both 'raw_spin_rq_lock'
> and 'irq_enter_rcu'.
>
> +-x::
> +--field-separator=<SEP>::
> + Show results using a CSV-style output to make it easy to import directly
> + into spreadsheets. Columns are separated by the string specified in SEP.
> +
>
> SEE ALSO
> --------
> diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
> index 187efb651436..98b0c0b1b307 100644
> --- a/tools/perf/builtin-lock.c
> +++ b/tools/perf/builtin-lock.c
> @@ -225,6 +225,12 @@ static void lock_stat_key_print_time(unsigned long long nsec, int len)
> { 0, NULL },
> };
>
> + /* for CSV output */
> + if (len == 0) {
> + pr_info("%llu", nsec);
Perhaps for the next patch set. Picking on the first print, I think it
makes sense with CSV output that there should be a file option.
Otherwise debug messages pr_* are going to end up breaking the CSV
format.
> + return;
> + }
> +
> for (int i = 0; table[i].unit; i++) {
> if (nsec < table[i].base)
> continue;
> @@ -1626,11 +1632,179 @@ static void sort_contention_result(void)
> sort_result();
> }
>
> -static void print_bpf_events(int total, struct lock_contention_fails *fails)
> +static void print_header_stdio(void)
> +{
> + struct lock_key *key;
> +
> + list_for_each_entry(key, &lock_keys, list)
> + pr_info("%*s ", key->len, key->header);
> +
> + switch (aggr_mode) {
> + case LOCK_AGGR_TASK:
> + pr_info(" %10s %s\n\n", "pid",
> + show_lock_owner ? "owner" : "comm");
> + break;
> + case LOCK_AGGR_CALLER:
> + pr_info(" %10s %s\n\n", "type", "caller");
> + break;
> + case LOCK_AGGR_ADDR:
> + pr_info(" %16s %s\n\n", "address", "symbol");
> + break;
> + default:
> + break;
> + }
> +}
> +
> +static void print_header_csv(const char *sep)
> +{
> + struct lock_key *key;
> +
> + pr_info("# output: ");
> + list_for_each_entry(key, &lock_keys, list)
> + pr_info("%s%s ", key->header, sep);
> +
> + switch (aggr_mode) {
> + case LOCK_AGGR_TASK:
> + pr_info("%s%s %s\n", "pid", sep,
> + show_lock_owner ? "owner" : "comm");
So a thought here, I would kind of like all the CSV functions
together. It is key for CSV output that the columns line up, the
layout here means you need to jump through the code to determine this.
I'd also prefer that the '\n' weren't output until after the switch.
The purpose being to show that the line is created, at the end of the
function when the line is done we move to the next line and that is
common for all aggregation modes.
> + break;
> + case LOCK_AGGR_CALLER:
> + pr_info("%s%s %s", "type", sep, "caller");
> + if (verbose > 0)
> + pr_info("%s %s", sep, "stacktrace");
> + pr_info("\n");
> + break;
> + case LOCK_AGGR_ADDR:
> + pr_info("%s%s %s%s %s\n", "address", sep, "symbol", sep, "type");
> + break;
> + default:
> + break;
> + }
> +}
> +
> +static void print_header(void)
> +{
> + if (!quiet) {
> + if (symbol_conf.field_sep)
> + print_header_csv(symbol_conf.field_sep);
> + else
> + print_header_stdio();
Suggestion: could we switch to the callback style here. So there is
some state and a set of callback routines - the usual fake OO pattern.
I could imagine the state for CSV being the current column number,
that way there could be asserts on the layout.
Thanks,
Ian
> + }
> +}
> +
> +static void print_lock_stat_stdio(struct lock_contention *con, struct lock_stat *st)
> +{
> + struct lock_key *key;
> + struct thread *t;
> + int pid;
> +
> + list_for_each_entry(key, &lock_keys, list) {
> + key->print(key, st);
> + pr_info(" ");
> + }
> +
> + switch (aggr_mode) {
> + case LOCK_AGGR_CALLER:
> + pr_info(" %10s %s\n", get_type_str(st->flags), st->name);
> + break;
> + case LOCK_AGGR_TASK:
> + pid = st->addr;
> + t = perf_session__findnew(session, pid);
> + pr_info(" %10d %s\n",
> + pid, pid == -1 ? "Unknown" : thread__comm_str(t));
> + break;
> + case LOCK_AGGR_ADDR:
> + pr_info(" %016llx %s (%s)\n", (unsigned long long)st->addr,
> + st->name, get_type_name(st->flags));
> + break;
> + default:
> + break;
> + }
> +
> + if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
> + struct map *kmap;
> + struct symbol *sym;
> + char buf[128];
> + u64 ip;
> +
> + for (int i = 0; i < max_stack_depth; i++) {
> + if (!st->callstack || !st->callstack[i])
> + break;
> +
> + ip = st->callstack[i];
> + sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
> + get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
> + pr_info("\t\t\t%#lx %s\n", (unsigned long)ip, buf);
> + }
> + }
> +}
> +
> +static void print_lock_stat_csv(struct lock_contention *con, struct lock_stat *st,
> + const char *sep)
> +{
> + struct lock_key *key;
> + struct thread *t;
> + int pid;
> +
> + list_for_each_entry(key, &lock_keys, list) {
> + key->print(key, st);
> + pr_info("%s ", sep);
> + }
> +
> + switch (aggr_mode) {
> + case LOCK_AGGR_CALLER:
> + pr_info("%s%s %s", get_type_str(st->flags), sep, st->name);
> + if (verbose <= 0)
> + pr_info("\n");
> + break;
> + case LOCK_AGGR_TASK:
> + pid = st->addr;
> + t = perf_session__findnew(session, pid);
> + pr_info("%d%s %s\n", pid, sep, pid == -1 ? "Unknown" : thread__comm_str(t));
> + break;
> + case LOCK_AGGR_ADDR:
> + pr_info("%llx%s %s%s %s\n", (unsigned long long)st->addr, sep,
> + st->name, sep, get_type_name(st->flags));
> + break;
> + default:
> + break;
> + }
> +
> + if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
> + struct map *kmap;
> + struct symbol *sym;
> + char buf[128];
> + u64 ip;
> +
> + for (int i = 0; i < max_stack_depth; i++) {
> + if (!st->callstack || !st->callstack[i])
> + break;
> +
> + ip = st->callstack[i];
> + sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
> + get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
> + pr_info("%s %#lx %s", i ? ":" : sep, (unsigned long) ip, buf);
> + }
> + pr_info("\n");
> + }
> +}
> +
> +static void print_lock_stat(struct lock_contention *con, struct lock_stat *st)
> +{
> + if (symbol_conf.field_sep)
> + print_lock_stat_csv(con, st, symbol_conf.field_sep);
> + else
> + print_lock_stat_stdio(con, st);
> +}
> +
> +static void print_footer_stdio(int total, int bad, struct lock_contention_fails *fails)
> {
> /* Output for debug, this have to be removed */
> int broken = fails->task + fails->stack + fails->time + fails->data;
>
> + if (!use_bpf)
> + print_bad_events(bad, total);
> +
> if (quiet || total == 0 || (broken == 0 && verbose <= 0))
> return;
>
> @@ -1646,38 +1820,53 @@ static void print_bpf_events(int total, struct lock_contention_fails *fails)
> pr_info(" %10s: %d\n", "data", fails->data);
> }
>
> +static void print_footer_csv(int total, int bad, struct lock_contention_fails *fails,
> + const char *sep)
> +{
> + /* Output for debug, this have to be removed */
> + if (use_bpf)
> + bad = fails->task + fails->stack + fails->time + fails->data;
> +
> + if (quiet || total == 0 || (bad == 0 && verbose <= 0))
> + return;
> +
> + total += bad;
> + pr_info("# debug: total=%d%s bad=%d", total, sep, bad);
> +
> + if (use_bpf) {
> + pr_info("%s bad_%s=%d", sep, "task", fails->task);
> + pr_info("%s bad_%s=%d", sep, "stack", fails->stack);
> + pr_info("%s bad_%s=%d", sep, "time", fails->time);
> + pr_info("%s bad_%s=%d", sep, "data", fails->data);
> + } else {
> + int i;
> + const char *name[4] = { "acquire", "acquired", "contended", "release" };
> +
> + for (i = 0; i < BROKEN_MAX; i++)
> + pr_info("%s bad_%s=%d", sep, name[i], bad_hist[i]);
> + }
> + pr_info("\n");
> +}
> +
> +static void print_footer(int total, int bad, struct lock_contention_fails *fails)
> +{
> + if (symbol_conf.field_sep)
> + print_footer_csv(total, bad, fails, symbol_conf.field_sep);
> + else
> + print_footer_stdio(total, bad, fails);
> +}
> +
> static void print_contention_result(struct lock_contention *con)
> {
> struct lock_stat *st;
> - struct lock_key *key;
> int bad, total, printed;
>
> - if (!quiet) {
> - list_for_each_entry(key, &lock_keys, list)
> - pr_info("%*s ", key->len, key->header);
> -
> - switch (aggr_mode) {
> - case LOCK_AGGR_TASK:
> - pr_info(" %10s %s\n\n", "pid",
> - show_lock_owner ? "owner" : "comm");
> - break;
> - case LOCK_AGGR_CALLER:
> - pr_info(" %10s %s\n\n", "type", "caller");
> - break;
> - case LOCK_AGGR_ADDR:
> - pr_info(" %16s %s\n\n", "address", "symbol");
> - break;
> - default:
> - break;
> - }
> - }
> + if (!quiet)
> + print_header();
>
> bad = total = printed = 0;
>
> while ((st = pop_from_result())) {
> - struct thread *t;
> - int pid;
> -
> total += use_bpf ? st->nr_contended : 1;
> if (st->broken)
> bad++;
> @@ -1685,45 +1874,7 @@ static void print_contention_result(struct lock_contention *con)
> if (!st->wait_time_total)
> continue;
>
> - list_for_each_entry(key, &lock_keys, list) {
> - key->print(key, st);
> - pr_info(" ");
> - }
> -
> - switch (aggr_mode) {
> - case LOCK_AGGR_CALLER:
> - pr_info(" %10s %s\n", get_type_str(st->flags), st->name);
> - break;
> - case LOCK_AGGR_TASK:
> - pid = st->addr;
> - t = perf_session__findnew(session, pid);
> - pr_info(" %10d %s\n",
> - pid, pid == -1 ? "Unknown" : thread__comm_str(t));
> - break;
> - case LOCK_AGGR_ADDR:
> - pr_info(" %016llx %s (%s)\n", (unsigned long long)st->addr,
> - st->name, get_type_name(st->flags));
> - break;
> - default:
> - break;
> - }
> -
> - if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
> - struct map *kmap;
> - struct symbol *sym;
> - char buf[128];
> - u64 ip;
> -
> - for (int i = 0; i < max_stack_depth; i++) {
> - if (!st->callstack || !st->callstack[i])
> - break;
> -
> - ip = st->callstack[i];
> - sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
> - get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
> - pr_info("\t\t\t%#lx %s\n", (unsigned long)ip, buf);
> - }
> - }
> + print_lock_stat(con, st);
>
> if (++printed >= print_nr_entries)
> break;
> @@ -1740,10 +1891,7 @@ static void print_contention_result(struct lock_contention *con)
> /* some entries are collected but hidden by the callstack filter */
> total += con->nr_filtered;
>
> - if (use_bpf)
> - print_bpf_events(total, &con->fails);
> - else
> - print_bad_events(bad, total);
> + print_footer(total, bad, &con->fails);
> }
>
> static bool force;
> @@ -1847,6 +1995,16 @@ static int check_lock_contention_options(const struct option *options,
> return -1;
> }
>
> + if (symbol_conf.field_sep) {
> + if (strstr(symbol_conf.field_sep, ":") || /* part of type flags */
> + strstr(symbol_conf.field_sep, "+") || /* part of caller offset */
> + strstr(symbol_conf.field_sep, ".")) { /* can be in a symbol name */
> + pr_err("Cannot use the separator that is already used\n");
> + parse_options_usage(usage, options, "x", 1);
> + return -1;
> + }
> + }
> +
> if (show_lock_owner)
> show_thread_stats = true;
>
> @@ -1962,6 +2120,15 @@ static int __cmd_contention(int argc, const char **argv)
> if (select_key(true))
> goto out_delete;
>
> + if (symbol_conf.field_sep) {
> + int i;
> + struct lock_key *keys = contention_keys;
> +
> + /* do not align output in CSV format */
> + for (i = 0; keys[i].name; i++)
> + keys[i].len = 0;
> + }
> +
> if (use_bpf) {
> lock_contention_start();
> if (argc)
> @@ -2330,6 +2497,8 @@ int cmd_lock(int argc, const char **argv)
> OPT_CALLBACK('S', "callstack-filter", NULL, "NAMES",
> "Filter specific function in the callstack", parse_call_stack),
> OPT_BOOLEAN('o', "lock-owner", &show_lock_owner, "show lock owners instead of waiters"),
> + OPT_STRING_NOEMPTY('x', "field-separator", &symbol_conf.field_sep, "separator",
> + "print result in CSV format with custom separator"),
> OPT_PARENT(lock_options)
> };
>
> --
> 2.41.0.255.g8b1d071c50-goog
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 1/4] perf lock: Remove stale comments
2023-06-28 20:01 ` [PATCH 1/4] perf lock: Remove stale comments Namhyung Kim
@ 2023-06-30 16:03 ` Ian Rogers
0 siblings, 0 replies; 11+ messages in thread
From: Ian Rogers @ 2023-06-30 16:03 UTC (permalink / raw)
To: Namhyung Kim
Cc: Arnaldo Carvalho de Melo, Jiri Olsa, Adrian Hunter,
Peter Zijlstra, Ingo Molnar, LKML, linux-perf-users, Song Liu,
Hao Luo
On Wed, Jun 28, 2023 at 1:01 PM Namhyung Kim <namhyung@kernel.org> wrote:
>
> The comment was for symbol_conf.sort_by_name which was deleted already.
> Let's get rid of the stale comments as well.
>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ian Rogers <irogers@google.com>
Thanks,
Ian
> ---
> tools/perf/builtin-lock.c | 2 --
> 1 file changed, 2 deletions(-)
>
> diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
> index da36ace66d68..187efb651436 100644
> --- a/tools/perf/builtin-lock.c
> +++ b/tools/perf/builtin-lock.c
> @@ -1773,7 +1773,6 @@ static int __cmd_report(bool display_info)
> return PTR_ERR(session);
> }
>
> - /* for lock function check */
> symbol_conf.allow_aliases = true;
> symbol__init(&session->header.env);
>
> @@ -1902,7 +1901,6 @@ static int __cmd_contention(int argc, const char **argv)
> if (con.aggr_mode == LOCK_AGGR_CALLER)
> con.save_callstack = true;
>
> - /* for lock function check */
> symbol_conf.allow_aliases = true;
> symbol__init(&session->header.env);
>
> --
> 2.41.0.255.g8b1d071c50-goog
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 3/4] perf lock contention: Add --output option
2023-06-28 20:01 ` [PATCH 3/4] perf lock contention: Add --output option Namhyung Kim
@ 2023-06-30 16:13 ` Ian Rogers
0 siblings, 0 replies; 11+ messages in thread
From: Ian Rogers @ 2023-06-30 16:13 UTC (permalink / raw)
To: Namhyung Kim
Cc: Arnaldo Carvalho de Melo, Jiri Olsa, Adrian Hunter,
Peter Zijlstra, Ingo Molnar, LKML, linux-perf-users, Song Liu,
Hao Luo
On Wed, Jun 28, 2023 at 1:01 PM Namhyung Kim <namhyung@kernel.org> wrote:
>
> To avoid formatting failures for example in CSV output due to debug
> messages, add --output option to put the result in a file.
> Unfortunately the short -o option was taken by the --owner already.
>
> $ sudo ./perf lock con -ab --output lock-out.txt -v sleep 1
> Looking at the vmlinux_path (8 entries long)
> symsrc__init: cannot get elf header.
> Using /proc/kcore for kernel data
> Using /proc/kallsyms for symbols
>
> $ head lock-out.txt
> contended total wait max wait avg wait type caller
>
> 3 76.79 us 26.89 us 25.60 us rwlock:R ep_poll_callback+0x2d
> 0xffffffff9a23f4b5 _raw_read_lock_irqsave+0x45
> 0xffffffff99bbd4dd ep_poll_callback+0x2d
> 0xffffffff999029f3 __wake_up_common+0x73
> 0xffffffff99902b82 __wake_up_common_lock+0x82
> 0xffffffff99fa5b1c sock_def_readable+0x3c
> 0xffffffff9a11521d unix_stream_sendmsg+0x18d
> 0xffffffff99f9fc9c sock_sendmsg+0x5c
>
> Suggested-by: Ian Rogers <irogers@google.com>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Making some of my previous suggestions mute :-)
Acked-by: Ian Rogers <irogers@google.com>
Thanks,
Ian
> ---
> tools/perf/Documentation/perf-lock.txt | 3 +
> tools/perf/builtin-lock.c | 140 +++++++++++++++----------
> 2 files changed, 85 insertions(+), 58 deletions(-)
>
> diff --git a/tools/perf/Documentation/perf-lock.txt b/tools/perf/Documentation/perf-lock.txt
> index d1efcbe7a470..30eea576721f 100644
> --- a/tools/perf/Documentation/perf-lock.txt
> +++ b/tools/perf/Documentation/perf-lock.txt
> @@ -36,6 +36,9 @@ COMMON OPTIONS
> --input=<file>::
> Input file name. (default: perf.data unless stdin is a fifo)
>
> +--output=<file>::
> + Output file name for perf lock contention and report.
> +
> -v::
> --verbose::
> Be more verbose (show symbol address, etc).
> diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
> index 98b0c0b1b307..c15386cb1033 100644
> --- a/tools/perf/builtin-lock.c
> +++ b/tools/perf/builtin-lock.c
> @@ -27,6 +27,7 @@
> #include "util/map.h"
> #include "util/util.h"
>
> +#include <stdio.h>
> #include <sys/types.h>
> #include <sys/prctl.h>
> #include <semaphore.h>
> @@ -65,6 +66,8 @@ static int max_stack_depth = CONTENTION_STACK_DEPTH;
> static int stack_skip = CONTENTION_STACK_SKIP;
> static int print_nr_entries = INT_MAX / 2;
> static LIST_HEAD(callstack_filters);
> +static const char *output_name = NULL;
> +static FILE *lock_output;
>
> struct callstack_filter {
> struct list_head list;
> @@ -227,7 +230,7 @@ static void lock_stat_key_print_time(unsigned long long nsec, int len)
>
> /* for CSV output */
> if (len == 0) {
> - pr_info("%llu", nsec);
> + fprintf(lock_output, "%llu", nsec);
> return;
> }
>
> @@ -235,18 +238,18 @@ static void lock_stat_key_print_time(unsigned long long nsec, int len)
> if (nsec < table[i].base)
> continue;
>
> - pr_info("%*.2f %s", len - 3, nsec / table[i].base, table[i].unit);
> + fprintf(lock_output, "%*.2f %s", len - 3, nsec / table[i].base, table[i].unit);
> return;
> }
>
> - pr_info("%*llu %s", len - 3, nsec, "ns");
> + fprintf(lock_output, "%*llu %s", len - 3, nsec, "ns");
> }
>
> #define PRINT_KEY(member) \
> static void lock_stat_key_print_ ## member(struct lock_key *key, \
> struct lock_stat *ls) \
> { \
> - pr_info("%*llu", key->len, (unsigned long long)ls->member); \
> + fprintf(lock_output, "%*llu", key->len, (unsigned long long)ls->member);\
> }
>
> #define PRINT_TIME(member) \
> @@ -1335,12 +1338,12 @@ static void print_bad_events(int bad, int total)
> if (quiet || total == 0 || (broken == 0 && verbose <= 0))
> return;
>
> - pr_info("\n=== output for debug ===\n\n");
> - pr_info("bad: %d, total: %d\n", bad, total);
> - pr_info("bad rate: %.2f %%\n", (double)bad / (double)total * 100);
> - pr_info("histogram of events caused bad sequence\n");
> + fprintf(lock_output, "\n=== output for debug ===\n\n");
> + fprintf(lock_output, "bad: %d, total: %d\n", bad, total);
> + fprintf(lock_output, "bad rate: %.2f %%\n", (double)bad / (double)total * 100);
> + fprintf(lock_output, "histogram of events caused bad sequence\n");
> for (i = 0; i < BROKEN_MAX; i++)
> - pr_info(" %10s: %d\n", name[i], bad_hist[i]);
> + fprintf(lock_output, " %10s: %d\n", name[i], bad_hist[i]);
> }
>
> /* TODO: various way to print, coloring, nano or milli sec */
> @@ -1352,10 +1355,10 @@ static void print_result(void)
> int bad, total, printed;
>
> if (!quiet) {
> - pr_info("%20s ", "Name");
> + fprintf(lock_output, "%20s ", "Name");
> list_for_each_entry(key, &lock_keys, list)
> - pr_info("%*s ", key->len, key->header);
> - pr_info("\n\n");
> + fprintf(lock_output, "%*s ", key->len, key->header);
> + fprintf(lock_output, "\n\n");
> }
>
> bad = total = printed = 0;
> @@ -1380,7 +1383,7 @@ static void print_result(void)
> name = thread__comm_str(t);
> }
>
> - pr_info("%20s ", name);
> + fprintf(lock_output, "%20s ", name);
> } else {
> strncpy(cut_name, st->name, 16);
> cut_name[16] = '.';
> @@ -1388,14 +1391,14 @@ static void print_result(void)
> cut_name[18] = '.';
> cut_name[19] = '\0';
> /* cut off name for saving output style */
> - pr_info("%20s ", cut_name);
> + fprintf(lock_output, "%20s ", cut_name);
> }
>
> list_for_each_entry(key, &lock_keys, list) {
> key->print(key, st);
> - pr_info(" ");
> + fprintf(lock_output, " ");
> }
> - pr_info("\n");
> + fprintf(lock_output, "\n");
>
> if (++printed >= print_nr_entries)
> break;
> @@ -1412,13 +1415,13 @@ static void dump_threads(void)
> struct rb_node *node;
> struct thread *t;
>
> - pr_info("%10s: comm\n", "Thread ID");
> + fprintf(lock_output, "%10s: comm\n", "Thread ID");
>
> node = rb_first(&thread_stats);
> while (node) {
> st = container_of(node, struct thread_stat, rb);
> t = perf_session__findnew(session, st->tid);
> - pr_info("%10d: %s\n", st->tid, thread__comm_str(t));
> + fprintf(lock_output, "%10d: %s\n", st->tid, thread__comm_str(t));
> node = rb_next(node);
> thread__put(t);
> }
> @@ -1444,7 +1447,7 @@ static void dump_map(void)
> unsigned int i;
> struct lock_stat *st;
>
> - pr_info("Address of instance: name of class\n");
> + fprintf(lock_output, "Address of instance: name of class\n");
> for (i = 0; i < LOCKHASH_SIZE; i++) {
> hlist_for_each_entry(st, &lockhash_table[i], hash_entry) {
> insert_to_result(st, compare_maps);
> @@ -1452,7 +1455,7 @@ static void dump_map(void)
> }
>
> while ((st = pop_from_result()))
> - pr_info(" %#llx: %s\n", (unsigned long long)st->addr, st->name);
> + fprintf(lock_output, " %#llx: %s\n", (unsigned long long)st->addr, st->name);
> }
>
> static int dump_info(void)
> @@ -1637,18 +1640,18 @@ static void print_header_stdio(void)
> struct lock_key *key;
>
> list_for_each_entry(key, &lock_keys, list)
> - pr_info("%*s ", key->len, key->header);
> + fprintf(lock_output, "%*s ", key->len, key->header);
>
> switch (aggr_mode) {
> case LOCK_AGGR_TASK:
> - pr_info(" %10s %s\n\n", "pid",
> + fprintf(lock_output, " %10s %s\n\n", "pid",
> show_lock_owner ? "owner" : "comm");
> break;
> case LOCK_AGGR_CALLER:
> - pr_info(" %10s %s\n\n", "type", "caller");
> + fprintf(lock_output, " %10s %s\n\n", "type", "caller");
> break;
> case LOCK_AGGR_ADDR:
> - pr_info(" %16s %s\n\n", "address", "symbol");
> + fprintf(lock_output, " %16s %s\n\n", "address", "symbol");
> break;
> default:
> break;
> @@ -1659,23 +1662,23 @@ static void print_header_csv(const char *sep)
> {
> struct lock_key *key;
>
> - pr_info("# output: ");
> + fprintf(lock_output, "# output: ");
> list_for_each_entry(key, &lock_keys, list)
> - pr_info("%s%s ", key->header, sep);
> + fprintf(lock_output, "%s%s ", key->header, sep);
>
> switch (aggr_mode) {
> case LOCK_AGGR_TASK:
> - pr_info("%s%s %s\n", "pid", sep,
> + fprintf(lock_output, "%s%s %s\n", "pid", sep,
> show_lock_owner ? "owner" : "comm");
> break;
> case LOCK_AGGR_CALLER:
> - pr_info("%s%s %s", "type", sep, "caller");
> + fprintf(lock_output, "%s%s %s", "type", sep, "caller");
> if (verbose > 0)
> - pr_info("%s %s", sep, "stacktrace");
> - pr_info("\n");
> + fprintf(lock_output, "%s %s", sep, "stacktrace");
> + fprintf(lock_output, "\n");
> break;
> case LOCK_AGGR_ADDR:
> - pr_info("%s%s %s%s %s\n", "address", sep, "symbol", sep, "type");
> + fprintf(lock_output, "%s%s %s%s %s\n", "address", sep, "symbol", sep, "type");
> break;
> default:
> break;
> @@ -1700,21 +1703,21 @@ static void print_lock_stat_stdio(struct lock_contention *con, struct lock_stat
>
> list_for_each_entry(key, &lock_keys, list) {
> key->print(key, st);
> - pr_info(" ");
> + fprintf(lock_output, " ");
> }
>
> switch (aggr_mode) {
> case LOCK_AGGR_CALLER:
> - pr_info(" %10s %s\n", get_type_str(st->flags), st->name);
> + fprintf(lock_output, " %10s %s\n", get_type_str(st->flags), st->name);
> break;
> case LOCK_AGGR_TASK:
> pid = st->addr;
> t = perf_session__findnew(session, pid);
> - pr_info(" %10d %s\n",
> + fprintf(lock_output, " %10d %s\n",
> pid, pid == -1 ? "Unknown" : thread__comm_str(t));
> break;
> case LOCK_AGGR_ADDR:
> - pr_info(" %016llx %s (%s)\n", (unsigned long long)st->addr,
> + fprintf(lock_output, " %016llx %s (%s)\n", (unsigned long long)st->addr,
> st->name, get_type_name(st->flags));
> break;
> default:
> @@ -1734,7 +1737,7 @@ static void print_lock_stat_stdio(struct lock_contention *con, struct lock_stat
> ip = st->callstack[i];
> sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
> get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
> - pr_info("\t\t\t%#lx %s\n", (unsigned long)ip, buf);
> + fprintf(lock_output, "\t\t\t%#lx %s\n", (unsigned long)ip, buf);
> }
> }
> }
> @@ -1748,22 +1751,23 @@ static void print_lock_stat_csv(struct lock_contention *con, struct lock_stat *s
>
> list_for_each_entry(key, &lock_keys, list) {
> key->print(key, st);
> - pr_info("%s ", sep);
> + fprintf(lock_output, "%s ", sep);
> }
>
> switch (aggr_mode) {
> case LOCK_AGGR_CALLER:
> - pr_info("%s%s %s", get_type_str(st->flags), sep, st->name);
> + fprintf(lock_output, "%s%s %s", get_type_str(st->flags), sep, st->name);
> if (verbose <= 0)
> - pr_info("\n");
> + fprintf(lock_output, "\n");
> break;
> case LOCK_AGGR_TASK:
> pid = st->addr;
> t = perf_session__findnew(session, pid);
> - pr_info("%d%s %s\n", pid, sep, pid == -1 ? "Unknown" : thread__comm_str(t));
> + fprintf(lock_output, "%d%s %s\n", pid, sep,
> + pid == -1 ? "Unknown" : thread__comm_str(t));
> break;
> case LOCK_AGGR_ADDR:
> - pr_info("%llx%s %s%s %s\n", (unsigned long long)st->addr, sep,
> + fprintf(lock_output, "%llx%s %s%s %s\n", (unsigned long long)st->addr, sep,
> st->name, sep, get_type_name(st->flags));
> break;
> default:
> @@ -1783,9 +1787,9 @@ static void print_lock_stat_csv(struct lock_contention *con, struct lock_stat *s
> ip = st->callstack[i];
> sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
> get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
> - pr_info("%s %#lx %s", i ? ":" : sep, (unsigned long) ip, buf);
> + fprintf(lock_output, "%s %#lx %s", i ? ":" : sep, (unsigned long) ip, buf);
> }
> - pr_info("\n");
> + fprintf(lock_output, "\n");
> }
> }
>
> @@ -1809,15 +1813,15 @@ static void print_footer_stdio(int total, int bad, struct lock_contention_fails
> return;
>
> total += broken;
> - pr_info("\n=== output for debug ===\n\n");
> - pr_info("bad: %d, total: %d\n", broken, total);
> - pr_info("bad rate: %.2f %%\n", (double)broken / (double)total * 100);
> + fprintf(lock_output, "\n=== output for debug ===\n\n");
> + fprintf(lock_output, "bad: %d, total: %d\n", broken, total);
> + fprintf(lock_output, "bad rate: %.2f %%\n", 100.0 * broken / total);
>
> - pr_info("histogram of failure reasons\n");
> - pr_info(" %10s: %d\n", "task", fails->task);
> - pr_info(" %10s: %d\n", "stack", fails->stack);
> - pr_info(" %10s: %d\n", "time", fails->time);
> - pr_info(" %10s: %d\n", "data", fails->data);
> + fprintf(lock_output, "histogram of failure reasons\n");
> + fprintf(lock_output, " %10s: %d\n", "task", fails->task);
> + fprintf(lock_output, " %10s: %d\n", "stack", fails->stack);
> + fprintf(lock_output, " %10s: %d\n", "time", fails->time);
> + fprintf(lock_output, " %10s: %d\n", "data", fails->data);
> }
>
> static void print_footer_csv(int total, int bad, struct lock_contention_fails *fails,
> @@ -1831,21 +1835,21 @@ static void print_footer_csv(int total, int bad, struct lock_contention_fails *f
> return;
>
> total += bad;
> - pr_info("# debug: total=%d%s bad=%d", total, sep, bad);
> + fprintf(lock_output, "# debug: total=%d%s bad=%d", total, sep, bad);
>
> if (use_bpf) {
> - pr_info("%s bad_%s=%d", sep, "task", fails->task);
> - pr_info("%s bad_%s=%d", sep, "stack", fails->stack);
> - pr_info("%s bad_%s=%d", sep, "time", fails->time);
> - pr_info("%s bad_%s=%d", sep, "data", fails->data);
> + fprintf(lock_output, "%s bad_%s=%d", sep, "task", fails->task);
> + fprintf(lock_output, "%s bad_%s=%d", sep, "stack", fails->stack);
> + fprintf(lock_output, "%s bad_%s=%d", sep, "time", fails->time);
> + fprintf(lock_output, "%s bad_%s=%d", sep, "data", fails->data);
> } else {
> int i;
> const char *name[4] = { "acquire", "acquired", "contended", "release" };
>
> for (i = 0; i < BROKEN_MAX; i++)
> - pr_info("%s bad_%s=%d", sep, name[i], bad_hist[i]);
> + fprintf(lock_output, "%s bad_%s=%d", sep, name[i], bad_hist[i]);
> }
> - pr_info("\n");
> + fprintf(lock_output, "\n");
> }
>
> static void print_footer(int total, int bad, struct lock_contention_fails *fails)
> @@ -2427,10 +2431,29 @@ static int parse_call_stack(const struct option *opt __maybe_unused, const char
> return ret;
> }
>
> +static int parse_output(const struct option *opt __maybe_unused, const char *str,
> + int unset __maybe_unused)
> +{
> + const char **name = (const char **)opt->value;
> +
> + if (str == NULL)
> + return -1;
> +
> + lock_output = fopen(str, "w");
> + if (lock_output == NULL) {
> + pr_err("Cannot open %s\n", str);
> + return -1;
> + }
> +
> + *name = str;
> + return 0;
> +}
> +
> int cmd_lock(int argc, const char **argv)
> {
> const struct option lock_options[] = {
> OPT_STRING('i', "input", &input_name, "file", "input file name"),
> + OPT_CALLBACK(0, "output", &output_name, "file", "output file name", parse_output),
> 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_BOOLEAN('f', "force", &force, "don't complain, do it"),
> @@ -2530,6 +2553,7 @@ int cmd_lock(int argc, const char **argv)
> for (i = 0; i < LOCKHASH_SIZE; i++)
> INIT_HLIST_HEAD(lockhash_table + i);
>
> + lock_output = stderr;
> argc = parse_options_subcommand(argc, argv, lock_options, lock_subcommands,
> lock_usage, PARSE_OPT_STOP_AT_NON_OPTION);
> if (!argc)
> --
> 2.41.0.255.g8b1d071c50-goog
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 4/4] perf test: Test perf lock contention CSV output
2023-06-28 20:01 ` [PATCH 4/4] perf test: Test perf lock contention CSV output Namhyung Kim
@ 2023-06-30 16:14 ` Ian Rogers
0 siblings, 0 replies; 11+ messages in thread
From: Ian Rogers @ 2023-06-30 16:14 UTC (permalink / raw)
To: Namhyung Kim
Cc: Arnaldo Carvalho de Melo, Jiri Olsa, Adrian Hunter,
Peter Zijlstra, Ingo Molnar, LKML, linux-perf-users, Song Liu,
Hao Luo
On Wed, Jun 28, 2023 at 1:01 PM Namhyung Kim <namhyung@kernel.org> wrote:
>
> To verify CSV output, just check the number of separators (",") using
> the tr and wc commands like this.
>
> grep -v "^#" ${result} | tr -d -c | wc -c
>
> Now it expects 6 columns (and 5 separators) in the output, but it may
> be changed later so count the field in the header first and compare it
> to the actual output lines.
>
> $ cat ${result}
> # output: contended, total wait, max wait, avg wait, type, caller
> 1, 28787, 28787, 28787, spinlock, raw_spin_rq_lock_nested+0x1b
>
> The test looks like below now:
>
> $ sudo ./perf test -v contention
> 86: kernel lock contention analysis test :
> --- start ---
> test child forked, pid 2705822
> Testing perf lock record and perf lock contention
> Testing perf lock contention --use-bpf
> Testing perf lock record and perf lock contention at the same time
> Testing perf lock contention --threads
> Testing perf lock contention --lock-addr
> Testing perf lock contention --type-filter (w/ spinlock)
> Testing perf lock contention --lock-filter (w/ tasklist_lock)
> Testing perf lock contention --callstack-filter (w/ unix_stream)
> Testing perf lock contention --callstack-filter with task aggregation
> Testing perf lock contention CSV output
> test child finished with 0
> ---- end ----
> kernel lock contention analysis test: Ok
>
> Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ian Rogers <irogers@google.com>
Thanks,
Ian
> ---
> tools/perf/tests/shell/lock_contention.sh | 36 +++++++++++++++++++++++
> 1 file changed, 36 insertions(+)
>
> diff --git a/tools/perf/tests/shell/lock_contention.sh b/tools/perf/tests/shell/lock_contention.sh
> index f2cc187b6186..4a194420416e 100755
> --- a/tools/perf/tests/shell/lock_contention.sh
> +++ b/tools/perf/tests/shell/lock_contention.sh
> @@ -233,6 +233,41 @@ test_aggr_task_stack_filter()
> fi
> }
>
> +test_csv_output()
> +{
> + echo "Testing perf lock contention CSV output"
> + perf lock contention -i ${perfdata} -E 1 -x , --output ${result}
> + # count the number of commas in the header
> + # it should have 5: contended, total-wait, max-wait, avg-wait, type, caller
> + header=$(grep "# output:" ${result} | tr -d -c , | wc -c)
> + if [ "${header}" != "5" ]; then
> + echo "[Fail] Recorded result does not have enough output columns: ${header} != 5"
> + err=1
> + exit
> + fi
> + # count the number of commas in the output
> + output=$(grep -v "^#" ${result} | tr -d -c , | wc -c)
> + if [ "${header}" != "${output}" ]; then
> + echo "[Fail] Recorded result does not match the number of commas: ${header} != ${output}"
> + err=1
> + exit
> + fi
> +
> + if ! perf lock con -b true > /dev/null 2>&1 ; then
> + echo "[Skip] No BPF support"
> + return
> + fi
> +
> + # the perf lock contention output goes to the stderr
> + perf lock con -a -b -E 1 -x , --output ${result} -- perf bench sched messaging > /dev/null 2>&1
> + output=$(grep -v "^#" ${result} | tr -d -c , | wc -c)
> + if [ "${header}" != "${output}" ]; then
> + echo "[Fail] BPF result does not match the number of commas: ${header} != ${output}"
> + err=1
> + exit
> + fi
> +}
> +
> check
>
> test_record
> @@ -244,5 +279,6 @@ test_type_filter
> test_lock_filter
> test_stack_filter
> test_aggr_task_stack_filter
> +test_csv_output
>
> exit ${err}
> --
> 2.41.0.255.g8b1d071c50-goog
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/4] perf lock contention: Add -x option for CSV style output
2023-06-30 16:02 ` Ian Rogers
@ 2023-07-01 17:39 ` Namhyung Kim
0 siblings, 0 replies; 11+ messages in thread
From: Namhyung Kim @ 2023-07-01 17:39 UTC (permalink / raw)
To: Ian Rogers
Cc: Arnaldo Carvalho de Melo, Jiri Olsa, Adrian Hunter,
Peter Zijlstra, Ingo Molnar, LKML, linux-perf-users, Song Liu,
Hao Luo
Hi Ian,
On Fri, Jun 30, 2023 at 9:03 AM Ian Rogers <irogers@google.com> wrote:
>
> On Wed, Jun 28, 2023 at 1:01 PM Namhyung Kim <namhyung@kernel.org> wrote:
> >
> > Sometimes we want to process the output by external programs. Let's add
> > the -x option to specify the field separator like perf stat.
> >
> > $ sudo ./perf lock con -ab -x, sleep 1
> > # output: contended, total wait, max wait, avg wait, type, caller
> > 19, 194232, 21415, 10222, spinlock, process_one_work+0x1f0
> > 15, 162748, 23843, 10849, rwsem:R, do_user_addr_fault+0x40e
> > 4, 86740, 23415, 21685, rwlock:R, ep_poll_callback+0x2d
> > 1, 84281, 84281, 84281, mutex, iwl_mvm_async_handlers_wk+0x135
> > 8, 67608, 27404, 8451, spinlock, __queue_work+0x174
> > 3, 58616, 31125, 19538, rwsem:W, do_mprotect_pkey+0xff
> > 3, 52953, 21172, 17651, rwlock:W, do_epoll_wait+0x248
> > 2, 30324, 19704, 15162, rwsem:R, do_madvise+0x3ad
> > 1, 24619, 24619, 24619, spinlock, rcu_core+0xd4
> >
> > The first line is a comment that shows the output format. Each line is
> > separated by the given string ("," in this case). The time is printed
> > in nsec without the unit so that it can be parsed easily.
> >
> > The characters can be used in the output like (":", "+" and ".") are not
> > allowed for the -x option.
> >
> > $ ./perf lock con -x:
> > Cannot use the separator that is already used
> >
> > Usage: perf lock contention [<options>]
> >
> > -x, --field-separator <separator>
> > print result in CSV format with custom separator
> >
> > The stacktraces are printed in the same line separated by ":". The
> > header is updated to show the stacktrace. Also the debug output is
> > added at the end as a comment.
> >
> > $ sudo ./perf lock con -abv -x, -F wait_total sleep 1
> > Looking at the vmlinux_path (8 entries long)
> > symsrc__init: cannot get elf header.
> > Using /proc/kcore for kernel data
> > Using /proc/kallsyms for symbols
> > # output: total wait, type, caller, stacktrace
> > 37134, spinlock, rcu_core+0xd4, 0xffffffff9d0401e4 _raw_spin_lock_irqsave+0x44: 0xffffffff9c738114 rcu_core+0xd4: ...
> > 21213, spinlock, raw_spin_rq_lock_nested+0x1b, 0xffffffff9d0407c0 _raw_spin_lock+0x30: 0xffffffff9c6d9cfb raw_spin_rq_lock_nested+0x1b: ...
> > 20506, rwlock:W, ep_done_scan+0x2d, 0xffffffff9c9bc4dd ep_done_scan+0x2d: 0xffffffff9c9bd5f1 do_epoll_wait+0x6d1: ...
> > 18044, rwlock:R, ep_poll_callback+0x2d, 0xffffffff9d040555 _raw_read_lock_irqsave+0x45: 0xffffffff9c9bc81d ep_poll_callback+0x2d: ...
> > 17890, rwlock:W, do_epoll_wait+0x47b, 0xffffffff9c9bd39b do_epoll_wait+0x47b: 0xffffffff9c9be9ef __x64_sys_epoll_wait+0x6d1: ...
> > 12114, spinlock, futex_wait_queue+0x60, 0xffffffff9d0407c0 _raw_spin_lock+0x30: 0xffffffff9d037cae __schedule+0xbe: ...
> > # debug: total=7, bad=0, bad_task=0, bad_stack=0, bad_time=0, bad_data=0
> >
> > Also note that some field (like lock symbols) can be empty.
> >
> > $ sudo ./perf lock con -abl -x, -E 10 sleep 1
> > # output: contended, total wait, max wait, avg wait, address, symbol, type
> > 6, 275025, 61764, 45837, ffff9dcc9f7d60d0, , spinlock
> > 18, 87716, 11196, 4873, ffff9dc540059000, , spinlock
> > 2, 6472, 5499, 3236, ffff9dcc7f730e00, rq_lock, spinlock
> > 3, 4429, 2341, 1476, ffff9dcc7f7b0e00, rq_lock, spinlock
> > 3, 3974, 1635, 1324, ffff9dcc7f7f0e00, rq_lock, spinlock
> > 4, 3290, 1326, 822, ffff9dc5f4e2cde0, , rwlock
> > 3, 2894, 1023, 964, ffffffff9e0d7700, rcu_state, spinlock
> > 1, 2567, 2567, 2567, ffff9dcc7f6b0e00, rq_lock, spinlock
> > 4, 1259, 596, 314, ffff9dc69c2adde0, , rwlock
> > 1, 934, 934, 934, ffff9dcc7f670e00, rq_lock, spinlock
> >
> > Signed-off-by: Namhyung Kim <namhyung@kernel.org>
> > Acked-by: Ian Rogers <irogers@google.com>
> > ---
> > tools/perf/Documentation/perf-lock.txt | 5 +
> > tools/perf/builtin-lock.c | 303 +++++++++++++++++++------
> > 2 files changed, 241 insertions(+), 67 deletions(-)
> >
> > diff --git a/tools/perf/Documentation/perf-lock.txt b/tools/perf/Documentation/perf-lock.txt
> > index 6e5ba3cd2b72..d1efcbe7a470 100644
> > --- a/tools/perf/Documentation/perf-lock.txt
> > +++ b/tools/perf/Documentation/perf-lock.txt
> > @@ -200,6 +200,11 @@ CONTENTION OPTIONS
> > Note that it matches the substring so 'rq' would match both 'raw_spin_rq_lock'
> > and 'irq_enter_rcu'.
> >
> > +-x::
> > +--field-separator=<SEP>::
> > + Show results using a CSV-style output to make it easy to import directly
> > + into spreadsheets. Columns are separated by the string specified in SEP.
> > +
> >
> > SEE ALSO
> > --------
> > diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
> > index 187efb651436..98b0c0b1b307 100644
> > --- a/tools/perf/builtin-lock.c
> > +++ b/tools/perf/builtin-lock.c
> > @@ -225,6 +225,12 @@ static void lock_stat_key_print_time(unsigned long long nsec, int len)
> > { 0, NULL },
> > };
> >
> > + /* for CSV output */
> > + if (len == 0) {
> > + pr_info("%llu", nsec);
>
> Perhaps for the next patch set. Picking on the first print, I think it
> makes sense with CSV output that there should be a file option.
> Otherwise debug messages pr_* are going to end up breaking the CSV
> format.
Yep, in the patch 3/4. :)
>
> > + return;
> > + }
> > +
> > for (int i = 0; table[i].unit; i++) {
> > if (nsec < table[i].base)
> > continue;
> > @@ -1626,11 +1632,179 @@ static void sort_contention_result(void)
> > sort_result();
> > }
> >
> > -static void print_bpf_events(int total, struct lock_contention_fails *fails)
> > +static void print_header_stdio(void)
> > +{
> > + struct lock_key *key;
> > +
> > + list_for_each_entry(key, &lock_keys, list)
> > + pr_info("%*s ", key->len, key->header);
> > +
> > + switch (aggr_mode) {
> > + case LOCK_AGGR_TASK:
> > + pr_info(" %10s %s\n\n", "pid",
> > + show_lock_owner ? "owner" : "comm");
> > + break;
> > + case LOCK_AGGR_CALLER:
> > + pr_info(" %10s %s\n\n", "type", "caller");
> > + break;
> > + case LOCK_AGGR_ADDR:
> > + pr_info(" %16s %s\n\n", "address", "symbol");
> > + break;
> > + default:
> > + break;
> > + }
> > +}
> > +
> > +static void print_header_csv(const char *sep)
> > +{
> > + struct lock_key *key;
> > +
> > + pr_info("# output: ");
> > + list_for_each_entry(key, &lock_keys, list)
> > + pr_info("%s%s ", key->header, sep);
> > +
> > + switch (aggr_mode) {
> > + case LOCK_AGGR_TASK:
> > + pr_info("%s%s %s\n", "pid", sep,
> > + show_lock_owner ? "owner" : "comm");
>
> So a thought here, I would kind of like all the CSV functions
> together. It is key for CSV output that the columns line up, the
> layout here means you need to jump through the code to determine this.
> I'd also prefer that the '\n' weren't output until after the switch.
> The purpose being to show that the line is created, at the end of the
> function when the line is done we move to the next line and that is
> common for all aggregation modes.
Yeah, I also think we should rewrite output code including perf stat
to do the job better. I hope I can find some time for it.
>
> > + break;
> > + case LOCK_AGGR_CALLER:
> > + pr_info("%s%s %s", "type", sep, "caller");
> > + if (verbose > 0)
> > + pr_info("%s %s", sep, "stacktrace");
> > + pr_info("\n");
> > + break;
> > + case LOCK_AGGR_ADDR:
> > + pr_info("%s%s %s%s %s\n", "address", sep, "symbol", sep, "type");
> > + break;
> > + default:
> > + break;
> > + }
> > +}
> > +
> > +static void print_header(void)
> > +{
> > + if (!quiet) {
> > + if (symbol_conf.field_sep)
> > + print_header_csv(symbol_conf.field_sep);
> > + else
> > + print_header_stdio();
>
> Suggestion: could we switch to the callback style here. So there is
> some state and a set of callback routines - the usual fake OO pattern.
> I could imagine the state for CSV being the current column number,
> that way there could be asserts on the layout.
Something like hpp code. Let me think about it later..
Thanks,
Namhyung
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2)
2023-06-28 20:01 [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
` (3 preceding siblings ...)
2023-06-28 20:01 ` [PATCH 4/4] perf test: Test perf lock contention CSV output Namhyung Kim
@ 2023-07-02 1:02 ` Namhyung Kim
4 siblings, 0 replies; 11+ messages in thread
From: Namhyung Kim @ 2023-07-02 1:02 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo, Jiri Olsa
Cc: Ian Rogers, Adrian Hunter, Peter Zijlstra, Ingo Molnar, LKML,
linux-perf-users, Song Liu, Hao Luo
On Wed, Jun 28, 2023 at 1:01 PM Namhyung Kim <namhyung@kernel.org> wrote:
>
> Hello,
>
> This is v2 of perf lock contention CSV output change.
> I've added --output option and a test case according to Ian's feedback.
>
> Sometimes we want to process the output by external programs. Let's add
> the -x option to specify the field separator like perf stat.
>
> $ sudo ./perf lock con -ab -x, sleep 1
> # output: contended, total wait, max wait, avg wait, type, caller
> 19, 194232, 21415, 10222, spinlock, process_one_work+0x1f0
> 15, 162748, 23843, 10849, rwsem:R, do_user_addr_fault+0x40e
> 4, 86740, 23415, 21685, rwlock:R, ep_poll_callback+0x2d
> 1, 84281, 84281, 84281, mutex, iwl_mvm_async_handlers_wk+0x135
> 8, 67608, 27404, 8451, spinlock, __queue_work+0x174
> 3, 58616, 31125, 19538, rwsem:W, do_mprotect_pkey+0xff
> 3, 52953, 21172, 17651, rwlock:W, do_epoll_wait+0x248
> 2, 30324, 19704, 15162, rwsem:R, do_madvise+0x3ad
> 1, 24619, 24619, 24619, spinlock, rcu_core+0xd4
>
> The first line is a comment that shows the output format. Each line is
> separated by the given string ("," in this case). The time is printed
> in nsec without the unit so that it can be parsed easily.
>
> The code is available at 'perf/lock-con-csv-v2' branch in
>
> git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git
>
> Thanks,
> Namhyung
>
>
> Namhyung Kim (4):
> perf lock: Remove stale comments
> perf lock contention: Add -x option for CSV style output
> perf lock contention: Add --output option
> perf test: Test perf lock contention CSV output
Applied to perf-tools-next, thanks!
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2023-07-02 1:03 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2023-06-28 20:01 [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
2023-06-28 20:01 ` [PATCH 1/4] perf lock: Remove stale comments Namhyung Kim
2023-06-30 16:03 ` Ian Rogers
2023-06-28 20:01 ` [PATCH 2/4] perf lock contention: Add -x option for CSV style output Namhyung Kim
2023-06-30 16:02 ` Ian Rogers
2023-07-01 17:39 ` Namhyung Kim
2023-06-28 20:01 ` [PATCH 3/4] perf lock contention: Add --output option Namhyung Kim
2023-06-30 16:13 ` Ian Rogers
2023-06-28 20:01 ` [PATCH 4/4] perf test: Test perf lock contention CSV output Namhyung Kim
2023-06-30 16:14 ` Ian Rogers
2023-07-02 1:02 ` [PATCHSET 0/4] perf lock contention: Add CSV style output support (v2) Namhyung Kim
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).