Skip to content

Commit 69c5c99

Browse files
namhyungnamhyung
committed
perf lock contention: Add -x option for CSV style output
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 Acked-by: Ian Rogers <[email protected]> Cc: Hao Luo <[email protected]> Cc: Peter Zijlstra <[email protected]> Cc: Adrian Hunter <[email protected]> Cc: Arnaldo Carvalho de Melo <[email protected]> Cc: Jiri Olsa <[email protected]> Cc: Ingo Molnar <[email protected]> Cc: Song Liu <[email protected]> Link: https://lore.kernel.org/r/[email protected] Signed-off-by: Namhyung Kim <[email protected]>
1 parent 7b83d59 commit 69c5c99

File tree

2 files changed

+241
-67
lines changed

2 files changed

+241
-67
lines changed

‎tools/perf/Documentation/perf-lock.txt

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -200,6 +200,11 @@ CONTENTION OPTIONS
200200
Note that it matches the substring so 'rq' would match both 'raw_spin_rq_lock'
201201
and 'irq_enter_rcu'.
202202

203+
-x::
204+
--field-separator=<SEP>::
205+
Show results using a CSV-style output to make it easy to import directly
206+
into spreadsheets. Columns are separated by the string specified in SEP.
207+
203208

204209
SEE ALSO
205210
--------

‎tools/perf/builtin-lock.c

Lines changed: 236 additions & 67 deletions
Original file line numberDiff line numberDiff line change
@@ -225,6 +225,12 @@ static void lock_stat_key_print_time(unsigned long long nsec, int len)
225225
{ 0, NULL },
226226
};
227227

228+
/* for CSV output */
229+
if (len == 0) {
230+
pr_info("%llu", nsec);
231+
return;
232+
}
233+
228234
for (int i = 0; table[i].unit; i++) {
229235
if (nsec < table[i].base)
230236
continue;
@@ -1626,11 +1632,179 @@ static void sort_contention_result(void)
16261632
sort_result();
16271633
}
16281634

