[PATCH 0/2 v3] [GIT PULL] tracing/events: add the __string field

[PATCH 0/2 v3] [GIT PULL] tracing/events: add the __string field

[Frederic Weisbecker]

Hi,

Here is the v3 of the __string() field patchset.
It applies suggestions from Steven and Peter with some arrangements.

This time, filtering is not supported (though it is ready in a pending patch).
I wanted to provide it but it looks like filtering has been broken recently.
Once I set a usual string filter, no more traces appear, and clearing it
doesn't change anything.

The following changes since commit 8e668b5b3455207e4540fc7ccab9ecf70142f288:
  Steven Rostedt (1):
        tracing: remove format attribute of inline function

are available in the git repository at:

  git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git tracing/core

Frederic Weisbecker (2):
      tracing/events: provide string with undefined size support
      tracing/lock: provide lock_acquired event support for dynamic size string

 include/trace/events/lockdep.h |    6 +-
 include/trace/ftrace.h         |   88 ++++++++++++++++++++++++++++++++++++++-
 2 files changed, 88 insertions(+), 6 deletions(-)

[PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Frederic Weisbecker]

This patch provides the support for dynamic size strings on
event tracing.

The key concept is to use a structure with an ending char array field of
undefined size and use such ability to allocate the minimal size on the
ring buffer to make one or more string entries fit inside, as opposite
to a fixed length strings with upper bound.

The strings themselves are represented using fields which have an offset
value from the beginning of the entry.

This patch provides three new macros:

__string(item, src)

This one declares a string to the structure inside TP_STRUCT__entry.
You need to provide the name of the string field and the source that will
be copied inside.
This will also add the dynamic size of the string needed for the ring
buffer entry allocation.
A stack allocated structure is used to temporarily store the offset
of each strings, avoiding double calls to strlen() on each event
insertion.

__get_str(field)

This one will give you a pointer to the string you have created. This
is an abstract helper to resolve the absolute address given the field
name which is a relative address from the beginning of the trace_structure.

__assign_str(dst, src)

Use this macro to automatically perform the string copy from src to
dst. src must be a variable to assign and dst is the name of a __string
field.

Example on how to use it:

TRACE_EVENT(my_event,
	TP_PROTO(char *src1, char *src2),

	TP_ARGS(src1, src2),
	TP_STRUCT__entry(
		__string(str1, src1)
		__string(str2, src2)
	),
	TP_fast_assign(
		__assign_str(str1, src1);
		__assign_str(str2, src2);
	),
	TP_printk("%s %s", __get_str(src1), __get_str(src2))
)

Of course you can mix-up any __field or __array inside this
TRACE_EVENT. The position of the __string or __assign_str
doesn't matter.

Changes in v2:

Address the suggestion of Steven Rostedt: drop the opening_string() macro
and redefine __ending_string() to get the size of the string to be copied
instead of overwritting the whole ring buffer allocation.

Changes in v3:

Address other suggestions of Steven Rostedt and Peter Zijlstra with
some changes: drop the __ending_string and the need to have only one
string field.
Use offsets instead of absolute addresses.

[ Impact: better usage of memory for string tracing ]

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Li Zefan <lizf@cn.fujitsu.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 include/trace/ftrace.h |   88 ++++++++++++++++++++++++++++++++++++++++++++++--
 1 files changed, 85 insertions(+), 3 deletions(-)

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 39a3351..353b7db 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -27,6 +27,9 @@
 #undef __field
 #define __field(type, item)		type	item;
 
+#undef __string
+#define __string(item, src)		int	__str_loc_##item;
+
 #undef TP_STRUCT__entry
 #define TP_STRUCT__entry(args...) args
 
@@ -35,14 +38,53 @@
 	struct ftrace_raw_##name {				\
 		struct trace_entry	ent;			\
 		tstruct						\
+		char			__str_data[0];		\
 	};							\
 	static struct ftrace_event_call event_##name
 
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
 
