From 84c3a2bb4c513ca9fd1326cf24d3729b769d9cf1 Mon Sep 17 00:00:00 2001 From: Namhyung Kim Date: Mon, 27 Mar 2023 15:57:11 -0700 Subject: perf lock contention: Show detail failure reason for BPF It can fail to collect lock stat from BPF for various reasons. For example, I've got a report that sometimes time calculation seems wrong in case of contended spinlocks. I suspect the time delta went negative for some reason. Count them separately and show in the output like below: $ sudo perf lock contention -abE5 sleep 10 contended total wait max wait avg wait type caller 13 785.61 us 79.36 us 60.43 us spinlock remove_wait_queue+0x14 10 469.02 us 87.51 us 46.90 us spinlock prepare_to_wait+0x27 9 289.09 us 69.08 us 32.12 us spinlock finish_wait+0x36 114 251.05 us 8.56 us 2.20 us spinlock try_to_wake_up+0x1f5 132 188.63 us 5.01 us 1.43 us spinlock __wake_up_common_lock+0x62 === output for debug === bad: 1, total: 279 bad rate: 0.36 % histogram of failure reasons task: 1 stack: 0 time: 0 Signed-off-by: Namhyung Kim Cc: Adrian Hunter Cc: Hao Luo Cc: Ian Rogers Cc: Ingo Molnar Cc: Jiri Olsa Cc: Peter Zijlstra Cc: bpf@vger.kernel.org Link: https://lore.kernel.org/r/20230327225711.245738-1-namhyung@kernel.org Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-lock.c | 28 ++++++++++++++++++++++------ 1 file changed, 22 insertions(+), 6 deletions(-) (limited to 'tools/perf/builtin-lock.c') diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c index 82dd2dfe5692..32ec58fb80e4 100644 --- a/tools/perf/builtin-lock.c +++ b/tools/perf/builtin-lock.c @@ -1619,6 +1619,24 @@ static void sort_contention_result(void) sort_result(); } +static void print_bpf_events(int total, struct lock_contention_fails *fails) +{ + /* Output for debug, this have to be removed */ + int broken = fails->task + fails->stack + fails->time; + + if (quiet || total == 0 || (broken == 0 && verbose <= 0)) + 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); + + 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); +} static void print_contention_result(struct lock_contention *con) { struct lock_stat *st; @@ -1646,8 +1664,6 @@ static void print_contention_result(struct lock_contention *con) } bad = total = printed = 0; - if (use_bpf) - bad = bad_hist[BROKEN_CONTENDED]; while ((st = pop_from_result())) { struct thread *t; @@ -1704,7 +1720,10 @@ static void print_contention_result(struct lock_contention *con) break; } - print_bad_events(bad, total); + if (use_bpf) + print_bpf_events(total, &con->fails); + else + print_bad_events(bad, total); } static bool force; @@ -1931,9 +1950,6 @@ static int __cmd_contention(int argc, const char **argv) lock_contention_stop(); lock_contention_read(&con); - - /* abuse bad hist stats for lost entries */ - bad_hist[BROKEN_CONTENDED] = con.lost; } else { err = perf_session__process_events(session); if (err) -- cgit v1.2.3-70-g09d2