1629-
static void print_bpf_events(int total, struct lock_contention_fails *fails)
1635+
static void print_header_stdio(void)
1636+
{
1637+
struct lock_key *key;
1638+
1639+
list_for_each_entry(key, &lock_keys, list)
1640+
pr_info("%*s ", key->len, key->header);
1641+
1642+
switch (aggr_mode) {
1643+
case LOCK_AGGR_TASK:
1644+
pr_info(" %10s %s\n\n", "pid",
1645+
show_lock_owner ? "owner" : "comm");
1646+
break;
1647+
case LOCK_AGGR_CALLER:
1648+
pr_info(" %10s %s\n\n", "type", "caller");
1649+
break;
1650+
case LOCK_AGGR_ADDR:
1651+
pr_info(" %16s %s\n\n", "address", "symbol");
1652+
break;
1653+
default:
1654+
break;
1655+
}
1656+
}
1657+
1658+
static void print_header_csv(const char *sep)
1659+
{
1660+
struct lock_key *key;
1661+
1662+
pr_info("# output: ");
1663+
list_for_each_entry(key, &lock_keys, list)
1664+
pr_info("%s%s ", key->header, sep);
1665+
1666+
switch (aggr_mode) {
1667+
case LOCK_AGGR_TASK:
1668+
pr_info("%s%s %s\n", "pid", sep,
1669+
show_lock_owner ? "owner" : "comm");
1670+
break;
1671+
case LOCK_AGGR_CALLER:
1672+
pr_info("%s%s %s", "type", sep, "caller");
1673+
if (verbose > 0)
1674+
pr_info("%s %s", sep, "stacktrace");
1675+
pr_info("\n");
1676+
break;
1677+
case LOCK_AGGR_ADDR:
1678+
pr_info("%s%s %s%s %s\n", "address", sep, "symbol", sep, "type");
1679+
break;
1680+
default:
1681+
break;
1682+
}
1683+
}
1684+
1685+
static void print_header(void)
1686+
{
1687+
if (!quiet) {
1688+
if (symbol_conf.field_sep)
1689+
print_header_csv(symbol_conf.field_sep);
1690+
else
1691+
print_header_stdio();
1692+
}
1693+
}
1694+
1695+
static void print_lock_stat_stdio(struct lock_contention *con, struct lock_stat *st)
1696+
{
1697+
struct lock_key *key;
1698+
struct thread *t;
1699+
int pid;
1700+
1701+
list_for_each_entry(key, &lock_keys, list) {
1702+
key->print(key, st);
1703+
pr_info(" ");
1704+
}
1705+
1706+
switch (aggr_mode) {
1707+
case LOCK_AGGR_CALLER:
1708+
pr_info(" %10s %s\n", get_type_str(st->flags), st->name);
1709+
break;
1710+
case LOCK_AGGR_TASK:
1711+
pid = st->addr;
1712+
t = perf_session__findnew(session, pid);
1713+
pr_info(" %10d %s\n",
1714+
pid, pid == -1 ? "Unknown" : thread__comm_str(t));
1715+
break;
1716+
case LOCK_AGGR_ADDR:
1717+
pr_info(" %016llx %s (%s)\n", (unsigned long long)st->addr,
1718+
st->name, get_type_name(st->flags));
1719+
break;
1720+
default:
1721+
break;
1722+
}
1723+
1724+
if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
1725+
struct map *kmap;
1726+
struct symbol *sym;
1727+
char buf[128];
1728+
u64 ip;
1729+
1730+
for (int i = 0; i < max_stack_depth; i++) {
1731+
if (!st->callstack || !st->callstack[i])
1732+
break;
1733+
1734+
ip = st->callstack[i];
1735+
sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
1736+
get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
1737+
pr_info("\t\t\t%#lx %s\n", (unsigned long)ip, buf);
1738+
}
1739+
}
1740+
}
1741+
1742+
static void print_lock_stat_csv(struct lock_contention *con, struct lock_stat *st,
1743+
const char *sep)
1744+
{
1745+
struct lock_key *key;
1746+
struct thread *t;
1747+
int pid;
1748+
1749+
list_for_each_entry(key, &lock_keys, list) {
1750+
key->print(key, st);
1751+
pr_info("%s ", sep);
1752+
}
1753+
1754+
switch (aggr_mode) {
1755+
case LOCK_AGGR_CALLER:
1756+
pr_info("%s%s %s", get_type_str(st->flags), sep, st->name);
1757+
if (verbose <= 0)
1758+
pr_info("\n");
1759+
break;
1760+
case LOCK_AGGR_TASK:
1761+
pid = st->addr;
1762+
t = perf_session__findnew(session, pid);
1763+
pr_info("%d%s %s\n", pid, sep, pid == -1 ? "Unknown" : thread__comm_str(t));
1764+
break;
1765+
case LOCK_AGGR_ADDR:
1766+
pr_info("%llx%s %s%s %s\n", (unsigned long long)st->addr, sep,
1767+
st->name, sep, get_type_name(st->flags));
1768+
break;
1769+
default:
1770+
break;
1771+
}
1772+
1773+
if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
1774+
struct map *kmap;
1775+
struct symbol *sym;
1776+
char buf[128];
1777+
u64 ip;
1778+
1779+
for (int i = 0; i < max_stack_depth; i++) {
1780+
if (!st->callstack || !st->callstack[i])
1781+
break;
1782+
1783+
ip = st->callstack[i];
1784+
sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
1785+
get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
1786+
pr_info("%s %#lx %s", i ? ":" : sep, (unsigned long) ip, buf);
1787+
}
1788+
pr_info("\n");
1789+
}
1790+
}
1791+
1792+
static void print_lock_stat(struct lock_contention *con, struct lock_stat *st)
1793+
{
1794+
if (symbol_conf.field_sep)
1795+
print_lock_stat_csv(con, st, symbol_conf.field_sep);
1796+
else
1797+
print_lock_stat_stdio(con, st);
1798+
}
1799+
1800+
static void print_footer_stdio(int total, int bad, struct lock_contention_fails *fails)
16301801
{
16311802
/* Output for debug, this have to be removed */
16321803
int broken = fails->task + fails->stack + fails->time + fails->data;
16331804

1805+
if (!use_bpf)
1806+
print_bad_events(bad, total);
1807+
16341808
if (quiet || total == 0 || (broken == 0 && verbose <= 0))
16351809
return;
16361810

@@ -1646,84 +1820,61 @@ static void print_bpf_events(int total, struct lock_contention_fails *fails)
16461820
pr_info(" %10s: %d\n", "data", fails->data);
16471821
}
16481822