+
 /*
  * Stage 2 of the trace events.
  *
+ * Include the following:
+ *
+ * struct ftrace_str_offsets_<call> {
+ *	int				<str1>;
+ *	int				<str2>;
+ *	[...]
+ * };
+ *
+ * The __string() macro will create each int <str>, this is to
+ * keep the offset of each string from the beggining of the event
+ * once we perform the strlen() of the src strings.
+ *
+ */
+
+#undef TRACE_FORMAT
+#define TRACE_FORMAT(call, proto, args, fmt)
+
+#undef __array
+#define __array(type, item, len)
+
+#undef __field
+#define __field(type, item);
+
+#undef __string
+#define __string(item, src)	int item;
+
+#undef TRACE_EVENT
+#define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
+	struct ftrace_str_offsets_##call {				\
+		tstruct;						\
+	};
+
+#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
+
+/*
+ * Stage 3 of the trace events.
+ *
  * Override the macros in <trace/trace_events.h> to include the following:
  *
  * enum print_line_t
@@ -80,6 +122,9 @@
 #undef TP_printk
 #define TP_printk(fmt, args...) fmt "\n", args
 
+#undef __get_str
+#define __get_str(field)	(char *)__entry + __entry->__str_loc_##field
+
 #undef TRACE_EVENT
 #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
 enum print_line_t							\
@@ -146,6 +191,16 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
 	if (!ret)							\
 		return 0;
 
+#undef __string
+#define __string(item, src)						       \
+	ret = trace_seq_printf(s, "\tfield: __str_loc " #item ";\t"	       \
+			       "offset:%u;tsize:%u;\n",			       \
+			       (unsigned int)offsetof(typeof(field),	       \
+					__str_loc_##item),		       \
+			       (unsigned int)sizeof(field.__str_loc_##item));  \
+	if (!ret)							       \
+		return 0;
+
 #undef __entry
 #define __entry REC
 
@@ -189,6 +244,12 @@ ftrace_format_##call(struct trace_seq *s)				\
 	if (ret)							\
 		return ret;
 
+#undef __string
+#define __string(item, src)						       \
+	ret = trace_define_field(event_call, "__str_loc", #item,	       \
+				offsetof(typeof(field), __str_loc_##item),     \
+				sizeof(field.__str_loc_##item));
+
 #undef TRACE_EVENT
 #define TRACE_EVENT(call, proto, args, tstruct, func, print)		\
 int									\
@@ -212,7 +273,7 @@ ftrace_define_fields_##call(void)					\
 #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
 
 /*
- * Stage 3 of the trace events.
+ * Stage 4 of the trace events.
  *
  * Override the macros in <trace/trace_events.h> to include the following:
  *
@@ -409,6 +470,23 @@ __attribute__((section("_ftrace_events"))) event_##call = {		\
 #undef __entry
 #define __entry entry
 
+#undef __field
+#define __field(type, item)
+
+#undef __array
+#define __array(type, item, len)
+
+#undef __string
+#define __string(item, src)						       \
+	__str_offsets.item = __str_size +				       \
+			     offsetof(typeof(*entry), __str_data);	       \
+	__str_size += strlen(src) + 1;
+
+#undef __assign_str
+#define __assign_str(dst, src)						\
+	__entry->__str_loc_##dst = __str_offsets.dst;			\
+	strcpy(__get_str(dst), src);
+
 #undef TRACE_EVENT
 #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
 _TRACE_PROFILE(call, PARAMS(proto), PARAMS(args))			\
@@ -417,18 +495,22 @@ static struct ftrace_event_call event_##call;				\
 									\
 static void ftrace_raw_event_##call(proto)				\
 {									\
+	struct ftrace_str_offsets_##call __maybe_unused __str_offsets;  \
 	struct ftrace_event_call *call = &event_##call;			\
 	struct ring_buffer_event *event;				\
 	struct ftrace_raw_##call *entry;				\
 	unsigned long irq_flags;					\
+	int __str_size = 0;						\
 	int pc;								\
 									\
 	local_save_flags(irq_flags);					\
 	pc = preempt_count();						\
 									\
+	tstruct;							\
+									\
 	event = trace_current_buffer_lock_reserve(event_##call.id,	\
-				  sizeof(struct ftrace_raw_##call),	\
-				  irq_flags, pc);			\
+				 sizeof(struct ftrace_raw_##call) + __str_size,\
+				 irq_flags, pc);			\
 	if (!event)							\
 		return;							\
 	entry	= ring_buffer_event_data(event);			\
-- 
1.6.1

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Li Zefan]

> @@ -417,18 +495,22 @@ static struct ftrace_event_call event_##call;				\
>  									\
>  static void ftrace_raw_event_##call(proto)				\
>  {									\
> +	struct ftrace_str_offsets_##call __maybe_unused __str_offsets;  \
>  	struct ftrace_event_call *call = &event_##call;			\
>  	struct ring_buffer_event *event;				\
>  	struct ftrace_raw_##call *entry;				\
>  	unsigned long irq_flags;					\
> +	int __str_size = 0;						\
>  	int pc;								\
>  									\
>  	local_save_flags(irq_flags);					\
>  	pc = preempt_count();						\
>  									\
> +	tstruct;							\
> +									\
>  	event = trace_current_buffer_lock_reserve(event_##call.id,	\
> -				  sizeof(struct ftrace_raw_##call),	\
> -				  irq_flags, pc);			\
> +				 sizeof(struct ftrace_raw_##call) + __str_size,\

sizeof(*entry) will make it much shorter. ;)

> +				 irq_flags, pc);			\
>  	if (!event)							\
>  		return;							\
>  	entry	= ring_buffer_event_data(event);			\

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Frederic Weisbecker]

On Sun, Apr 19, 2009 at 02:15:36PM +0800, Li Zefan wrote:
> > @@ -417,18 +495,22 @@ static struct ftrace_event_call event_##call;				\
> >  									\
> >  static void ftrace_raw_event_##call(proto)				\
> >  {									\
> > +	struct ftrace_str_offsets_##call __maybe_unused __str_offsets;  \
> >  	struct ftrace_event_call *call = &event_##call;			\
> >  	struct ring_buffer_event *event;				\
> >  	struct ftrace_raw_##call *entry;				\
> >  	unsigned long irq_flags;					\
> > +	int __str_size = 0;						\
> >  	int pc;								\
> >  									\
> >  	local_save_flags(irq_flags);					\
> >  	pc = preempt_count();						\
> >  									\
> > +	tstruct;							\
> > +									\
> >  	event = trace_current_buffer_lock_reserve(event_##call.id,	\
> > -				  sizeof(struct ftrace_raw_##call),	\
> > -				  irq_flags, pc);			\
> > +				 sizeof(struct ftrace_raw_##call) + __str_size,\
> 
> sizeof(*entry) will make it much shorter. ;)


Heh, you're right :-)
I will update that.


> 
> > +				 irq_flags, pc);			\
> >  	if (!event)							\
> >  		return;							\
> >  	entry	= ring_buffer_event_data(event);			\
> 

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Frederic Weisbecker]

On Sun, Apr 19, 2009 at 07:01:34AM +0200, Frederic Weisbecker wrote:
> This patch provides the support for dynamic size strings on
> event tracing.
> 
> The key concept is to use a structure with an ending char array field of
> undefined size and use such ability to allocate the minimal size on the
> ring buffer to make one or more string entries fit inside, as opposite
> to a fixed length strings with upper bound.
> 
> The strings themselves are represented using fields which have an offset
> value from the beginning of the entry.
> 
> This patch provides three new macros:
> 
> __string(item, src)
> 
> This one declares a string to the structure inside TP_STRUCT__entry.
> You need to provide the name of the string field and the source that will
> be copied inside.
> This will also add the dynamic size of the string needed for the ring
> buffer entry allocation.
> A stack allocated structure is used to temporarily store the offset
> of each strings, avoiding double calls to strlen() on each event
> insertion.
> 
> __get_str(field)
> 
> This one will give you a pointer to the string you have created. This
> is an abstract helper to resolve the absolute address given the field
> name which is a relative address from the beginning of the trace_structure.
> 
> __assign_str(dst, src)
> 
> Use this macro to automatically perform the string copy from src to
> dst. src must be a variable to assign and dst is the name of a __string
> field.
> 
> Example on how to use it:
> 
> TRACE_EVENT(my_event,
> 	TP_PROTO(char *src1, char *src2),
> 
> 	TP_ARGS(src1, src2),
> 	TP_STRUCT__entry(
> 		__string(str1, src1)
> 		__string(str2, src2)
> 	),
> 	TP_fast_assign(
> 		__assign_str(str1, src1);
> 		__assign_str(str2, src2);
> 	),
> 	TP_printk("%s %s", __get_str(src1), __get_str(src2))
> )
> 
> Of course you can mix-up any __field or __array inside this
> TRACE_EVENT. The position of the __string or __assign_str
> doesn't matter.
> 
> Changes in v2:
> 
> Address the suggestion of Steven Rostedt: drop the opening_string() macro
> and redefine __ending_string() to get the size of the string to be copied
> instead of overwritting the whole ring buffer allocation.
> 
> Changes in v3:
> 
> Address other suggestions of Steven Rostedt and Peter Zijlstra with
> some changes: drop the __ending_string and the need to have only one
> string field.
> Use offsets instead of absolute addresses.
> 
> [ Impact: better usage of memory for string tracing ]
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Li Zefan <lizf@cn.fujitsu.com>
> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
> ---


Hi,

Do you have doubts about this?
It would be nice to have a (N)Acked-by from you for these
two patches :-)

Thanks!

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Steven Rostedt]

On Tue, 21 Apr 2009, Frederic Weisbecker wrote:

> On Sun, Apr 19, 2009 at 07:01:34AM +0200, Frederic Weisbecker wrote:
> > This patch provides the support for dynamic size strings on
> > event tracing.
> > 
> > The key concept is to use a structure with an ending char array field of
> > undefined size and use such ability to allocate the minimal size on the
> > ring buffer to make one or more string entries fit inside, as opposite
> > to a fixed length strings with upper bound.
> > 
> > The strings themselves are represented using fields which have an offset
> > value from the beginning of the entry.
> > 
> > This patch provides three new macros:
> > 
> > __string(item, src)
> > 
> > This one declares a string to the structure inside TP_STRUCT__entry.
> > You need to provide the name of the string field and the source that will
> > be copied inside.
> > This will also add the dynamic size of the string needed for the ring
> > buffer entry allocation.
> > A stack allocated structure is used to temporarily store the offset
> > of each strings, avoiding double calls to strlen() on each event
> > insertion.
> > 
> > __get_str(field)
> > 
> > This one will give you a pointer to the string you have created. This
> > is an abstract helper to resolve the absolute address given the field
> > name which is a relative address from the beginning of the trace_structure.
> > 
> > __assign_str(dst, src)
> > 
> > Use this macro to automatically perform the string copy from src to
> > dst. src must be a variable to assign and dst is the name of a __string
> > field.
> > 
> > Example on how to use it:
> > 
> > TRACE_EVENT(my_event,
> > 	TP_PROTO(char *src1, char *src2),
> > 
> > 	TP_ARGS(src1, src2),
> > 	TP_STRUCT__entry(
> > 		__string(str1, src1)
> > 		__string(str2, src2)
> > 	),
> > 	TP_fast_assign(
> > 		__assign_str(str1, src1);
> > 		__assign_str(str2, src2);
> > 	),
> > 	TP_printk("%s %s", __get_str(src1), __get_str(src2))
> > )
> > 
> > Of course you can mix-up any __field or __array inside this
> > TRACE_EVENT. The position of the __string or __assign_str
> > doesn't matter.
> > 
> > Changes in v2:
> > 
> > Address the suggestion of Steven Rostedt: drop the opening_string() macro
> > and redefine __ending_string() to get the size of the string to be copied
> > instead of overwritting the whole ring buffer allocation.
> > 
> > Changes in v3:
> > 
> > Address other suggestions of Steven Rostedt and Peter Zijlstra with
> > some changes: drop the __ending_string and the need to have only one
> > string field.
> > Use offsets instead of absolute addresses.
> > 
> > [ Impact: better usage of memory for string tracing ]
> > 
> > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > Cc: Steven Rostedt <rostedt@goodmis.org>
> > Cc: Li Zefan <lizf@cn.fujitsu.com>
> > Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
> > ---
> 
> 
> Hi,
> 
> Do you have doubts about this?
> It would be nice to have a (N)Acked-by from you for these
> two patches :-)

Ouch, I totally missed seeing this. It was engulfed in spam/unrelated 
email.

I'm about to go to school for a few hours, I'll review it when I get back.

Thanks,

-- Steve

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Steven Rostedt]

Hi Frederic,

Cool stuff!


On Sun, 19 Apr 2009, Frederic Weisbecker wrote:

> This patch provides the support for dynamic size strings on
> event tracing.
> 
> The key concept is to use a structure with an ending char array field of
> undefined size and use such ability to allocate the minimal size on the
> ring buffer to make one or more string entries fit inside, as opposite
> to a fixed length strings with upper bound.
> 
> The strings themselves are represented using fields which have an offset
> value from the beginning of the entry.
> 
> This patch provides three new macros:
> 
> __string(item, src)
> 
> This one declares a string to the structure inside TP_STRUCT__entry.
> You need to provide the name of the string field and the source that will
> be copied inside.
> This will also add the dynamic size of the string needed for the ring
> buffer entry allocation.
> A stack allocated structure is used to temporarily store the offset
> of each strings, avoiding double calls to strlen() on each event
> insertion.
> 
> __get_str(field)
> 
> This one will give you a pointer to the string you have created. This
> is an abstract helper to resolve the absolute address given the field
> name which is a relative address from the beginning of the trace_structure.
> 
> __assign_str(dst, src)
> 
> Use this macro to automatically perform the string copy from src to
> dst. src must be a variable to assign and dst is the name of a __string
> field.
> 
> Example on how to use it:
> 
> TRACE_EVENT(my_event,
> 	TP_PROTO(char *src1, char *src2),
> 
> 	TP_ARGS(src1, src2),
> 	TP_STRUCT__entry(
> 		__string(str1, src1)
> 		__string(str2, src2)
> 	),
> 	TP_fast_assign(
> 		__assign_str(str1, src1);
> 		__assign_str(str2, src2);
> 	),
> 	TP_printk("%s %s", __get_str(src1), __get_str(src2))
> )
> 
> Of course you can mix-up any __field or __array inside this
> TRACE_EVENT. The position of the __string or __assign_str
> doesn't matter.
> 
> Changes in v2:
> 
> Address the suggestion of Steven Rostedt: drop the opening_string() macro
> and redefine __ending_string() to get the size of the string to be copied
> instead of overwritting the whole ring buffer allocation.
> 
> Changes in v3:
> 
> Address other suggestions of Steven Rostedt and Peter Zijlstra with
> some changes: drop the __ending_string and the need to have only one
> string field.
> Use offsets instead of absolute addresses.
> 
> [ Impact: better usage of memory for string tracing ]
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Li Zefan <lizf@cn.fujitsu.com>
> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
> ---
>  include/trace/ftrace.h |   88 ++++++++++++++++++++++++++++++++++++++++++++++--
>  1 files changed, 85 insertions(+), 3 deletions(-)
> 
> diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
> index 39a3351..353b7db 100644
> --- a/include/trace/ftrace.h
> +++ b/include/trace/ftrace.h
> @@ -27,6 +27,9 @@
>  #undef __field
>  #define __field(type, item)		type	item;
>  
> +#undef __string
> +#define __string(item, src)		int	__str_loc_##item;
> +
>  #undef TP_STRUCT__entry
>  #define TP_STRUCT__entry(args...) args
>  
> @@ -35,14 +38,53 @@
>  	struct ftrace_raw_##name {				\
>  		struct trace_entry	ent;			\
>  		tstruct						\
> +		char			__str_data[0];		\
>  	};							\
>  	static struct ftrace_event_call event_##name
>  
>  #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
>  
> +
>  /*
>   * Stage 2 of the trace events.
>   *
> + * Include the following:
> + *
> + * struct ftrace_str_offsets_<call> {
> + *	int				<str1>;
> + *	int				<str2>;
> + *	[...]
> + * };
> + *
> + * The __string() macro will create each int <str>, this is to
> + * keep the offset of each string from the beggining of the event
> + * once we perform the strlen() of the src strings.
> + *
> + */
> +
> +#undef TRACE_FORMAT
> +#define TRACE_FORMAT(call, proto, args, fmt)
> +
> +#undef __array
> +#define __array(type, item, len)
> +
> +#undef __field
> +#define __field(type, item);
> +
> +#undef __string
> +#define __string(item, src)	int item;
> +
> +#undef TRACE_EVENT
> +#define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
> +	struct ftrace_str_offsets_##call {				\
> +		tstruct;						\
> +	};
> +
> +#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> +
> +/*
> + * Stage 3 of the trace events.
> + *
>   * Override the macros in <trace/trace_events.h> to include the following:
>   *
>   * enum print_line_t
> @@ -80,6 +122,9 @@
>  #undef TP_printk
>  #define TP_printk(fmt, args...) fmt "\n", args
>  
> +#undef __get_str
> +#define __get_str(field)	(char *)__entry + __entry->__str_loc_##field

Because __get_str() is used it the "code" part of the macro, we probably 
should put parenthesis around it:

#define __get_str(field)	((char *)__entry + __entry->__str_loc__##field)


> +
>  #undef TRACE_EVENT
>  #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
>  enum print_line_t							\
> @@ -146,6 +191,16 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
>  	if (!ret)							\
>  		return 0;
>  
> +#undef __string
> +#define __string(item, src)						       \
> +	ret = trace_seq_printf(s, "\tfield: __str_loc " #item ";\t"	       \
> +			       "offset:%u;tsize:%u;\n",			       \
> +			       (unsigned int)offsetof(typeof(field),	       \
> +					__str_loc_##item),		       \
> +			       (unsigned int)sizeof(field.__str_loc_##item));  \
> +	if (!ret)							       \
> +		return 0;
> +
>  #undef __entry
>  #define __entry REC
>  
> @@ -189,6 +244,12 @@ ftrace_format_##call(struct trace_seq *s)				\
>  	if (ret)							\
>  		return ret;
>  
> +#undef __string
> +#define __string(item, src)						       \
> +	ret = trace_define_field(event_call, "__str_loc", #item,	       \
> +				offsetof(typeof(field), __str_loc_##item),     \
> +				sizeof(field.__str_loc_##item));
> +
>  #undef TRACE_EVENT
>  #define TRACE_EVENT(call, proto, args, tstruct, func, print)		\
>  int									\
> @@ -212,7 +273,7 @@ ftrace_define_fields_##call(void)					\
>  #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
>  
>  /*
> - * Stage 3 of the trace events.
> + * Stage 4 of the trace events.
>   *
>   * Override the macros in <trace/trace_events.h> to include the following:
>   *
> @@ -409,6 +470,23 @@ __attribute__((section("_ftrace_events"))) event_##call = {		\
>  #undef __entry
>  #define __entry entry
>  
> +#undef __field
> +#define __field(type, item)
> +
> +#undef __array
> +#define __array(type, item, len)
> +
> +#undef __string
> +#define __string(item, src)						       \
> +	__str_offsets.item = __str_size +				       \
> +			     offsetof(typeof(*entry), __str_data);	       \
> +	__str_size += strlen(src) + 1;
> +
> +#undef __assign_str
> +#define __assign_str(dst, src)						\
> +	__entry->__str_loc_##dst = __str_offsets.dst;			\
> +	strcpy(__get_str(dst), src);
> +
>  #undef TRACE_EVENT
>  #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
>  _TRACE_PROFILE(call, PARAMS(proto), PARAMS(args))			\
> @@ -417,18 +495,22 @@ static struct ftrace_event_call event_##call;				\
>  									\
>  static void ftrace_raw_event_##call(proto)				\
>  {									\
> +	struct ftrace_str_offsets_##call __maybe_unused __str_offsets;  \
>  	struct ftrace_event_call *call = &event_##call;			\
>  	struct ring_buffer_event *event;				\
>  	struct ftrace_raw_##call *entry;				\
>  	unsigned long irq_flags;					\
> +	int __str_size = 0;						\
>  	int pc;								\
>  									\
>  	local_save_flags(irq_flags);					\
>  	pc = preempt_count();						\
>  									\
> +	tstruct;							\
> +									\
>  	event = trace_current_buffer_lock_reserve(event_##call.id,	\
> -				  sizeof(struct ftrace_raw_##call),	\
> -				  irq_flags, pc);			\
> +				 sizeof(struct ftrace_raw_##call) + __str_size,\
> +				 irq_flags, pc);			\
>  	if (!event)							\
>  		return;							\
>  	entry	= ring_buffer_event_data(event);			\
> -- 
> 1.6.1

Other than my comment above...

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Steven Rostedt]

On Tue, 21 Apr 2009, Steven Rostedt wrote:

> 
> Hi Frederic,
> 
> Cool stuff!
> 
> 
> On Sun, 19 Apr 2009, Frederic Weisbecker wrote:
> 
> > This patch provides the support for dynamic size strings on
> > event tracing.
> > 
> > The key concept is to use a structure with an ending char array field of
> > undefined size and use such ability to allocate the minimal size on the
> > ring buffer to make one or more string entries fit inside, as opposite
> > to a fixed length strings with upper bound.
> > 
> > The strings themselves are represented using fields which have an offset
> > value from the beginning of the entry.
> > 
> > This patch provides three new macros:
> > 
> > __string(item, src)
> > 
> > This one declares a string to the structure inside TP_STRUCT__entry.
> > You need to provide the name of the string field and the source that will
> > be copied inside.
> > This will also add the dynamic size of the string needed for the ring
> > buffer entry allocation.
> > A stack allocated structure is used to temporarily store the offset
> > of each strings, avoiding double calls to strlen() on each event
> > insertion.
> > 
> > __get_str(field)
> > 
> > This one will give you a pointer to the string you have created. This
> > is an abstract helper to resolve the absolute address given the field
> > name which is a relative address from the beginning of the trace_structure.
> > 
> > __assign_str(dst, src)
> > 
> > Use this macro to automatically perform the string copy from src to
> > dst. src must be a variable to assign and dst is the name of a __string
> > field.
> > 
> > Example on how to use it:
> > 
> > TRACE_EVENT(my_event,
> > 	TP_PROTO(char *src1, char *src2),
> > 
> > 	TP_ARGS(src1, src2),
> > 	TP_STRUCT__entry(
> > 		__string(str1, src1)
> > 		__string(str2, src2)
> > 	),
> > 	TP_fast_assign(
> > 		__assign_str(str1, src1);
> > 		__assign_str(str2, src2);
> > 	),
> > 	TP_printk("%s %s", __get_str(src1), __get_str(src2))
> > )
> > 
> > Of course you can mix-up any __field or __array inside this
> > TRACE_EVENT. The position of the __string or __assign_str
> > doesn't matter.
> > 
> > Changes in v2:
> > 
> > Address the suggestion of Steven Rostedt: drop the opening_string() macro
> > and redefine __ending_string() to get the size of the string to be copied
> > instead of overwritting the whole ring buffer allocation.
> > 
> > Changes in v3:
> > 
> > Address other suggestions of Steven Rostedt and Peter Zijlstra with
> > some changes: drop the __ending_string and the need to have only one
> > string field.
> > Use offsets instead of absolute addresses.
> > 
> > [ Impact: better usage of memory for string tracing ]
> > 
> > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > Cc: Steven Rostedt <rostedt@goodmis.org>
> > Cc: Li Zefan <lizf@cn.fujitsu.com>
> > Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
> > ---
> >  include/trace/ftrace.h |   88 ++++++++++++++++++++++++++++++++++++++++++++++--
> >  1 files changed, 85 insertions(+), 3 deletions(-)
> > 
> > diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
> > index 39a3351..353b7db 100644
> > --- a/include/trace/ftrace.h
> > +++ b/include/trace/ftrace.h
> > @@ -27,6 +27,9 @@
> >  #undef __field
> >  #define __field(type, item)		type	item;
> >  
> > +#undef __string
> > +#define __string(item, src)		int	__str_loc_##item;
> > +
> >  #undef TP_STRUCT__entry
> >  #define TP_STRUCT__entry(args...) args
> >  
> > @@ -35,14 +38,53 @@
> >  	struct ftrace_raw_##name {				\
> >  		struct trace_entry	ent;			\
> >  		tstruct						\
> > +		char			__str_data[0];		\
> >  	};							\
> >  	static struct ftrace_event_call event_##name
> >  
> >  #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> >  
> > +
> >  /*
> >   * Stage 2 of the trace events.
> >   *
> > + * Include the following:
> > + *
> > + * struct ftrace_str_offsets_<call> {
> > + *	int				<str1>;
> > + *	int				<str2>;
> > + *	[...]
> > + * };
> > + *
> > + * The __string() macro will create each int <str>, this is to
> > + * keep the offset of each string from the beggining of the event
> > + * once we perform the strlen() of the src strings.
> > + *
> > + */
> > +
> > +#undef TRACE_FORMAT
> > +#define TRACE_FORMAT(call, proto, args, fmt)
> > +
> > +#undef __array
> > +#define __array(type, item, len)
> > +
> > +#undef __field
> > +#define __field(type, item);
> > +
> > +#undef __string
> > +#define __string(item, src)	int item;
> > +
> > +#undef TRACE_EVENT
> > +#define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
> > +	struct ftrace_str_offsets_##call {				\
> > +		tstruct;						\
> > +	};
> > +
> > +#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> > +
> > +/*
> > + * Stage 3 of the trace events.
> > + *
> >   * Override the macros in <trace/trace_events.h> to include the following:
> >   *
> >   * enum print_line_t
> > @@ -80,6 +122,9 @@
> >  #undef TP_printk
> >  #define TP_printk(fmt, args...) fmt "\n", args
> >  
> > +#undef __get_str
> > +#define __get_str(field)	(char *)__entry + __entry->__str_loc_##field
> 
> Because __get_str() is used it the "code" part of the macro, we probably 
> should put parenthesis around it:
> 
> #define __get_str(field)	((char *)__entry + __entry->__str_loc__##field)
> 
> 
> > +
> >  #undef TRACE_EVENT
> >  #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
> >  enum print_line_t							\
> > @@ -146,6 +191,16 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
> >  	if (!ret)							\
> >  		return 0;
> >  
> > +#undef __string
> > +#define __string(item, src)						       \
> > +	ret = trace_seq_printf(s, "\tfield: __str_loc " #item ";\t"	       \
> > +			       "offset:%u;tsize:%u;\n",			       \
> > +			       (unsigned int)offsetof(typeof(field),	       \
> > +					__str_loc_##item),		       \
> > +			       (unsigned int)sizeof(field.__str_loc_##item));  \
> > +	if (!ret)							       \
> > +		return 0;
> > +
> >  #undef __entry
> >  #define __entry REC
> >  
> > @@ -189,6 +244,12 @@ ftrace_format_##call(struct trace_seq *s)				\
> >  	if (ret)							\
> >  		return ret;
> >  
> > +#undef __string
> > +#define __string(item, src)						       \
> > +	ret = trace_define_field(event_call, "__str_loc", #item,	       \
> > +				offsetof(typeof(field), __str_loc_##item),     \
> > +				sizeof(field.__str_loc_##item));
> > +
> >  #undef TRACE_EVENT
> >  #define TRACE_EVENT(call, proto, args, tstruct, func, print)		\
> >  int									\
> > @@ -212,7 +273,7 @@ ftrace_define_fields_##call(void)					\
> >  #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> >  
> >  /*
> > - * Stage 3 of the trace events.
> > + * Stage 4 of the trace events.
> >   *
> >   * Override the macros in <trace/trace_events.h> to include the following:
> >   *
> > @@ -409,6 +470,23 @@ __attribute__((section("_ftrace_events"))) event_##call = {		\
> >  #undef __entry
> >  #define __entry entry
> >  
> > +#undef __field
> > +#define __field(type, item)
> > +
> > +#undef __array
> > +#define __array(type, item, len)
> > +
> > +#undef __string
> > +#define __string(item, src)						       \
> > +	__str_offsets.item = __str_size +				       \
> > +			     offsetof(typeof(*entry), __str_data);	       \
> > +	__str_size += strlen(src) + 1;
> > +
> > +#undef __assign_str
> > +#define __assign_str(dst, src)						\
> > +	__entry->__str_loc_##dst = __str_offsets.dst;			\
> > +	strcpy(__get_str(dst), src);
> > +
> >  #undef TRACE_EVENT
> >  #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
> >  _TRACE_PROFILE(call, PARAMS(proto), PARAMS(args))			\
> > @@ -417,18 +495,22 @@ static struct ftrace_event_call event_##call;				\
> >  									\
> >  static void ftrace_raw_event_##call(proto)				\
> >  {									\
> > +	struct ftrace_str_offsets_##call __maybe_unused __str_offsets;  \
> >  	struct ftrace_event_call *call = &event_##call;			\
> >  	struct ring_buffer_event *event;				\
> >  	struct ftrace_raw_##call *entry;				\
> >  	unsigned long irq_flags;					\
> > +	int __str_size = 0;						\
> >  	int pc;								\
> >  									\
> >  	local_save_flags(irq_flags);					\
> >  	pc = preempt_count();						\
> >  									\
> > +	tstruct;							\
> > +									\
> >  	event = trace_current_buffer_lock_reserve(event_##call.id,	\
> > -				  sizeof(struct ftrace_raw_##call),	\
> > -				  irq_flags, pc);			\
> > +				 sizeof(struct ftrace_raw_##call) + __str_size,\
> > +				 irq_flags, pc);			\
> >  	if (!event)							\
> >  		return;							\
> >  	entry	= ring_buffer_event_data(event);			\
> > -- 
> > 1.6.1
> 
> Other than my comment above...
> 
> Acked-by: Steven Rostedt <rostedt@goodmis.org>

Actually I looked at this code deeper than an Ack.

Reviewed-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Frederic Weisbecker]

On Tue, Apr 21, 2009 at 06:00:20PM -0400, Steven Rostedt wrote:
> 
> 
> 
> On Tue, 21 Apr 2009, Steven Rostedt wrote:
> 
> > 
> > Hi Frederic,
> > 
> > Cool stuff!
> > 
> > 
> > On Sun, 19 Apr 2009, Frederic Weisbecker wrote:
> > 
> > > This patch provides the support for dynamic size strings on
> > > event tracing.
> > > 
> > > The key concept is to use a structure with an ending char array field of
> > > undefined size and use such ability to allocate the minimal size on the
> > > ring buffer to make one or more string entries fit inside, as opposite
> > > to a fixed length strings with upper bound.
> > > 
> > > The strings themselves are represented using fields which have an offset
> > > value from the beginning of the entry.
> > > 
> > > This patch provides three new macros:
> > > 
> > > __string(item, src)
> > > 
> > > This one declares a string to the structure inside TP_STRUCT__entry.
> > > You need to provide the name of the string field and the source that will
> > > be copied inside.
> > > This will also add the dynamic size of the string needed for the ring
> > > buffer entry allocation.
> > > A stack allocated structure is used to temporarily store the offset
> > > of each strings, avoiding double calls to strlen() on each event
> > > insertion.
> > > 
> > > __get_str(field)
> > > 
> > > This one will give you a pointer to the string you have created. This
> > > is an abstract helper to resolve the absolute address given the field
> > > name which is a relative address from the beginning of the trace_structure.
> > > 
> > > __assign_str(dst, src)
> > > 
> > > Use this macro to automatically perform the string copy from src to
> > > dst. src must be a variable to assign and dst is the name of a __string
> > > field.
> > > 
> > > Example on how to use it:
> > > 
> > > TRACE_EVENT(my_event,
> > > 	TP_PROTO(char *src1, char *src2),
> > > 
> > > 	TP_ARGS(src1, src2),
> > > 	TP_STRUCT__entry(
> > > 		__string(str1, src1)
> > > 		__string(str2, src2)
> > > 	),
> > > 	TP_fast_assign(
> > > 		__assign_str(str1, src1);
> > > 		__assign_str(str2, src2);
> > > 	),
> > > 	TP_printk("%s %s", __get_str(src1), __get_str(src2))
> > > )
> > > 
> > > Of course you can mix-up any __field or __array inside this
> > > TRACE_EVENT. The position of the __string or __assign_str
> > > doesn't matter.
> > > 
> > > Changes in v2:
> > > 
> > > Address the suggestion of Steven Rostedt: drop the opening_string() macro
> > > and redefine __ending_string() to get the size of the string to be copied
> > > instead of overwritting the whole ring buffer allocation.
> > > 
> > > Changes in v3:
> > > 
> > > Address other suggestions of Steven Rostedt and Peter Zijlstra with
> > > some changes: drop the __ending_string and the need to have only one
> > > string field.
> > > Use offsets instead of absolute addresses.
> > > 
> > > [ Impact: better usage of memory for string tracing ]
> > > 
> > > Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> > > Cc: Steven Rostedt <rostedt@goodmis.org>
> > > Cc: Li Zefan <lizf@cn.fujitsu.com>
> > > Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
> > > ---
> > >  include/trace/ftrace.h |   88 ++++++++++++++++++++++++++++++++++++++++++++++--
> > >  1 files changed, 85 insertions(+), 3 deletions(-)
> > > 
> > > diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
> > > index 39a3351..353b7db 100644
> > > --- a/include/trace/ftrace.h
> > > +++ b/include/trace/ftrace.h
> > > @@ -27,6 +27,9 @@
> > >  #undef __field
> > >  #define __field(type, item)		type	item;
> > >  
> > > +#undef __string
> > > +#define __string(item, src)		int	__str_loc_##item;
> > > +
> > >  #undef TP_STRUCT__entry
> > >  #define TP_STRUCT__entry(args...) args
> > >  
> > > @@ -35,14 +38,53 @@
> > >  	struct ftrace_raw_##name {				\
> > >  		struct trace_entry	ent;			\
> > >  		tstruct						\
> > > +		char			__str_data[0];		\
> > >  	};							\
> > >  	static struct ftrace_event_call event_##name
> > >  
> > >  #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> > >  
> > > +
> > >  /*
> > >   * Stage 2 of the trace events.
> > >   *
> > > + * Include the following:
> > > + *
> > > + * struct ftrace_str_offsets_<call> {
> > > + *	int				<str1>;
> > > + *	int				<str2>;
> > > + *	[...]
> > > + * };
> > > + *
> > > + * The __string() macro will create each int <str>, this is to
> > > + * keep the offset of each string from the beggining of the event
> > > + * once we perform the strlen() of the src strings.
> > > + *
> > > + */
> > > +
> > > +#undef TRACE_FORMAT
> > > +#define TRACE_FORMAT(call, proto, args, fmt)
> > > +
> > > +#undef __array
> > > +#define __array(type, item, len)
> > > +
> > > +#undef __field
> > > +#define __field(type, item);
> > > +
> > > +#undef __string
> > > +#define __string(item, src)	int item;
> > > +
> > > +#undef TRACE_EVENT
> > > +#define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
> > > +	struct ftrace_str_offsets_##call {				\
> > > +		tstruct;						\
> > > +	};
> > > +
> > > +#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> > > +
> > > +/*
> > > + * Stage 3 of the trace events.
> > > + *
> > >   * Override the macros in <trace/trace_events.h> to include the following:
> > >   *
> > >   * enum print_line_t
> > > @@ -80,6 +122,9 @@
> > >  #undef TP_printk
> > >  #define TP_printk(fmt, args...) fmt "\n", args
> > >  
> > > +#undef __get_str
> > > +#define __get_str(field)	(char *)__entry + __entry->__str_loc_##field
> > 
> > Because __get_str() is used it the "code" part of the macro, we probably 
> > should put parenthesis around it:
> > 
> > #define __get_str(field)	((char *)__entry + __entry->__str_loc__##field)
> > 
> > 
> > > +
> > >  #undef TRACE_EVENT
> > >  #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
> > >  enum print_line_t							\
> > > @@ -146,6 +191,16 @@ ftrace_raw_output_##call(struct trace_iterator *iter, int flags)	\
> > >  	if (!ret)							\
> > >  		return 0;
> > >  
> > > +#undef __string
> > > +#define __string(item, src)						       \
> > > +	ret = trace_seq_printf(s, "\tfield: __str_loc " #item ";\t"	       \
> > > +			       "offset:%u;tsize:%u;\n",			       \
> > > +			       (unsigned int)offsetof(typeof(field),	       \
> > > +					__str_loc_##item),		       \
> > > +			       (unsigned int)sizeof(field.__str_loc_##item));  \
> > > +	if (!ret)							       \
> > > +		return 0;
> > > +
> > >  #undef __entry
> > >  #define __entry REC
> > >  
> > > @@ -189,6 +244,12 @@ ftrace_format_##call(struct trace_seq *s)				\
> > >  	if (ret)							\
> > >  		return ret;
> > >  
> > > +#undef __string
> > > +#define __string(item, src)						       \
> > > +	ret = trace_define_field(event_call, "__str_loc", #item,	       \
> > > +				offsetof(typeof(field), __str_loc_##item),     \
> > > +				sizeof(field.__str_loc_##item));
> > > +
> > >  #undef TRACE_EVENT
> > >  #define TRACE_EVENT(call, proto, args, tstruct, func, print)		\
> > >  int									\
> > > @@ -212,7 +273,7 @@ ftrace_define_fields_##call(void)					\
> > >  #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
> > >  
> > >  /*
> > > - * Stage 3 of the trace events.
> > > + * Stage 4 of the trace events.
> > >   *
> > >   * Override the macros in <trace/trace_events.h> to include the following:
> > >   *
> > > @@ -409,6 +470,23 @@ __attribute__((section("_ftrace_events"))) event_##call = {		\
> > >  #undef __entry
> > >  #define __entry entry
> > >  
> > > +#undef __field
> > > +#define __field(type, item)
> > > +
> > > +#undef __array
> > > +#define __array(type, item, len)
> > > +
> > > +#undef __string
> > > +#define __string(item, src)						       \
> > > +	__str_offsets.item = __str_size +				       \
> > > +			     offsetof(typeof(*entry), __str_data);	       \
> > > +	__str_size += strlen(src) + 1;
> > > +
> > > +#undef __assign_str
> > > +#define __assign_str(dst, src)						\
> > > +	__entry->__str_loc_##dst = __str_offsets.dst;			\
> > > +	strcpy(__get_str(dst), src);
> > > +
> > >  #undef TRACE_EVENT
> > >  #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
> > >  _TRACE_PROFILE(call, PARAMS(proto), PARAMS(args))			\
> > > @@ -417,18 +495,22 @@ static struct ftrace_event_call event_##call;				\
> > >  									\
> > >  static void ftrace_raw_event_##call(proto)				\
> > >  {									\
> > > +	struct ftrace_str_offsets_##call __maybe_unused __str_offsets;  \
> > >  	struct ftrace_event_call *call = &event_##call;			\
> > >  	struct ring_buffer_event *event;				\
> > >  	struct ftrace_raw_##call *entry;				\
> > >  	unsigned long irq_flags;					\
> > > +	int __str_size = 0;						\
> > >  	int pc;								\
> > >  									\
> > >  	local_save_flags(irq_flags);					\
> > >  	pc = preempt_count();						\
> > >  									\
> > > +	tstruct;							\
> > > +									\
> > >  	event = trace_current_buffer_lock_reserve(event_##call.id,	\
> > > -				  sizeof(struct ftrace_raw_##call),	\
> > > -				  irq_flags, pc);			\
> > > +				 sizeof(struct ftrace_raw_##call) + __str_size,\
> > > +				 irq_flags, pc);			\
> > >  	if (!event)							\
> > >  		return;							\
> > >  	entry	= ring_buffer_event_data(event);			\
> > > -- 
> > > 1.6.1
> > 
> > Other than my comment above...
> > 
> > Acked-by: Steven Rostedt <rostedt@goodmis.org>
> 
> Actually I looked at this code deeper than an Ack.
> 
> Reviewed-by: Steven Rostedt <rostedt@goodmis.org>


Thanks!
Then, may be I should wait for Ingo's pull (if he accepts)
before sending a delta to add the parenthesis around __get_str().

Frederic.

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Steven Rostedt]

On Wed, 22 Apr 2009, Frederic Weisbecker wrote:
> 
> 
> Thanks!
> Then, may be I should wait for Ingo's pull (if he accepts)
> before sending a delta to add the parenthesis around __get_str().

It would probably be better to just make the fix now. Just put the fix in 
a separate branch to avoid race conditions (if Ingo already did a pull ;-)

-- Steve

[PATCH][GIT-PULL] tracing/events: protect __get_str()

[Frederic Weisbecker]

On Tue, Apr 21, 2009 at 06:21:54PM -0400, Steven Rostedt wrote:
> It would probably be better to just make the fix now. Just put the fix in 
> a separate branch to avoid race conditions (if Ingo already did a pull ;-)
> 
> -- Steve


Ok, so this new pull request includes the patches in the previous
request + your Reviewed/Acked-by + the fix on __get_str() which
I pasted below. It's also a rebase against latest tip/tracing/core.

Thanks.

The following changes since commit 3554228d4289098a8fe5cfd87512ec32a19bbe5a:
  Steven Rostedt (1):
        ring-buffer: only warn on wrap if buffer is bigger than two pages

are available in the git repository at:

  git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git tracing/core-v2

Frederic Weisbecker (3):
      tracing/events: provide string with undefined size support
      tracing/lock: provide lock_acquired event support for dynamic size string
      tracing/events: protect __get_str()

 include/trace/events/lockdep.h |    6 +-
 include/trace/ftrace.h         |   88 ++++++++++++++++++++++++++++++++++++++-
 2 files changed, 88 insertions(+), 6 deletions(-)
---
>From 94be8f865ac6887e79cd38302d707f5536e377fe Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <fweisbec@gmail.com>
Date: Wed, 22 Apr 2009 00:41:09 +0200
Subject: [PATCH] tracing/events: protect __get_str()

The __get_str() macro is used in a code part then its content should be
protected with parenthesis.

[ Impact: protect macro content ]

Reported-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 include/trace/ftrace.h |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 353b7db..019cc5d 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -123,7 +123,7 @@
 #define TP_printk(fmt, args...) fmt "\n", args
 
 #undef __get_str
-#define __get_str(field)	(char *)__entry + __entry->__str_loc_##field
+#define __get_str(field)	((char *)__entry + __entry->__str_loc_##field)
 
 #undef TRACE_EVENT
 #define TRACE_EVENT(call, proto, args, tstruct, assign, print)		\
-- 
1.6.2.3

Re: [PATCH][GIT-PULL] tracing/events: protect __get_str()

[Ingo Molnar]

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

> On Tue, Apr 21, 2009 at 06:21:54PM -0400, Steven Rostedt wrote:
> > It would probably be better to just make the fix now. Just put the fix in 
> > a separate branch to avoid race conditions (if Ingo already did a pull ;-)
> > 
> > -- Steve
> 
> 
> Ok, so this new pull request includes the patches in the previous
> request + your Reviewed/Acked-by + the fix on __get_str() which
> I pasted below. It's also a rebase against latest tip/tracing/core.
> 
> Thanks.
> 
> The following changes since commit 3554228d4289098a8fe5cfd87512ec32a19bbe5a:
>   Steven Rostedt (1):
>         ring-buffer: only warn on wrap if buffer is bigger than two pages
> 
> are available in the git repository at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git tracing/core-v2
> 
> Frederic Weisbecker (3):
>       tracing/events: provide string with undefined size support
>       tracing/lock: provide lock_acquired event support for dynamic size string
>       tracing/events: protect __get_str()
> 
>  include/trace/events/lockdep.h |    6 +-
>  include/trace/ftrace.h         |   88 ++++++++++++++++++++++++++++++++++++++-
>  2 files changed, 88 insertions(+), 6 deletions(-)

Pulled, thanks Frederic!

	Ingo

Re: [PATCH 1/2 v3] tracing/events: provide string with undefined size support

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 22 Apr 2009, Frederic Weisbecker wrote:
>
> > Thanks!
> > Then, may be I should wait for Ingo's pull (if he accepts)
> > before sending a delta to add the parenthesis around __get_str().
> 
> It would probably be better to just make the fix now. Just put the 
> fix in a separate branch to avoid race conditions (if Ingo already 
> did a pull ;-)

Yeah - doing a -v2 (-v3, -v4 ;-) COW branch and then removing them 
once they served their purpose does the trick here.

While i generally dont get surprised (negatively ;) by seeing more 
(or less) stuff in a branch than expected from the pull request (i 
review it all anyway), it's good to practice the COW pull workflow 
so that if you send stuff to Linus or others who expect COW there's 
no mistakes.

	Ingo

[PATCH 2/2 v3] tracing/lock: provide lock_acquired event support for dynamic size string

[Frederic Weisbecker]

Now that we can support the dynamic sized string, make the lock tracing
able to use it, making it safe against modules removal and consuming
the right amount of memory needed for each lock name

Changes in v2:
adapt to the __ending_string() updates and the opening_string() removal.

[ Impact: protect against module removal ]

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/lockdep.h |    6 +++---
 1 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/include/trace/events/lockdep.h b/include/trace/events/lockdep.h
index 45e326b..3ca315c 100644
--- a/include/trace/events/lockdep.h
+++ b/include/trace/events/lockdep.h
@@ -38,16 +38,16 @@ TRACE_EVENT(lock_acquired,
 	TP_ARGS(lock, ip, waittime),
 
 	TP_STRUCT__entry(
-		__field(const char *, name)
+		__string(name, lock->name)
 		__field(unsigned long, wait_usec)
 		__field(unsigned long, wait_nsec_rem)
 	),
 	TP_fast_assign(
-		__entry->name = lock->name;
+		__assign_str(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,
+	TP_printk("%s (%lu.%03lu us)", __get_str(name), __entry->wait_usec,
 				       __entry->wait_nsec_rem)
 );
 
-- 
1.6.1

Re: [PATCH 2/2 v3] tracing/lock: provide lock_acquired event support for dynamic size string

[Steven Rostedt]

On Sun, 19 Apr 2009, Frederic Weisbecker wrote:

> Now that we can support the dynamic sized string, make the lock tracing
> able to use it, making it safe against modules removal and consuming
> the right amount of memory needed for each lock name
> 
> Changes in v2:
> adapt to the __ending_string() updates and the opening_string() removal.
> 
> [ Impact: protect against module removal ]
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> ---
>  include/trace/events/lockdep.h |    6 +++---
>  1 files changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/include/trace/events/lockdep.h b/include/trace/events/lockdep.h
> index 45e326b..3ca315c 100644
> --- a/include/trace/events/lockdep.h
> +++ b/include/trace/events/lockdep.h
> @@ -38,16 +38,16 @@ TRACE_EVENT(lock_acquired,
>  	TP_ARGS(lock, ip, waittime),
>  
>  	TP_STRUCT__entry(
> -		__field(const char *, name)
> +		__string(name, lock->name)
>  		__field(unsigned long, wait_usec)
>  		__field(unsigned long, wait_nsec_rem)
>  	),
>  	TP_fast_assign(
> -		__entry->name = lock->name;
> +		__assign_str(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,
> +	TP_printk("%s (%lu.%03lu us)", __get_str(name), __entry->wait_usec,
>  				       __entry->wait_nsec_rem)
>  );

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

Re: [PATCH 0/2 v3] [GIT PULL] tracing/events: add the __string field

[Li Zefan]

Frederic Weisbecker wrote:
> Hi,
> 
> Here is the v3 of the __string() field patchset.
> It applies suggestions from Steven and Peter with some arrangements.
> 
> This time, filtering is not supported (though it is ready in a pending patch).
> I wanted to provide it but it looks like filtering has been broken recently.
> Once I set a usual string filter, no more traces appear, and clearing it
> doesn't change anything.
> 

I tried it, and triggered a WARNING, and ring buffers was
disabled permanently:

------------[ cut here ]------------
WARNING: at kernel/trace/ring_buffer.c:1501 ring_buffer_lock_reserve+0x78/0x122()
Hardware name: Aspire SA85
Modules linked in: autofs4 parport_pc parport button sg r8169 mii sata_sis pata_sis ata_generic libata sd_mod scsi_mod ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd [last unloaded: scsi_wait_scan]
Pid: 0, comm: swapper Not tainted 2.6.30-rc2-tip #84
Call Trace:
 [<c0431d8d>] warn_slowpath+0x79/0x8f
 [<c0468379>] ? __rcu_read_unlock+0x70/0x7f
 [<c045022b>] ? trace_hardirqs_off+0xb/0xd
 [<c0468379>] ? __rcu_read_unlock+0x70/0x7f
 [<c045022b>] ? trace_hardirqs_off+0xb/0xd
 [<c0468379>] ? __rcu_read_unlock+0x70/0x7f
 [<c063784b>] ? _spin_unlock_irqrestore+0x34/0x5d
 [<c0450200>] ? trace_hardirqs_off_caller+0x8f/0xaf
 [<c04718fa>] ring_buffer_lock_reserve+0x78/0x122
 [<c0473f17>] trace_buffer_lock_reserve+0x11/0x34
 [<c0474399>] trace_current_buffer_lock_reserve+0x19/0x1e
 [<c0465299>] ftrace_raw_event_irq_handler_exit+0x34/0x73
 [<c0464fdb>] handle_IRQ_event+0xcc/0x169
 [<c0466bc0>] handle_fasteoi_irq+0x77/0xb0
 [<c0466b49>] ? handle_fasteoi_irq+0x0/0xb0
 <IRQ>  [<c0637d76>] ? do_IRQ+0x4e/0xa3
 [<c04030ee>] ? common_interrupt+0x2e/0x34
 [<c045007b>] ? lockdep_init_map+0x2d5/0x39f
 [<c04092b3>] ? mwait_idle+0xab/0x100
 [<c0401b4e>] ? cpu_idle+0x53/0x85
 [<c0631fb5>] ? start_secondary+0x1aa/0x1b1
---[ end trace ab1a6955379aeb3f ]---

Re: [PATCH 0/2 v3] [GIT PULL] tracing/events: add the __string field

[Frederic Weisbecker]

On Sun, Apr 19, 2009 at 02:14:54PM +0800, Li Zefan wrote:
> Frederic Weisbecker wrote:
> > Hi,
> > 
> > Here is the v3 of the __string() field patchset.
> > It applies suggestions from Steven and Peter with some arrangements.
> > 
> > This time, filtering is not supported (though it is ready in a pending patch).
> > I wanted to provide it but it looks like filtering has been broken recently.
> > Once I set a usual string filter, no more traces appear, and clearing it
> > doesn't change anything.
> > 
> 
> I tried it, and triggered a WARNING, and ring buffers was
> disabled permanently:


I've also seen this warning but on another event.
I don't think this is related to this patchset but
more about the tracing recursion detection.

For exemple, here we are in an Irq event, which doesn't
use the __string() thing. For such off-case, the only change
is a variable declaration and a + 0 operation.

Another thing: I've only seen it in a selftest.

I will investigate.
Thanks.

Frederic.


> 
> ------------[ cut here ]------------
> WARNING: at kernel/trace/ring_buffer.c:1501 ring_buffer_lock_reserve+0x78/0x122()
> Hardware name: Aspire SA85
> Modules linked in: autofs4 parport_pc parport button sg r8169 mii sata_sis pata_sis ata_generic libata sd_mod scsi_mod ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd [last unloaded: scsi_wait_scan]
> Pid: 0, comm: swapper Not tainted 2.6.30-rc2-tip #84
> Call Trace:
>  [<c0431d8d>] warn_slowpath+0x79/0x8f
>  [<c0468379>] ? __rcu_read_unlock+0x70/0x7f
>  [<c045022b>] ? trace_hardirqs_off+0xb/0xd
>  [<c0468379>] ? __rcu_read_unlock+0x70/0x7f
>  [<c045022b>] ? trace_hardirqs_off+0xb/0xd
>  [<c0468379>] ? __rcu_read_unlock+0x70/0x7f
>  [<c063784b>] ? _spin_unlock_irqrestore+0x34/0x5d
>  [<c0450200>] ? trace_hardirqs_off_caller+0x8f/0xaf
>  [<c04718fa>] ring_buffer_lock_reserve+0x78/0x122
>  [<c0473f17>] trace_buffer_lock_reserve+0x11/0x34
>  [<c0474399>] trace_current_buffer_lock_reserve+0x19/0x1e
>  [<c0465299>] ftrace_raw_event_irq_handler_exit+0x34/0x73
>  [<c0464fdb>] handle_IRQ_event+0xcc/0x169
>  [<c0466bc0>] handle_fasteoi_irq+0x77/0xb0
>  [<c0466b49>] ? handle_fasteoi_irq+0x0/0xb0
>  <IRQ>  [<c0637d76>] ? do_IRQ+0x4e/0xa3
>  [<c04030ee>] ? common_interrupt+0x2e/0x34
>  [<c045007b>] ? lockdep_init_map+0x2d5/0x39f
>  [<c04092b3>] ? mwait_idle+0xab/0x100
>  [<c0401b4e>] ? cpu_idle+0x53/0x85
>  [<c0631fb5>] ? start_secondary+0x1aa/0x1b1
> ---[ end trace ab1a6955379aeb3f ]---
> 
> 

[PATCH] tracing/core: Add current context on tracing recursion warning

[Frederic Weisbecker]

On Sun, Apr 19, 2009 at 02:34:32PM +0200, Frederic Weisbecker wrote:
> On Sun, Apr 19, 2009 at 02:14:54PM +0800, Li Zefan wrote:
> > Frederic Weisbecker wrote:
> > > Hi,
> > > 
> > > Here is the v3 of the __string() field patchset.
> > > It applies suggestions from Steven and Peter with some arrangements.
> > > 
> > > This time, filtering is not supported (though it is ready in a pending patch).
> > > I wanted to provide it but it looks like filtering has been broken recently.
> > > Once I set a usual string filter, no more traces appear, and clearing it
> > > doesn't change anything.
> > > 
> > 
> > I tried it, and triggered a WARNING, and ring buffers was
> > disabled permanently:
> 
> 
> I've also seen this warning but on another event.
> I don't think this is related to this patchset but
> more about the tracing recursion detection.
> 
> For exemple, here we are in an Irq event, which doesn't
> use the __string() thing. For such off-case, the only change
> is a variable declaration and a + 0 operation.
> 
> Another thing: I've only seen it in a selftest.


Worst: I can't reproduce it anymore.
What were you doing when you got such warning? Were you
in a selftest, or trying a usual event?

Also, could you test the following patch. It will give us
more informations about the tracing recursion.

You can find it on:

git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing tracing/recursion

It's against tip/tracing/core

Thanks!

---
>From d13bf59ca011b976c561f623e3189a4a5b94370e Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <fweisbec@gmail.com>
Date: Sun, 19 Apr 2009 15:30:19 +0200
Subject: [PATCH] tracing/core: Add current context on tracing recursion warning

In case of tracing recursion detection, we only get the stacktrace.
But the current context may be very useful to debug the issue.

This patch adds the softirq/hardirq/nmi context with the warning
using lockdep context display to have a familiar output.

[ Impact: more information in tracing recursion ]

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/trace/ring_buffer.c |   13 +++++++++++++
 1 files changed, 13 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index b421b0e..27a6e7d 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -1493,8 +1493,21 @@ static int trace_recursive_lock(void)
 	level = trace_irq_level();
 
 	if (unlikely(current->trace_recursion & (1 << level))) {
+		static atomic_t warned;
+
 		/* Disable all tracing before we do anything else */
 		tracing_off_permanent();
