* [PATCH] tracing/lockdep: report the time waited for a lock
@ 2009-04-05 23:49 Frederic Weisbecker
2009-04-10 11:07 ` [tip:tracing/core] " Frederic Weisbecker
2009-05-28 14:32 ` [PATCH] " Steven Rostedt
0 siblings, 2 replies; 5+ messages in thread
From: Frederic Weisbecker @ 2009-04-05 23:49 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, LKML, Frederic Weisbecker, Peter Zijlstra
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 implement:
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>
---
include/trace/lockdep_event_types.h | 23 ++++++++++++++++++-----
kernel/lockdep.c | 8 ++++----
2 files changed, 22 insertions(+), 9 deletions(-)
diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
index adccfcd..863f1e4 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
diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index b0f0118..c4582a6 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -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;
--
1.6.1
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [tip:tracing/core] tracing/lockdep: report the time waited for a lock
2009-04-05 23:49 [PATCH] tracing/lockdep: report the time waited for a lock Frederic Weisbecker
@ 2009-04-10 11:07 ` Frederic Weisbecker
2009-05-28 14:32 ` [PATCH] " Steven Rostedt
1 sibling, 0 replies; 5+ messages in thread
From: Frederic Weisbecker @ 2009-04-10 11:07 UTC (permalink / raw)
To: linux-tip-commits
Cc: linux-kernel, hpa, mingo, fweisbec, rostedt, peterz, tglx, mingo
Commit-ID: 2062501ae6505dbc5bff3a792246c2661d114050
Gitweb: http://git.kernel.org/tip/2062501ae6505dbc5bff3a792246c2661d114050
Author: Frederic Weisbecker <fweisbec@gmail.com>
AuthorDate: Mon, 6 Apr 2009 01:49:33 +0200
Committer: Ingo Molnar <mingo@elte.hu>
CommitDate: Fri, 10 Apr 2009 12:50:56 +0200
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>
---
include/trace/lockdep_event_types.h | 23 ++++++++++++++++++-----
kernel/lockdep.c | 8 ++++----
2 files changed, 22 insertions(+), 9 deletions(-)
diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
index adccfcd..863f1e4 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
diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index b0f0118..c4582a6 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -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;
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH] tracing/lockdep: report the time waited for a lock
2009-04-05 23:49 [PATCH] tracing/lockdep: report the time waited for a lock Frederic Weisbecker
2009-04-10 11:07 ` [tip:tracing/core] " Frederic Weisbecker
@ 2009-05-28 14:32 ` Steven Rostedt
2009-05-28 14:34 ` Peter Zijlstra
1 sibling, 1 reply; 5+ messages in thread
From: Steven Rostedt @ 2009-05-28 14:32 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: Ingo Molnar, LKML, Peter Zijlstra
On Mon, 6 Apr 2009, Frederic Weisbecker wrote:
> ---
> include/trace/lockdep_event_types.h | 23 ++++++++++++++++++-----
> kernel/lockdep.c | 8 ++++----
> 2 files changed, 22 insertions(+), 9 deletions(-)
>
> diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
> index adccfcd..863f1e4 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);
I know this is already accepted, but can you move the do_div into the
print section.
Thanks,
-- Steve
> + __entry->wait_usec = (unsigned long) waittime;
> + ),
> + TP_printk("%s (%lu.%03lu us)", __entry->name, __entry->wait_usec,
> + __entry->wait_nsec_rem)
> +);
>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] tracing/lockdep: report the time waited for a lock
2009-05-28 14:32 ` [PATCH] " Steven Rostedt
@ 2009-05-28 14:34 ` Peter Zijlstra
2009-05-28 14:39 ` Frederic Weisbecker
0 siblings, 1 reply; 5+ messages in thread
From: Peter Zijlstra @ 2009-05-28 14:34 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Frederic Weisbecker, Ingo Molnar, LKML
On Thu, 2009-05-28 at 10:32 -0400, Steven Rostedt wrote:
> > + 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);
>
> I know this is already accepted, but can you move the do_div into the
> print section.
please do. Just fold those wait_* fields into a single u64 nsec one.
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] tracing/lockdep: report the time waited for a lock
2009-05-28 14:34 ` Peter Zijlstra
@ 2009-05-28 14:39 ` Frederic Weisbecker
0 siblings, 0 replies; 5+ messages in thread
From: Frederic Weisbecker @ 2009-05-28 14:39 UTC (permalink / raw)
To: Peter Zijlstra; +Cc: Steven Rostedt, Ingo Molnar, LKML
On Thu, May 28, 2009 at 04:34:43PM +0200, Peter Zijlstra wrote:
> On Thu, 2009-05-28 at 10:32 -0400, Steven Rostedt wrote:
>
> > > + 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);
> >
> > I know this is already accepted, but can you move the do_div into the
> > print section.
>
> please do. Just fold those wait_* fields into a single u64 nsec one.
Indeed, I'll fix it. Thanks!
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2009-05-28 14:39 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2009-04-05 23:49 [PATCH] tracing/lockdep: report the time waited for a lock Frederic Weisbecker
2009-04-10 11:07 ` [tip:tracing/core] " Frederic Weisbecker
2009-05-28 14:32 ` [PATCH] " Steven Rostedt
2009-05-28 14:34 ` Peter Zijlstra
2009-05-28 14:39 ` Frederic Weisbecker
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).