From: Namhyung Kim <namhyung@kernel.org>
Date: Wed, 15 Jun 2022 16:32:16 +0000 (-0700)
Subject: perf lock: Print wait times with unit
X-Git-Url: http://git.maquefel.me/?a=commitdiff_plain;h=ab0101768f639801b726f8be50e2ff7366ade056;p=linux.git
perf lock: Print wait times with unit
Currently it only prints the time in nsec but it's a bit hard to read
and takes longer in the screen. We can change it to use different units
and keep the number small to save the space.
Before:
$ perf lock report
Name acquired contended avg wait (ns) total wait (ns) max wait (ns) min wait (ns)
jiffies_lock 433 32 2778 88908 13570 692
&lruvec->lru_lock 747 5 11254 56272 18317 1412
slock-AF_INET6 7 1 23543 23543 23543 23543
&newf->file_lock 706 15 1025 15388 2279 618
slock-AF_INET6 8 1 10379 10379 10379 10379
&rq->__lock 2143 5 2037 10185 3462 939
After:
Name acquired contended avg wait total wait max wait min wait
jiffies_lock 433 32 2.78 us 88.91 us 13.57 us 692 ns
&lruvec->lru_lock 747 5 11.25 us 56.27 us 18.32 us 1.41 us
slock-AF_INET6 7 1 23.54 us 23.54 us 23.54 us 23.54 us
&newf->file_lock 706 15 1.02 us 15.39 us 2.28 us 618 ns
slock-AF_INET6 8 1 10.38 us 10.38 us 10.38 us 10.38 us
&rq->__lock 2143 5 2.04 us 10.19 us 3.46 us 939 ns
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Acked-by: Ian Rogers <irogers@google.com>
Cc: Boqun Feng <boqun.feng@gmail.com>
Cc: Davidlohr Bueso <dave@stgolabs.net>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Waiman Long <longman@redhat.com>
Cc: Will Deacon <will@kernel.org>
Link: https://lore.kernel.org/r/20220615163222.1275500-2-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 23a33ac15e685..57e396323d057 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -251,6 +251,31 @@ struct lock_key {
struct list_head list;
};
+static void lock_stat_key_print_time(unsigned long long nsec, int len)
+{
+ static const struct {
+ float base;
+ const char *unit;
+ } table[] = {
+ { 1e9 * 3600, "h " },
+ { 1e9 * 60, "m " },
+ { 1e9, "s " },
+ { 1e6, "ms" },
+ { 1e3, "us" },
+ { 0, NULL },
+ };
+
+ for (int i = 0; table[i].unit; i++) {
+ if (nsec < table[i].base)
+ continue;
+
+ pr_info("%*.2f %s", len - 3, nsec / table[i].base, table[i].unit);
+ return;
+ }
+
+ pr_info("%*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) \
@@ -258,11 +283,18 @@ static void lock_stat_key_print_ ## member(struct lock_key *key, \
pr_info("%*llu", key->len, (unsigned long long)ls->member); \
}
+#define PRINT_TIME(member) \
+static void lock_stat_key_print_ ## member(struct lock_key *key, \
+ struct lock_stat *ls) \
+{ \
+ lock_stat_key_print_time((unsigned long long)ls->member, key->len); \
+}
+
PRINT_KEY(nr_acquired)
PRINT_KEY(nr_contended)
-PRINT_KEY(avg_wait_time)
-PRINT_KEY(wait_time_total)
-PRINT_KEY(wait_time_max)
+PRINT_TIME(avg_wait_time)
+PRINT_TIME(wait_time_total)
+PRINT_TIME(wait_time_max)
static void lock_stat_key_print_wait_time_min(struct lock_key *key,
struct lock_stat *ls)
@@ -272,7 +304,7 @@ static void lock_stat_key_print_wait_time_min(struct lock_key *key,
if (wait_time == ULLONG_MAX)
wait_time = 0;
- pr_info("%*"PRIu64, key->len, wait_time);
+ lock_stat_key_print_time(wait_time, key->len);
}
@@ -291,10 +323,10 @@ static const char *output_fields;
struct lock_key keys[] = {
DEF_KEY_LOCK(acquired, "acquired", nr_acquired, 10),
DEF_KEY_LOCK(contended, "contended", nr_contended, 10),
- DEF_KEY_LOCK(avg_wait, "avg wait (ns)", avg_wait_time, 15),
- DEF_KEY_LOCK(wait_total, "total wait (ns)", wait_time_total, 15),
- DEF_KEY_LOCK(wait_max, "max wait (ns)", wait_time_max, 15),
- DEF_KEY_LOCK(wait_min, "min wait (ns)", wait_time_min, 15),
+ DEF_KEY_LOCK(avg_wait, "avg wait", avg_wait_time, 12),
+ DEF_KEY_LOCK(wait_total, "total wait", wait_time_total, 12),
+ DEF_KEY_LOCK(wait_max, "max wait", wait_time_max, 12),
+ DEF_KEY_LOCK(wait_min, "min wait", wait_time_min, 12),
/* extra comparisons much complicated should be here */
{ }