[PATCH] tracing/lockdep: turn lock->name into an array

[PATCH] tracing/lockdep: turn lock->name into an array

[Frederic Weisbecker]

Impact: allow filtering by lock name / fix module tracing

Currently, the "lock acquired" event is traced using a TRACE_EVENT.
But we can't use the char * type for the name without risking to
dereference a freed pointer. A lock name can come from a module
towards lockdep and it is risky to only store its address because we
defer its name printing.

That's why this patch uses a fixed array size and copy the name.
Also it lets us filter the lock name because the event filtering
doesn't handle the char pointers. Such support is not needed yet since
the events don't use it for now because it is rarely easy to keep track
of a string while we defer its output.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 include/trace/lockdep_event_types.h |   13 +++++++++++--
 1 files changed, 11 insertions(+), 2 deletions(-)

diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
index 863f1e4..68f84f4 100644
--- a/include/trace/lockdep_event_types.h
+++ b/include/trace/lockdep_event_types.h
@@ -32,18 +32,27 @@ TRACE_FORMAT(lock_contended,
 	TP_FMT("%s", lock->name)
 	);
 
+#define LOCK_NAME_SIZE	25
+
+/*
+ * We might loose the name if it comes from a module
+ * so we keep a fixed array size of 25, enough for most
+ * usecases.
+ */
+
 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)
+		__array(char, name, LOCK_NAME_SIZE)
 		__field(unsigned long, wait_usec)
 		__field(unsigned long, wait_nsec_rem)
 	),
 	TP_fast_assign(
-		__entry->name = lock->name;
+		strncpy(__entry->name, lock->name, LOCK_NAME_SIZE - 1);
+		__entry->name[LOCK_NAME_SIZE - 1] = 0;
 		__entry->wait_nsec_rem = do_div(waittime, NSEC_PER_USEC);
 		__entry->wait_usec = (unsigned long) waittime;
 	),
-- 
1.6.1

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Frederic Weisbecker]

On Tue, Apr 14, 2009 at 12:36:06AM +0200, Frederic Weisbecker wrote:
> Impact: allow filtering by lock name / fix module tracing
> 
> Currently, the "lock acquired" event is traced using a TRACE_EVENT.
> But we can't use the char * type for the name without risking to
> dereference a freed pointer. A lock name can come from a module
> towards lockdep and it is risky to only store its address because we
> defer its name printing.
> 
> That's why this patch uses a fixed array size and copy the name.
> Also it lets us filter the lock name because the event filtering
> doesn't handle the char pointers. Such support is not needed yet since
> the events don't use it for now because it is rarely easy to keep track
> of a string while we defer its output.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  include/trace/lockdep_event_types.h |   13 +++++++++++--
>  1 files changed, 11 insertions(+), 2 deletions(-)
> 
> diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
> index 863f1e4..68f84f4 100644
> --- a/include/trace/lockdep_event_types.h
> +++ b/include/trace/lockdep_event_types.h
> @@ -32,18 +32,27 @@ TRACE_FORMAT(lock_contended,
>  	TP_FMT("%s", lock->name)
>  	);
>  
> +#define LOCK_NAME_SIZE	25



This constant may look a bit weird.
I just started with the assumption that a full lock name
will rarely exceed this length.

If you agree with it, I will expand the conversion of lockdep
TRACE_FORMAT to TRACE_EVENTS with the same assumption.
So that we will be able to use filters with locks events.

Thanks.



> +
> +/*
> + * We might loose the name if it comes from a module
> + * so we keep a fixed array size of 25, enough for most
> + * usecases.
> + */
> +
>  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)
> +		__array(char, name, LOCK_NAME_SIZE)
>  		__field(unsigned long, wait_usec)
>  		__field(unsigned long, wait_nsec_rem)
>  	),
>  	TP_fast_assign(
> -		__entry->name = lock->name;
> +		strncpy(__entry->name, lock->name, LOCK_NAME_SIZE - 1);
> +		__entry->name[LOCK_NAME_SIZE - 1] = 0;
>  		__entry->wait_nsec_rem = do_div(waittime, NSEC_PER_USEC);
>  		__entry->wait_usec = (unsigned long) waittime;
>  	),
> -- 
> 1.6.1
> 

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> On Tue, Apr 14, 2009 at 12:36:06AM +0200, Frederic Weisbecker wrote:
> > Impact: allow filtering by lock name / fix module tracing
> > 
> > Currently, the "lock acquired" event is traced using a TRACE_EVENT.
> > But we can't use the char * type for the name without risking to
> > dereference a freed pointer. A lock name can come from a module
> > towards lockdep and it is risky to only store its address because we
> > defer its name printing.
> > 
> > That's why this patch uses a fixed array size and copy the name.
> > Also it lets us filter the lock name because the event filtering
> > doesn't handle the char pointers. Such support is not needed yet since
> > the events don't use it for now because it is rarely easy to keep track
> > of a string while we defer its output.
> > 
> > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > ---
> >  include/trace/lockdep_event_types.h |   13 +++++++++++--
> >  1 files changed, 11 insertions(+), 2 deletions(-)
> > 
> > diff --git a/include/trace/lockdep_event_types.h b/include/trace/lockdep_event_types.h
> > index 863f1e4..68f84f4 100644
> > --- a/include/trace/lockdep_event_types.h
> > +++ b/include/trace/lockdep_event_types.h
> > @@ -32,18 +32,27 @@ TRACE_FORMAT(lock_contended,
> >  	TP_FMT("%s", lock->name)
> >  	);
> >  
> > +#define LOCK_NAME_SIZE	25
> 
> 
> 
> This constant may look a bit weird.
> I just started with the assumption that a full lock name
> will rarely exceed this length.
> 
> If you agree with it, I will expand the conversion of lockdep
> TRACE_FORMAT to TRACE_EVENTS with the same assumption.
> So that we will be able to use filters with locks events.

