perf lock: Account for lock average wait time

While perf-lock currently reports both the total wait time and the
number of contentions, it doesn't explicitly show the average wait time.
Having this value immediately in the report can be quite useful when
looking into performance issues.

Furthermore, allowing report to sort by averages is another handy
feature to have - and thus do not only print the value, but add it to
the lock_stat structure.

Signed-off-by: Davidlohr Bueso <davidlohr@hp.com>
Cc: Aswin Chandramouleeswaran <aswin@hp.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1378693159-8747-8-git-send-email-davidlohr@hp.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>

diff --git a/tools/perf/Documentation/perf-lock.txt b/tools/perf/Documentation/perf-lock.txt
index c7f5f55634ac3fab974216404fdcb6348aec94d0..ab25be28c9dcaab31adb1822195afab571308910 100644 (file)
--- a/tools/perf/Documentation/perf-lock.txt
+++ b/tools/perf/Documentation/perf-lock.txt
@@ -48,7 +48,7 @@ REPORT OPTIONS
 -k::
 --key=<value>::
         Sorting key. Possible values: acquired (default), contended,
-        wait_total, wait_max, wait_min.
+       avg_wait, wait_total, wait_max, wait_min.
 
 INFO OPTIONS
 ------------

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 972310cbeb63b069b44c7cba9d19eead1ba3f97a..6a9076f165f44e7babfe8006a56765df4f2d1fb3 100644 (file)
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -56,7 +56,9 @@ struct lock_stat {
 
        unsigned int            nr_readlock;
        unsigned int            nr_trylock;
+
        /* these times are in nano sec. */
+       u64                     avg_wait_time;
        u64                     wait_time_total;
        u64                     wait_time_min;
        u64                     wait_time_max;
@@ -208,6 +210,7 @@ static struct thread_stat *thread_stat_findnew_first(u32 tid)
 
 SINGLE_KEY(nr_acquired)
 SINGLE_KEY(nr_contended)
+SINGLE_KEY(avg_wait_time)
 SINGLE_KEY(wait_time_total)
 SINGLE_KEY(wait_time_max)
 
@@ -244,6 +247,7 @@ static struct rb_root               result; /* place to store sorted data */
 struct lock_key keys[] = {
        DEF_KEY_LOCK(acquired, nr_acquired),
        DEF_KEY_LOCK(contended, nr_contended),
+       DEF_KEY_LOCK(avg_wait, avg_wait_time),
        DEF_KEY_LOCK(wait_total, wait_time_total),
        DEF_KEY_LOCK(wait_min, wait_time_min),
        DEF_KEY_LOCK(wait_max, wait_time_max),
@@ -516,6 +520,7 @@ static int report_lock_acquired_event(struct perf_evsel *evsel,
 
        seq->state = SEQ_STATE_ACQUIRED;
        ls->nr_acquired++;
+       ls->avg_wait_time = ls->nr_contended ? ls->wait_time_total/ls->nr_contended : 0;
        seq->prev_event_time = sample->time;
 end:
        return 0;
@@ -570,6 +575,7 @@ static int report_lock_contended_event(struct perf_evsel *evsel,
 
        seq->state = SEQ_STATE_CONTENDED;
        ls->nr_contended++;
+       ls->avg_wait_time = ls->wait_time_total/ls->nr_contended;
        seq->prev_event_time = sample->time;
 end:
        return 0;
@@ -703,6 +709,7 @@ static void print_result(void)
        pr_info("%10s ", "acquired");
        pr_info("%10s ", "contended");
 
+       pr_info("%15s ", "avg wait (ns)");
        pr_info("%15s ", "total wait (ns)");
        pr_info("%15s ", "max wait (ns)");
        pr_info("%15s ", "min wait (ns)");
@@ -734,6 +741,7 @@ static void print_result(void)
                pr_info("%10u ", st->nr_acquired);
                pr_info("%10u ", st->nr_contended);
 
+               pr_info("%15" PRIu64 " ", st->avg_wait_time);
                pr_info("%15" PRIu64 " ", st->wait_time_total);
                pr_info("%15" PRIu64 " ", st->wait_time_max);
                pr_info("%15" PRIu64 " ", st->wait_time_min == ULLONG_MAX ?
@@ -940,7 +948,7 @@ int cmd_lock(int argc, const char **argv, const char *prefix __maybe_unused)
        };
        const struct option report_options[] = {
        OPT_STRING('k', "key", &sort_key, "acquired",
-                   "key for sorting (acquired / contended / wait_total / wait_max / wait_min)"),
+                   "key for sorting (acquired / contended / avg_wait / wait_total / wait_max / wait_min)"),
        /* TODO: type */
        OPT_END()
        };