1823+
static void print_footer_csv(int total, int bad, struct lock_contention_fails *fails,
1824+
const char *sep)
1825+
{
1826+
/* Output for debug, this have to be removed */
1827+
if (use_bpf)
1828+
bad = fails->task + fails->stack + fails->time + fails->data;
1829+
1830+
if (quiet || total == 0 || (bad == 0 && verbose <= 0))
1831+
return;
1832+
1833+
total += bad;
1834+
pr_info("# debug: total=%d%s bad=%d", total, sep, bad);
1835+
1836+
if (use_bpf) {
1837+
pr_info("%s bad_%s=%d", sep, "task", fails->task);
1838+
pr_info("%s bad_%s=%d", sep, "stack", fails->stack);
1839+
pr_info("%s bad_%s=%d", sep, "time", fails->time);
1840+
pr_info("%s bad_%s=%d", sep, "data", fails->data);
1841+
} else {
1842+
int i;
1843+
const char *name[4] = { "acquire", "acquired", "contended", "release" };
1844+
1845+
for (i = 0; i < BROKEN_MAX; i++)
1846+
pr_info("%s bad_%s=%d", sep, name[i], bad_hist[i]);
1847+
}
1848+
pr_info("\n");
1849+
}
1850+
1851+
static void print_footer(int total, int bad, struct lock_contention_fails *fails)
1852+
{
1853+
if (symbol_conf.field_sep)
1854+
print_footer_csv(total, bad, fails, symbol_conf.field_sep);
1855+
else
1856+
print_footer_stdio(total, bad, fails);
1857+
}
1858+
16491859
static void print_contention_result(struct lock_contention *con)
16501860
{
16511861
struct lock_stat *st;
1652-
struct lock_key *key;
16531862
int bad, total, printed;
16541863

1655-
if (!quiet) {
1656-
list_for_each_entry(key, &lock_keys, list)
1657-
pr_info("%*s ", key->len, key->header);
1658-
1659-
switch (aggr_mode) {
1660-
case LOCK_AGGR_TASK:
1661-
pr_info(" %10s %s\n\n", "pid",
1662-
show_lock_owner ? "owner" : "comm");
1663-
break;
1664-
case LOCK_AGGR_CALLER:
1665-
pr_info(" %10s %s\n\n", "type", "caller");
1666-
break;
1667-
case LOCK_AGGR_ADDR:
1668-
pr_info(" %16s %s\n\n", "address", "symbol");
1669-
break;
1670-
default:
1671-
break;
1672-
}
1673-
}
1864+
if (!quiet)
1865+
print_header();
16741866

16751867
bad = total = printed = 0;
16761868

16771869
while ((st = pop_from_result())) {
1678-
struct thread *t;
1679-
int pid;
1680-
16811870
total += use_bpf ? st->nr_contended : 1;
16821871
if (st->broken)
16831872
bad++;
16841873

16851874
if (!st->wait_time_total)
16861875
continue;
16871876

1688-
list_for_each_entry(key, &lock_keys, list) {
1689-
key->print(key, st);
1690-
pr_info(" ");
1691-
}
1692-
1693-
switch (aggr_mode) {
1694-
case LOCK_AGGR_CALLER:
1695-
pr_info(" %10s %s\n", get_type_str(st->flags), st->name);
1696-
break;
1697-
case LOCK_AGGR_TASK:
1698-
pid = st->addr;
1699-
t = perf_session__findnew(session, pid);
1700-
pr_info(" %10d %s\n",
1701-
pid, pid == -1 ? "Unknown" : thread__comm_str(t));
1702-
break;
1703-
case LOCK_AGGR_ADDR:
1704-
pr_info(" %016llx %s (%s)\n", (unsigned long long)st->addr,
1705-
st->name, get_type_name(st->flags));
1706-
break;
1707-
default:
1708-
break;
1709-
}
1710-
1711-
if (aggr_mode == LOCK_AGGR_CALLER && verbose > 0) {
1712-
struct map *kmap;
1713-
struct symbol *sym;
1714-
char buf[128];
1715-
u64 ip;
1716-
1717-
for (int i = 0; i < max_stack_depth; i++) {
1718-
if (!st->callstack || !st->callstack[i])
1719-
break;
1720-
1721-
ip = st->callstack[i];
1722-
sym = machine__find_kernel_symbol(con->machine, ip, &kmap);
1723-
get_symbol_name_offset(kmap, sym, ip, buf, sizeof(buf));
1724-
pr_info("\t\t\t%#lx %s\n", (unsigned long)ip, buf);
1725-
}
1726-
}
1877+
print_lock_stat(con, st);
17271878

17281879
if (++printed >= print_nr_entries)
17291880
break;
@@ -1740,10 +1891,7 @@ static void print_contention_result(struct lock_contention *con)
17401891
/* some entries are collected but hidden by the callstack filter */
17411892
total += con->nr_filtered;
17421893

1743-
if (use_bpf)
1744-
print_bpf_events(total, &con->fails);
1745-
else
1746-
print_bad_events(bad, total);
1894+
print_footer(total, bad, &con->fails);
17471895
}
17481896

17491897
static bool force;
@@ -1847,6 +1995,16 @@ static int check_lock_contention_options(const struct option *options,
18471995
return -1;
18481996
}
18491997

1998+
if (symbol_conf.field_sep) {
1999+
if (strstr(symbol_conf.field_sep, ":") || /* part of type flags */
2000+
strstr(symbol_conf.field_sep, "+") || /* part of caller offset */
2001+
strstr(symbol_conf.field_sep, ".")) { /* can be in a symbol name */
2002+
pr_err("Cannot use the separator that is already used\n");
2003+
parse_options_usage(usage, options, "x", 1);
2004+
return -1;
2005+
}
2006+
}
2007+
18502008
if (show_lock_owner)
18512009
show_thread_stats = true;
18522010

@@ -1962,6 +2120,15 @@ static int __cmd_contention(int argc, const char **argv)
19622120
if (select_key(true))
19632121
goto out_delete;
19642122

2123+
if (symbol_conf.field_sep) {
2124+
int i;
2125+
struct lock_key *keys = contention_keys;
2126+
2127+
/* do not align output in CSV format */
2128+
for (i = 0; keys[i].name; i++)
2129+
keys[i].len = 0;
2130+
}
2131+
19652132
if (use_bpf) {
19662133
lock_contention_start();
19672134
if (argc)
@@ -2330,6 +2497,8 @@ int cmd_lock(int argc, const char **argv)
23302497
OPT_CALLBACK('S', "callstack-filter", NULL, "NAMES",
23312498
"Filter specific function in the callstack", parse_call_stack),
23322499
OPT_BOOLEAN('o', "lock-owner", &show_lock_owner, "show lock owners instead of waiters"),
2500+
OPT_STRING_NOEMPTY('x', "field-separator", &symbol_conf.field_sep, "separator",
2501+
"print result in CSV format with custom separator"),
23332502
OPT_PARENT(lock_options)
23342503
};
23352504

0 commit comments

Comments
 (0)