| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20230628200141.2739587-4-namhyung@kernel.org>
Date: Wed, 28 Jun 2023 13:01:40 -0700
From: Namhyung Kim <namhyung@...nel.org>
To: Arnaldo Carvalho de Melo <acme@...nel.org>,
Jiri Olsa <jolsa@...nel.org>
Cc: Ian Rogers <irogers@...gle.com>,
Adrian Hunter <adrian.hunter@...el.com>,
Peter Zijlstra <peterz@...radead.org>,
Ingo Molnar <mingo@...nel.org>,
LKML <linux-kernel@...r.kernel.org>,
linux-perf-users@...r.kernel.org, Song Liu <song@...nel.org>,
Hao Luo <haoluo@...gle.com>
Subject: [PATCH 3/4] perf lock contention: Add --output option
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@...gle.com>
Signed-off-by: Namhyung Kim <namhyung@...nel.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
Powered by blists - more mailing lists