+
+		if (atomic_inc_return(&warned) == 1) {
+			printk(KERN_WARNING "Tracing recursion: "
+				"[HC%u[%lu]:SC%u[%lu]:NMI[%lu]:HE%u:SE%u]\n",
+				current->hardirq_context,
+				hardirq_count() >> HARDIRQ_SHIFT,
+				current->softirq_context,
+				softirq_count() >> SOFTIRQ_SHIFT,
+				in_nmi(), current->hardirqs_enabled,
+				current->softirqs_enabled);
+		}
 		WARN_ON_ONCE(1);
 		return -1;
 	}
-- 
1.6.1

Re: [PATCH] tracing/core: Add current context on tracing recursion warning

[Ingo Molnar]

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

> On Sun, Apr 19, 2009 at 02:34:32PM +0200, Frederic Weisbecker wrote:
> > On Sun, Apr 19, 2009 at 02:14:54PM +0800, Li Zefan wrote:
> > > Frederic Weisbecker wrote:
> > > > Hi,
> > > > 
> > > > Here is the v3 of the __string() field patchset.
> > > > It applies suggestions from Steven and Peter with some arrangements.
> > > > 
> > > > This time, filtering is not supported (though it is ready in a pending patch).
> > > > I wanted to provide it but it looks like filtering has been broken recently.
> > > > Once I set a usual string filter, no more traces appear, and clearing it
> > > > doesn't change anything.
> > > > 
> > > 
> > > I tried it, and triggered a WARNING, and ring buffers was
> > > disabled permanently:
> > 
> > 
> > I've also seen this warning but on another event.
> > I don't think this is related to this patchset but
> > more about the tracing recursion detection.
> > 
> > For exemple, here we are in an Irq event, which doesn't
> > use the __string() thing. For such off-case, the only change
> > is a variable declaration and a + 0 operation.
> > 
> > Another thing: I've only seen it in a selftest.
> 
> 
> Worst: I can't reproduce it anymore.
> What were you doing when you got such warning? Were you
> in a selftest, or trying a usual event?
> 
> Also, could you test the following patch. It will give us
> more informations about the tracing recursion.
> 
> You can find it on:
> 
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing tracing/recursion
> 
> It's against tip/tracing/core
> 
> Thanks!
> 
> ---
> >From d13bf59ca011b976c561f623e3189a4a5b94370e Mon Sep 17 00:00:00 2001
> From: Frederic Weisbecker <fweisbec@gmail.com>
> Date: Sun, 19 Apr 2009 15:30:19 +0200
> Subject: [PATCH] tracing/core: Add current context on tracing recursion warning

