tracing/lockdep: report the time waited for a lock

While trying to optimize the new lock on reiserfs to replace
the bkl, I find the lock tracing very useful though it lacks
something important for performance (and latency) instrumentation:
the time a task waits for a lock.

That's what this patch implements:

  bash-4816  [000]   202.652815: lock_contended: lock_contended: &sb->s_type->i_mutex_key
  bash-4816  [000]   202.652819: lock_acquired: &rq->lock (0.000 us)
 <...>-4787  [000]   202.652825: lock_acquired: &rq->lock (0.000 us)
 <...>-4787  [000]   202.652829: lock_acquired: &rq->lock (0.000 us)
  bash-4816  [000]   202.652833: lock_acquired: &sb->s_type->i_mutex_key (16.005 us)

As shown above, the "lock acquired" field is followed by the time
it has been waiting for the lock. Usually, a lock contended entry
is followed by a near lock_acquired entry with a non-zero time waited.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Acked-by: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
LKML-Reference: <1238975373-15739-1-git-send-email-fweisbec@gmail.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>

1 files changed, 18 insertions, 5 deletions

diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
index adccfcd2ec8f..863f1e4583a6 100644
--- a/include/trace/lockdep_event_types.h
+++ b/include/trace/lockdep_event_types.h
@@ -32,11 +32,24 @@ TRACE_FORMAT(lock_contended,
         TP_FMT("%s", lock->name)
         );
 
-TRACE_FORMAT(lock_acquired,
-        TP_PROTO(struct lockdep_map *lock, unsigned long ip),
-        TP_ARGS(lock, ip),
-        TP_FMT("%s", lock->name)
-        );
+TRACE_EVENT(lock_acquired,
+        TP_PROTO(struct lockdep_map *lock, unsigned long ip, s64 waittime),
+
+        TP_ARGS(lock, ip, waittime),
+
+        TP_STRUCT__entry(
+                __field(const char *, name)
+                __field(unsigned long, wait_usec)
+                __field(unsigned long, wait_nsec_rem)
+        ),
+        TP_fast_assign(
+                __entry->name = lock->name;
+                __entry->wait_nsec_rem = do_div(waittime, NSEC_PER_USEC);
+                __entry->wait_usec = (unsigned long) waittime;
+        ),
+        TP_printk("%s (%lu.%03lu us)", __entry->name, __entry->wait_usec,
+                                       __entry->wait_nsec_rem)
+);
 
 #endif
 #endif