Sure.

But 25 might be on the narrow side. The names come from macros and 
we do have a few cases of particularly long sequences of: 
spin_lock(&my_subsys->my_bus->my_driver->my_hw->my_object->my_lock) 
easily spanning 25 characters. And stripping will strip away the 
most useful (final) bits of the word.

	Ingo

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Peter Zijlstra]

On Tue, 2009-04-14 at 00:42 +0200, Frederic Weisbecker wrote:
> > +#define LOCK_NAME_SIZE       25
> 
> 
> 
> This constant may look a bit weird.
> I just started with the assumption that a full lock name
> will rarely exceed this length.
> 
> If you agree with it, I will expand the conversion of lockdep
> TRACE_FORMAT to TRACE_EVENTS with the same assumption.
> So that we will be able to use filters with locks events.

I really really hate this.

if you pick a size on the top end so that all lock->name's fit in,
you're wasting heaps of space, if you pick a median length, everything
will get truncated.

If you're going to do a copy, just do the print into the buffer by using
_FORMAT and be done with it.

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> wrote:

> On Tue, 2009-04-14 at 00:42 +0200, Frederic Weisbecker wrote:
> > > +#define LOCK_NAME_SIZE       25
> > 
> > 
> > 
> > This constant may look a bit weird.
> > I just started with the assumption that a full lock name
> > will rarely exceed this length.
> > 
> > If you agree with it, I will expand the conversion of lockdep
> > TRACE_FORMAT to TRACE_EVENTS with the same assumption.
> > So that we will be able to use filters with locks events.
> 
> I really really hate this.
> 
> if you pick a size on the top end so that all lock->name's fit in, 
> you're wasting heaps of space, if you pick a median length, 
> everything will get truncated.
> 
> If you're going to do a copy, just do the print into the buffer by 
> using _FORMAT and be done with it.

what i suggested was a variable length field. That solves the size 
issue. The ring-buffer supports variable size records anyway.

	Ingo

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Frederic Weisbecker]

On Tue, Apr 14, 2009 at 12:27:54PM +0200, Ingo Molnar wrote:
> 
> * Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > On Tue, 2009-04-14 at 00:42 +0200, Frederic Weisbecker wrote:
> > > > +#define LOCK_NAME_SIZE       25
> > > 
> > > 
> > > 
> > > This constant may look a bit weird.
> > > I just started with the assumption that a full lock name
> > > will rarely exceed this length.
> > > 
> > > If you agree with it, I will expand the conversion of lockdep
> > > TRACE_FORMAT to TRACE_EVENTS with the same assumption.
> > > So that we will be able to use filters with locks events.
> > 
> > I really really hate this.
> > 
> > if you pick a size on the top end so that all lock->name's fit in, 
> > you're wasting heaps of space, if you pick a median length, 
> > everything will get truncated.
> > 
> > If you're going to do a copy, just do the print into the buffer by 
> > using _FORMAT and be done with it.
> 
> what i suggested was a variable length field. That solves the size 
> issue. The ring-buffer supports variable size records anyway.
> 
> 	Ingo



Indeed. That's how I plan to change it.
It can become the main new __string() field concept
that we talked about.

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

>  	TP_STRUCT__entry(
> -		__field(const char *, name)
> +		__array(char, name, LOCK_NAME_SIZE)
>  		__field(unsigned long, wait_usec)
>  		__field(unsigned long, wait_nsec_rem)
>  	),

Hm. These constants tend to grow - 25 will certainly be too narrow. 
But increasing it increases the record size as well.