> 
> In case of tracing recursion detection, we only get the stacktrace.
> But the current context may be very useful to debug the issue.
> 
> This patch adds the softirq/hardirq/nmi context with the warning
> using lockdep context display to have a familiar output.
> 
> [ Impact: more information in tracing recursion ]
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/trace/ring_buffer.c |   13 +++++++++++++
>  1 files changed, 13 insertions(+), 0 deletions(-)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index b421b0e..27a6e7d 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -1493,8 +1493,21 @@ static int trace_recursive_lock(void)
>  	level = trace_irq_level();
>  
>  	if (unlikely(current->trace_recursion & (1 << level))) {
> +		static atomic_t warned;
> +
>  		/* Disable all tracing before we do anything else */
>  		tracing_off_permanent();
> +
> +		if (atomic_inc_return(&warned) == 1) {
> +			printk(KERN_WARNING "Tracing recursion: "
> +				"[HC%u[%lu]:SC%u[%lu]:NMI[%lu]:HE%u:SE%u]\n",
> +				current->hardirq_context,
> +				hardirq_count() >> HARDIRQ_SHIFT,
> +				current->softirq_context,
> +				softirq_count() >> SOFTIRQ_SHIFT,
> +				in_nmi(), current->hardirqs_enabled,
> +				current->softirqs_enabled);
> +		}

It would be nice to have this ... but there's no need to do that 
atomic thing - just use printk_once() please. (if we race with 
another instance and get two messages that's not a problem)

	Ingo

Re: [PATCH] tracing/core: Add current context on tracing recursion warning

[Frederic Weisbecker]

On Sun, Apr 19, 2009 at 04:01:54PM +0200, Ingo Molnar wrote:
> It would be nice to have this ... but there's no need to do that 
> atomic thing - just use printk_once() please. (if we race with 
> another instance and get two messages that's not a problem)
> 
> 	Ingo


Ah, indeed I forgot about printk_once()
I've updated the repo with the following v2 on:
git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing tracing/recursion

---
>From e894732989e345ea012de146c37d71dd7ed3575d Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <fweisbec@gmail.com>
Date: Sun, 19 Apr 2009 16:18:16 +0200
Subject: [PATCH v2] tracing/core: Add current context on tracing recursion warning

In case of tracing recursion detection, we only get the stacktrace.
But the current context may be very useful to debug the issue.

This patch adds the softirq/hardirq/nmi context with the warning
using lockdep context display to have a familiar output.

v2: Use printk_once()

[ Impact: more information in tracing recursion ]

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/trace/ring_buffer.c |   10 ++++++++++
 1 files changed, 10 insertions(+), 0 deletions(-)

diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
index b421b0e..e315178 100644
--- a/kernel/trace/ring_buffer.c
+++ b/kernel/trace/ring_buffer.c
@@ -1495,6 +1495,16 @@ static int trace_recursive_lock(void)
 	if (unlikely(current->trace_recursion & (1 << level))) {
 		/* Disable all tracing before we do anything else */
 		tracing_off_permanent();
+
+		printk_once(KERN_WARNING "Tracing recursion: "
+			    "[HC%u[%lu]:SC%u[%lu]:NMI[%lu]:HE%u:SE%u]\n",
+			    current->hardirq_context,
+			    hardirq_count() >> HARDIRQ_SHIFT,
+			    current->softirq_context,
+			    softirq_count() >> SOFTIRQ_SHIFT,
+			    in_nmi(), current->hardirqs_enabled,
+			    current->softirqs_enabled);
+
 		WARN_ON_ONCE(1);
 		return -1;
 	}
-- 
1.6.1

Re: [PATCH] tracing/core: Add current context on tracing recursion warning

[Ingo Molnar]

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

> On Sun, Apr 19, 2009 at 04:01:54PM +0200, Ingo Molnar wrote:
> > It would be nice to have this ... but there's no need to do that 
> > atomic thing - just use printk_once() please. (if we race with 
> > another instance and get two messages that's not a problem)
> > 
> > 	Ingo
> 
> 
> Ah, indeed I forgot about printk_once()
> I've updated the repo with the following v2 on:
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing tracing/recursion
> 
> ---
> >From e894732989e345ea012de146c37d71dd7ed3575d Mon Sep 17 00:00:00 2001
> From: Frederic Weisbecker <fweisbec@gmail.com>
> Date: Sun, 19 Apr 2009 16:18:16 +0200
> Subject: [PATCH v2] tracing/core: Add current context on tracing recursion warning

> 
> In case of tracing recursion detection, we only get the stacktrace.
> But the current context may be very useful to debug the issue.
> 
> This patch adds the softirq/hardirq/nmi context with the warning
> using lockdep context display to have a familiar output.
> 
> v2: Use printk_once()
> 
> [ Impact: more information in tracing recursion ]
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/trace/ring_buffer.c |   10 ++++++++++
>  1 files changed, 10 insertions(+), 0 deletions(-)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index b421b0e..e315178 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -1495,6 +1495,16 @@ static int trace_recursive_lock(void)
>  	if (unlikely(current->trace_recursion & (1 << level))) {
>  		/* Disable all tracing before we do anything else */
>  		tracing_off_permanent();
> +
> +		printk_once(KERN_WARNING "Tracing recursion: "
> +			    "[HC%u[%lu]:SC%u[%lu]:NMI[%lu]:HE%u:SE%u]\n",
> +			    current->hardirq_context,
> +			    hardirq_count() >> HARDIRQ_SHIFT,
> +			    current->softirq_context,
> +			    softirq_count() >> SOFTIRQ_SHIFT,
> +			    in_nmi(), current->hardirqs_enabled,
> +			    current->softirqs_enabled);
> +
>  		WARN_ON_ONCE(1);

Pulled, thanks Frederic!

btw., we might have done it via:

	if (WARN_ON_ONCE(1)) {
		printk(...);
	}

as well ... but i have not checked how WARN_ON_ONCE() return value 
behaves after the first warning - does it return true or false?

	Ingo

Re: [PATCH] tracing/core: Add current context on tracing recursion warning

[Frédéric Weisbecker]

2009/4/19 Ingo Molnar <mingo@elte.hu>:
>
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
>> On Sun, Apr 19, 2009 at 04:01:54PM +0200, Ingo Molnar wrote:
>> > It would be nice to have this ... but there's no need to do that
>> > atomic thing - just use printk_once() please. (if we race with
>> > another instance and get two messages that's not a problem)
>> >
>> >     Ingo
>>
>>
>> Ah, indeed I forgot about printk_once()
>> I've updated the repo with the following v2 on:
>> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing tracing/recursion
>>
>> ---
>> >From e894732989e345ea012de146c37d71dd7ed3575d Mon Sep 17 00:00:00 2001
>> From: Frederic Weisbecker <fweisbec@gmail.com>
>> Date: Sun, 19 Apr 2009 16:18:16 +0200
>> Subject: [PATCH v2] tracing/core: Add current context on tracing recursion warning
>
>>
>> In case of tracing recursion detection, we only get the stacktrace.
>> But the current context may be very useful to debug the issue.
>>
>> This patch adds the softirq/hardirq/nmi context with the warning
>> using lockdep context display to have a familiar output.
>>
>> v2: Use printk_once()
>>
>> [ Impact: more information in tracing recursion ]
>>
>> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
>> ---
>>  kernel/trace/ring_buffer.c |   10 ++++++++++
>>  1 files changed, 10 insertions(+), 0 deletions(-)
>>
>> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
>> index b421b0e..e315178 100644
>> --- a/kernel/trace/ring_buffer.c
>> +++ b/kernel/trace/ring_buffer.c
>> @@ -1495,6 +1495,16 @@ static int trace_recursive_lock(void)
>>       if (unlikely(current->trace_recursion & (1 << level))) {
>>               /* Disable all tracing before we do anything else */
>>               tracing_off_permanent();
>> +
>> +             printk_once(KERN_WARNING "Tracing recursion: "
>> +                         "[HC%u[%lu]:SC%u[%lu]:NMI[%lu]:HE%u:SE%u]\n",
>> +                         current->hardirq_context,
>> +                         hardirq_count() >> HARDIRQ_SHIFT,
>> +                         current->softirq_context,
>> +                         softirq_count() >> SOFTIRQ_SHIFT,
>> +                         in_nmi(), current->hardirqs_enabled,
>> +                         current->softirqs_enabled);
>> +
>>               WARN_ON_ONCE(1);
>
> Pulled, thanks Frederic!
>
> btw., we might have done it via:
>
>        if (WARN_ON_ONCE(1)) {
>                printk(...);
>        }
>
> as well ... but i have not checked how WARN_ON_ONCE() return value
> behaves after the first warning - does it return true or false?



I've checked it because I wanted to do that first :-)
It returns always 1 if the condition is true, not only once.

Btw, I've found the origin of the warning.
We drop the recursion protection on commit but not on discard.

Preparing a patch.


>        Ingo
>

Re: [PATCH] tracing/core: Add current context on tracing recursion warning

[Ingo Molnar]

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

> [ Impact: more information in tracing recursion ]

Small sidenote for next time around: please always try to use a verb 
in impact lines. So this:

> [ Impact: print more information when tracing recurses ]

would have been a better one. (But the above one is unambigous as 
well at a second glance - so no need to redo the commit.)

	Ingo

Re: [PATCH] tracing/core: Add current context on tracing recursion warning

[Frederic Weisbecker]

On Sun, Apr 19, 2009 at 03:49:28PM +0200, Frederic Weisbecker wrote:
> On Sun, Apr 19, 2009 at 02:34:32PM +0200, Frederic Weisbecker wrote:
> > On Sun, Apr 19, 2009 at 02:14:54PM +0800, Li Zefan wrote:
> > > Frederic Weisbecker wrote:
> > > > Hi,
> > > > 
> > > > Here is the v3 of the __string() field patchset.
> > > > It applies suggestions from Steven and Peter with some arrangements.
> > > > 
> > > > This time, filtering is not supported (though it is ready in a pending patch).
> > > > I wanted to provide it but it looks like filtering has been broken recently.
> > > > Once I set a usual string filter, no more traces appear, and clearing it
> > > > doesn't change anything.
> > > > 
> > > 
> > > I tried it, and triggered a WARNING, and ring buffers was
> > > disabled permanently:
> > 
> > 
> > I've also seen this warning but on another event.
> > I don't think this is related to this patchset but
> > more about the tracing recursion detection.
> > 
> > For exemple, here we are in an Irq event, which doesn't
> > use the __string() thing. For such off-case, the only change
> > is a variable declaration and a + 0 operation.
> > 
> > Another thing: I've only seen it in a selftest.
> 
> 
> Worst: I can't reproduce it anymore.
> What were you doing when you got such warning? Were you
> in a selftest, or trying a usual event?



Now I can reproduce it. It seems to happen when I set a filter,
but also on other situations:

Bisected back to:

commit 261842b7c9099f56de2eb969c8ad65402d68e00e
tracing: add same level recursion detection

It might be caused by a bug in this patch or
by real tracing recursions on some places.

Another example:

111.119821] ------------[ cut here ]------------
[  111.119829] WARNING: at kernel/trace/ring_buffer.c:1498 ring_buffer_lock_reserve+0x1b7/0x1d0()
[  111.119835] Hardware name: AMILO Li 2727                  
[  111.119839] Modules linked in:
[  111.119846] Pid: 5731, comm: Xorg Tainted: G        W  2.6.30-rc1 #69
[  111.119851] Call Trace:
[  111.119863]  [<ffffffff8025ce68>] warn_slowpath+0xd8/0x130
[  111.119873]  [<ffffffff8028a30f>] ? __lock_acquire+0x19f/0x1ae0
[  111.119882]  [<ffffffff8028a30f>] ? __lock_acquire+0x19f/0x1ae0
[  111.119891]  [<ffffffff802199b0>] ? native_sched_clock+0x20/0x70
[  111.119899]  [<ffffffff80286dee>] ? put_lock_stats+0xe/0x30
[  111.119906]  [<ffffffff80286eb8>] ? lock_release_holdtime+0xa8/0x150
[  111.119913]  [<ffffffff802c8ae7>] ring_buffer_lock_reserve+0x1b7/0x1d0
[  111.119921]  [<ffffffff802cd110>] trace_buffer_lock_reserve+0x30/0x70
[  111.119930]  [<ffffffff802ce000>] trace_current_buffer_lock_reserve+0x20/0x30
[  111.119939]  [<ffffffff802474e8>] ftrace_raw_event_sched_switch+0x58/0x100
[  111.119948]  [<ffffffff808103b7>] __schedule+0x3a7/0x4cd
[  111.119957]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.119964]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.119971]  [<ffffffff80810c08>] schedule+0x18/0x40
[  111.119977]  [<ffffffff80810e09>] preempt_schedule+0x39/0x60
[  111.119985]  [<ffffffff80813bd3>] _read_unlock+0x53/0x60
[  111.119993]  [<ffffffff807259d2>] sock_def_readable+0x72/0x80
[  111.120002]  [<ffffffff807ad5ed>] unix_stream_sendmsg+0x24d/0x3d0
[  111.120011]  [<ffffffff807219a3>] sock_aio_write+0x143/0x160
[  111.120019]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.120026]  [<ffffffff80721860>] ? sock_aio_write+0x0/0x160
[  111.120033]  [<ffffffff80721860>] ? sock_aio_write+0x0/0x160
[  111.120042]  [<ffffffff8031c283>] do_sync_readv_writev+0xf3/0x140
[  111.120049]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.120057]  [<ffffffff80276ff0>] ? autoremove_wake_function+0x0/0x40
[  111.120067]  [<ffffffff8045d489>] ? cap_file_permission+0x9/0x10
[  111.120074]  [<ffffffff8045c1e6>] ? security_file_permission+0x16/0x20
[  111.120082]  [<ffffffff8031cab4>] do_readv_writev+0xd4/0x1f0
[  111.120089]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.120097]  [<ffffffff80211b56>] ? ftrace_call+0x5/0x2b
[  111.120105]  [<ffffffff8031cc18>] vfs_writev+0x48/0x70
[  111.120111]  [<ffffffff8031cd65>] sys_writev+0x55/0xc0
[  111.120119]  [<ffffffff80211e32>] system_call_fastpath+0x16/0x1b
[  111.120125] ---[ end trace 15605f4e98d5ccb5 ]---


Frederic.

 
> Also, could you test the following patch. It will give us
> more informations about the tracing recursion.
> 
> You can find it on:
> 
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing tracing/recursion
> 
> It's against tip/tracing/core
> 
> Thanks!
> 
> ---
> From d13bf59ca011b976c561f623e3189a4a5b94370e Mon Sep 17 00:00:00 2001
> From: Frederic Weisbecker <fweisbec@gmail.com>
> Date: Sun, 19 Apr 2009 15:30:19 +0200
> Subject: [PATCH] tracing/core: Add current context on tracing recursion warning
> 
> In case of tracing recursion detection, we only get the stacktrace.
> But the current context may be very useful to debug the issue.
> 
> This patch adds the softirq/hardirq/nmi context with the warning
> using lockdep context display to have a familiar output.
> 
> [ Impact: more information in tracing recursion ]
> 
> Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
> ---
>  kernel/trace/ring_buffer.c |   13 +++++++++++++
>  1 files changed, 13 insertions(+), 0 deletions(-)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index b421b0e..27a6e7d 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -1493,8 +1493,21 @@ static int trace_recursive_lock(void)
>  	level = trace_irq_level();
>  
>  	if (unlikely(current->trace_recursion & (1 << level))) {
> +		static atomic_t warned;
> +
>  		/* Disable all tracing before we do anything else */
>  		tracing_off_permanent();
> +
> +		if (atomic_inc_return(&warned) == 1) {
> +			printk(KERN_WARNING "Tracing recursion: "
> +				"[HC%u[%lu]:SC%u[%lu]:NMI[%lu]:HE%u:SE%u]\n",
> +				current->hardirq_context,
> +				hardirq_count() >> HARDIRQ_SHIFT,
> +				current->softirq_context,
> +				softirq_count() >> SOFTIRQ_SHIFT,
> +				in_nmi(), current->hardirqs_enabled,
> +				current->softirqs_enabled);
> +		}
>  		WARN_ON_ONCE(1);
>  		return -1;
>  	}
> -- 
> 1.6.1
> 
> 

Re: [PATCH] tracing/core: Add current context on tracing recursion warning

[Li Zefan]

> Now I can reproduce it. It seems to happen when I set a filter,

Right, you said filter seems to be broken, so I tried to set a filter
and enabled the trace event, and got this warning.

> but also on other situations:
> 
> Bisected back to:
> 
> commit 261842b7c9099f56de2eb969c8ad65402d68e00e
> tracing: add same level recursion detection
> 
> It might be caused by a bug in this patch or
> by real tracing recursions on some places.