tracing/lockdep: report the time waited for a lock (2062501a) · Commits · 戴 / test

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>

include/trace/lockdep_event_types.h

+18 −5

Original line number	Diff line number	Diff line
		@@ -32,10 +32,23 @@ 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

kernel/lockdep.c

+4 −4

Original line number	Diff line number	Diff line
		@@ -3061,6 +3061,8 @@ found_it:
		put_lock_stats(stats);
		}

		DEFINE_TRACE(lock_acquired);

		static void
		__lock_acquired(struct lockdep_map *lock, unsigned long ip)
		{
		@@ -3099,6 +3101,8 @@ found_it:
		hlock->holdtime_stamp = now;
		}

		trace_lock_acquired(lock, ip, waittime);

		stats = get_lock_stats(hlock_class(hlock));
		if (waittime) {
		if (hlock->read)
		@@ -3137,14 +3141,10 @@ void lock_contended(struct lockdep_map *lock, unsigned long ip)
		}
		EXPORT_SYMBOL_GPL(lock_contended);

		DEFINE_TRACE(lock_acquired);

		void lock_acquired(struct lockdep_map *lock, unsigned long ip)
		{
		unsigned long flags;

		trace_lock_acquired(lock, ip);

		if (unlikely(!lock_stat))
		return;

Admin message