I think we'll need an embedded __string() type, with a length field 
(but still also zero-delimited, for convenience), hm?

	Ingo

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Frederic Weisbecker]

On Tue, Apr 14, 2009 at 01:01:10AM +0200, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
> 
> >  	TP_STRUCT__entry(
> > -		__field(const char *, name)
> > +		__array(char, name, LOCK_NAME_SIZE)
> >  		__field(unsigned long, wait_usec)
> >  		__field(unsigned long, wait_nsec_rem)
> >  	),
> 
> Hm. These constants tend to grow - 25 will certainly be too narrow. 
> But increasing it increases the record size as well.


Yeah, that's why I'm not sure about the right size.

 
> I think we'll need an embedded __string() type, with a length field 
> (but still also zero-delimited, for convenience), hm?


Indeed. It tends to be a repetitive pattern.
Also, may be we can use an undefined array size on the structure
for the __string field.
We already do so with the old style trace_printk entry and may be
some others. Extending TRACE_EVENT to support it shouldn't be a big deal.

I'll just wait for Steven changes and try to do that.


> 	Ingo

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[KOSAKI Motohiro]

Hi

> Impact: allow filtering by lock name / fix module tracing
> 
> Currently, the "lock acquired" event is traced using a TRACE_EVENT.
> But we can't use the char * type for the name without risking to
> dereference a freed pointer. A lock name can come from a module
> towards lockdep and it is risky to only store its address because we
> defer its name printing.

When released lockdep string table?
I guess it only happend at module unloading. if so, we should consider to
make delayed string table freeing at module unloading.

My point is, module unloading is rare event. thus meking pointer safe mechanism
widely avoid string copy.

IOW, if not, ringbuffer is filled tons string. it kill the merit of binary
buffer and current design.


> That's why this patch uses a fixed array size and copy the name.
> Also it lets us filter the lock name because the event filtering
> doesn't handle the char pointers. Such support is not needed yet since
> the events don't use it for now because it is rarely easy to keep track
> of a string while we defer its output.
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Ingo Molnar]

* KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com> wrote:

> Hi
> 
> > Impact: allow filtering by lock name / fix module tracing
> > 
> > Currently, the "lock acquired" event is traced using a TRACE_EVENT.
> > But we can't use the char * type for the name without risking to
> > dereference a freed pointer. A lock name can come from a module
> > towards lockdep and it is risky to only store its address because we
> > defer its name printing.
> 
> When released lockdep string table? I guess it only happend at 
> module unloading. if so, we should consider to make delayed string 
> table freeing at module unloading.
> 
> My point is, module unloading is rare event. thus meking pointer 
> safe mechanism widely avoid string copy.
> 
> IOW, if not, ringbuffer is filled tons string. it kill the merit 
> of binary buffer and current design.

We could zap all pending trace entries on module unload (it is a 
rare operation). That would indeed make a whole category of 
symbol-alike string pointers safe to be passed by value.

	Ingo

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[KOSAKI Motohiro]

> 
> * KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com> wrote:
> 
> > Hi
> > 
> > > Impact: allow filtering by lock name / fix module tracing
> > > 
> > > Currently, the "lock acquired" event is traced using a TRACE_EVENT.
> > > But we can't use the char * type for the name without risking to
> > > dereference a freed pointer. A lock name can come from a module
> > > towards lockdep and it is risky to only store its address because we
> > > defer its name printing.
> > 
> > When released lockdep string table? I guess it only happend at 
> > module unloading. if so, we should consider to make delayed string 
> > table freeing at module unloading.
> > 
> > My point is, module unloading is rare event. thus meking pointer 
> > safe mechanism widely avoid string copy.
> > 
> > IOW, if not, ringbuffer is filled tons string. it kill the merit 
> > of binary buffer and current design.
> 
> We could zap all pending trace entries on module unload (it is a 
> rare operation). That would indeed make a whole category of 
> symbol-alike string pointers safe to be passed by value.

Oh, it seems very good idea!

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Peter Zijlstra]

On Tue, 2009-04-14 at 08:53 +0200, Ingo Molnar wrote:
> * KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com> wrote:
> 
> > Hi
> > 
> > > Impact: allow filtering by lock name / fix module tracing
> > > 
> > > Currently, the "lock acquired" event is traced using a TRACE_EVENT.
> > > But we can't use the char * type for the name without risking to
> > > dereference a freed pointer. A lock name can come from a module
> > > towards lockdep and it is risky to only store its address because we
> > > defer its name printing.
> > 
> > When released lockdep string table? I guess it only happend at 
> > module unloading. if so, we should consider to make delayed string 
> > table freeing at module unloading.
> > 
> > My point is, module unloading is rare event. thus meking pointer 
> > safe mechanism widely avoid string copy.
> > 
> > IOW, if not, ringbuffer is filled tons string. it kill the merit 
> > of binary buffer and current design.
> 
> We could zap all pending trace entries on module unload (it is a 
> rare operation). That would indeed make a whole category of 
> symbol-alike string pointers safe to be passed by value.

