aboutsummaryrefslogtreecommitdiff
path: root/include/trace
diff options
context:
space:
mode:
authorFrederic Weisbecker <fweisbec@gmail.com>2009-04-06 01:49:33 +0200
committerIngo Molnar <mingo@elte.hu>2009-04-10 12:50:56 +0200
commit2062501ae6505dbc5bff3a792246c2661d114050 (patch)
tree59792987c9e9fd1ae657c2e4a5cdb14545523e24 /include/trace
parent1cad1252ed279ea59f3f8d3d3a5817eeb2f7a4d3 (diff)
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>
Diffstat (limited to 'include/trace')
-rw-r--r--include/trace/lockdep_event_types.h23
1 files changed, 18 insertions, 5 deletions
diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
index adccfcd2ec8..863f1e4583a 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