Except that might make debugging a module unload bug rather hard...

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> wrote:

> On Tue, 2009-04-14 at 08:53 +0200, Ingo Molnar wrote:
> > * KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com> wrote:
> > 
> > > Hi
> > > 
> > > > Impact: allow filtering by lock name / fix module tracing
> > > > 
> > > > Currently, the "lock acquired" event is traced using a TRACE_EVENT.
> > > > But we can't use the char * type for the name without risking to
> > > > dereference a freed pointer. A lock name can come from a module
> > > > towards lockdep and it is risky to only store its address because we
> > > > defer its name printing.
> > > 
> > > When released lockdep string table? I guess it only happend at 
> > > module unloading. if so, we should consider to make delayed string 
> > > table freeing at module unloading.
> > > 
> > > My point is, module unloading is rare event. thus meking pointer 
> > > safe mechanism widely avoid string copy.
> > > 
> > > IOW, if not, ringbuffer is filled tons string. it kill the merit 
> > > of binary buffer and current design.
> > 
> > We could zap all pending trace entries on module unload (it is a 
> > rare operation). That would indeed make a whole category of 
> > symbol-alike string pointers safe to be passed by value.
> 
> Except that might make debugging a module unload bug rather 
> hard...

yes. Never needed to do that personally though. Plus more specific 
tracers like function tracer without event-tracing embellishments 
could still be used in such situations too, without flushing.

	Ingo

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Jeremy Fitzhardinge]

Ingo Molnar wrote:
> We could zap all pending trace entries on module unload (it is a 
> rare operation)

...Unless you're trying to trace something across a module unload.  I 
don't know if its at all practical, but it would be nice to just zap the 
pointers within the buffer, rather than the whole buffer.

    J

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Peter Zijlstra]

On Fri, 2009-04-17 at 10:25 -0700, Jeremy Fitzhardinge wrote:
> Ingo Molnar wrote:
> > We could zap all pending trace entries on module unload (it is a 
> > rare operation)
> 
> ....Unless you're trying to trace something across a module unload.  I 
> don't know if its at all practical, but it would be nice to just zap the 
> pointers within the buffer, rather than the whole buffer.

I think the new __string() thing that's in the works will avoid the
whole problem by copying the string into the buffer, instead of keeping
a reference.

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Steven Rostedt]

On Fri, 17 Apr 2009, Peter Zijlstra wrote:

> On Fri, 2009-04-17 at 10:25 -0700, Jeremy Fitzhardinge wrote:
> > Ingo Molnar wrote:
> > > We could zap all pending trace entries on module unload (it is a 
> > > rare operation)
> > 
> > ....Unless you're trying to trace something across a module unload.  I 
> > don't know if its at all practical, but it would be nice to just zap the 
> > pointers within the buffer, rather than the whole buffer.
> 
> I think the new __string() thing that's in the works will avoid the
> whole problem by copying the string into the buffer, instead of keeping
> a reference.

Speaking of which. We have not heard back from Frederic on this yet. I 
hope he's taking a break, enjoying the sun, and not stuck on some tricky 
macro crap ;-)

-- Steve

Re: [PATCH] tracing/lockdep: turn lock->name into an array

[Frederic Weisbecker]

On Fri, Apr 17, 2009 at 01:36:58PM -0400, Steven Rostedt wrote:
> 
> 
> On Fri, 17 Apr 2009, Peter Zijlstra wrote:
> 
> > On Fri, 2009-04-17 at 10:25 -0700, Jeremy Fitzhardinge wrote:
> > > Ingo Molnar wrote:
> > > > We could zap all pending trace entries on module unload (it is a 
> > > > rare operation)
> > > 
> > > ....Unless you're trying to trace something across a module unload.  I 
> > > don't know if its at all practical, but it would be nice to just zap the 
> > > pointers within the buffer, rather than the whole buffer.
> > 
> > I think the new __string() thing that's in the works will avoid the
> > whole problem by copying the string into the buffer, instead of keeping
> > a reference.
> 
> Speaking of which. We have not heard back from Frederic on this yet. I 
> hope he's taking a break, enjoying the sun, and not stuck on some tricky 
> macro crap ;-)
> 
> -- Steve
>



Oh you haven't yet received my mail about that?
It said I was cheering up about your and Peter's idea of using offsets
instead of pointer because of the end result:

- We can use as much __string() as we want
- No need for something else, such as the strcpy bits
- We are not forced to put it in the end of the patch
- Which means I will implement that in a v3 very soon ;-)

Frederic.