[PATCH 0/3] tracing: fix macro expansion and refactor some of dynamic_array support

[PATCH 0/3] tracing: fix macro expansion and refactor some of dynamic_array support

[Filipe Brandenburger]

Hi Steven Rostedt, Li Zefan,

This fixes an issue with macro expansion introduced in commit 7d536cb3f
(tracing/events: record the size of dynamic arrays).

I split it in 3 patches, the first fixes a bug, the second improves the code to
evaluate the expression only once and the third refactors an u32 holding two
pieces of data in lower/higher 16 bits into a struct to make the code cleaner.

I split them this way since I expect the first two to be more straightforward
while the third one might generate some discussion. I'd be happy to squash them
into a single one if you'd prefer that.

Cheers,
Filipe


Filipe Brandenburger (3):
  tracing: correctly expand len expressions from __dynamic_array macro
  tracing: evaluate len expression only once in __dynamic_array macro
  tracing: introduce a trace_data_offset struct to store array size

 include/linux/ftrace_event.h       |  5 +++++
 include/trace/ftrace.h             | 26 ++++++++++++++------------
 kernel/trace/trace_events_filter.c | 13 ++++++++++---
 3 files changed, 29 insertions(+), 15 deletions(-)

-- 
1.9.0.279.gdc9e3eb

[PATCH 1/3] tracing: correctly expand len expressions from __dynamic_array macro

[Filipe Brandenburger]

This fixes expansion of the len argument in __dynamic_array macros.
The previous code from commit 7d536cb3f would not fully evaluate the
expression before multiplying its result by the size of the type.

This went unnoticed because the length stored in the high 16 bits of the
offset (which is the one that was broken here) is only used by
filter_pred_strloc which only acts on strings for which the size of the
type is 1.

Signed-off-by: Filipe Brandenburger <filbranden@google.com>
---
 include/trace/ftrace.h | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 1a8b28d..82e8d89 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -375,7 +375,7 @@ ftrace_define_fields_##call(struct ftrace_event_call *event_call)	\
 #define __dynamic_array(type, item, len)				\
 	__data_offsets->item = __data_size +				\
 			       offsetof(typeof(*entry), __data);	\
-	__data_offsets->item |= (len * sizeof(type)) << 16;		\
+	__data_offsets->item |= ((len) * sizeof(type)) << 16;		\
 	__data_size += (len) * sizeof(type);
 
 #undef __string
-- 
1.9.0.279.gdc9e3eb

Re: [PATCH 1/3] tracing: correctly expand len expressions from __dynamic_array macro

[Steven Rostedt]

On Fri, 28 Feb 2014 21:32:16 -0800
Filipe Brandenburger <filbranden@google.com> wrote:

> This fixes expansion of the len argument in __dynamic_array macros.
> The previous code from commit 7d536cb3f would not fully evaluate the
> expression before multiplying its result by the size of the type.
> 
> This went unnoticed because the length stored in the high 16 bits of the
> offset (which is the one that was broken here) is only used by
> filter_pred_strloc which only acts on strings for which the size of the
> type is 1.
> 

Was this visible in any of the tracepoints? Should this be marked for
stable? It's been in the kernel for a long time (2009). Or is a new
tracepoint showing a problem?

-- Steve

> Signed-off-by: Filipe Brandenburger <filbranden@google.com>
> ---
>  include/trace/ftrace.h | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
> index 1a8b28d..82e8d89 100644
> --- a/include/trace/ftrace.h
> +++ b/include/trace/ftrace.h
> @@ -375,7 +375,7 @@ ftrace_define_fields_##call(struct ftrace_event_call *event_call)	\
>  #define __dynamic_array(type, item, len)				\
>  	__data_offsets->item = __data_size +				\
>  			       offsetof(typeof(*entry), __data);	\
> -	__data_offsets->item |= (len * sizeof(type)) << 16;		\
> +	__data_offsets->item |= ((len) * sizeof(type)) << 16;		\
>  	__data_size += (len) * sizeof(type);
>  
>  #undef __string

Re: [PATCH 1/3] tracing: correctly expand len expressions from __dynamic_array macro

[Filipe Brandenburger]

Hi Steve,

I don't think this needs to be backported to stable, since the only
place that uses the high 16 bits of the offset field as the length is
filter_pred_strloc which only works for strings and sizeof(char) == 1
so that essentially whenever the bug is triggered, the actual stored
value is not used.

I have a follow up patch to expose that field to TP_fast_assign (as
something like __get_dynamic_array_length) in which case it's
important that this is fixed, otherwise for __dynamic_array of
something other than char we'll have a bug.

Thanks,
Filipe


On Mon, Mar 3, 2014 at 11:51 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Fri, 28 Feb 2014 21:32:16 -0800
> Filipe Brandenburger <filbranden@google.com> wrote:
>
>> This fixes expansion of the len argument in __dynamic_array macros.
>> The previous code from commit 7d536cb3f would not fully evaluate the
>> expression before multiplying its result by the size of the type.
>>
>> This went unnoticed because the length stored in the high 16 bits of the
>> offset (which is the one that was broken here) is only used by
>> filter_pred_strloc which only acts on strings for which the size of the
>> type is 1.
>>
>
> Was this visible in any of the tracepoints? Should this be marked for
> stable? It's been in the kernel for a long time (2009). Or is a new
> tracepoint showing a problem?
>
> -- Steve
>
>> Signed-off-by: Filipe Brandenburger <filbranden@google.com>
>> ---
>>  include/trace/ftrace.h | 2 +-
>>  1 file changed, 1 insertion(+), 1 deletion(-)
>>
>> diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
>> index 1a8b28d..82e8d89 100644
>> --- a/include/trace/ftrace.h
>> +++ b/include/trace/ftrace.h
>> @@ -375,7 +375,7 @@ ftrace_define_fields_##call(struct ftrace_event_call *event_call) \
>>  #define __dynamic_array(type, item, len)                             \
>>       __data_offsets->item = __data_size +                            \
>>                              offsetof(typeof(*entry), __data);        \
>> -     __data_offsets->item |= (len * sizeof(type)) << 16;             \
>> +     __data_offsets->item |= ((len) * sizeof(type)) << 16;           \
>>       __data_size += (len) * sizeof(type);
>>
>>  #undef __string
>

[PATCH 2/3] tracing: evaluate len expression only once in __dynamic_array macro

[Filipe Brandenburger]

Use a temporary variable to store the expansion of the len expression.
If the evaluation is expensive, this commit will ensure it is evaluated
only once inside ftrace_get_offsets_<call>.

Signed-off-by: Filipe Brandenburger <filbranden@google.com>
---
 include/trace/ftrace.h | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 82e8d89..86a056a 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -373,10 +373,11 @@ ftrace_define_fields_##call(struct ftrace_event_call *event_call)	\
 
 #undef __dynamic_array
 #define __dynamic_array(type, item, len)				\
+	__item_length = (len) * sizeof(type);				\
 	__data_offsets->item = __data_size +				\
 			       offsetof(typeof(*entry), __data);	\
-	__data_offsets->item |= ((len) * sizeof(type)) << 16;		\
-	__data_size += (len) * sizeof(type);
+	__data_offsets->item |= __item_length << 16;			\
+	__data_size += __item_length;
 
 #undef __string
 #define __string(item, src) __dynamic_array(char, item,			\
@@ -388,6 +389,7 @@ static inline notrace int ftrace_get_offsets_##call(			\
 	struct ftrace_data_offsets_##call *__data_offsets, proto)       \
 {									\
 	int __data_size = 0;						\
+	int __maybe_unused __item_length;				\
 	struct ftrace_raw_##call __maybe_unused *entry;			\
 									\
 	tstruct;							\
-- 
1.9.0.279.gdc9e3eb

[PATCH 3/3] tracing: introduce a trace_data_offset struct to store array size

[Filipe Brandenburger]

Commit 7d536cb3f stores the length of the array in the high 16 bits of
the offset field. Using a struct with two separate 16 bit fields makes
it cleaner.

Tested: Boot kernel with this change, set a 'filename ~ "/usr/bin/pst*"'
regex filter on events/sched/sched_process_exec/filter, enabled tracing,
checked that calling pstree would log the trace event as expected.

Signed-off-by: Filipe Brandenburger <filbranden@google.com>
---
 include/linux/ftrace_event.h       |  5 +++++
 include/trace/ftrace.h             | 28 ++++++++++++++--------------
 kernel/trace/trace_events_filter.c | 13 ++++++++++---
 3 files changed, 29 insertions(+), 17 deletions(-)

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index 4e4cc28..67e4122 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -123,6 +123,11 @@ struct trace_event {
 	struct trace_event_functions	*funcs;
 };
 
+struct trace_array_offset {
+	u16			offset;
+	u16			length;
+};
+
 extern int register_ftrace_event(struct trace_event *event);
 extern int unregister_ftrace_event(struct trace_event *event);
 
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 86a056a..eac4d0a 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -48,7 +48,8 @@
 #define __array(type, item, len)	type	item[len];
 
 #undef __dynamic_array
-#define __dynamic_array(type, item, len) u32 __data_loc_##item;
+#define __dynamic_array(type, item, len)				\
+		struct trace_array_offset __data_loc_##item;
 
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
@@ -103,14 +104,14 @@
  * Include the following:
  *
  * struct ftrace_data_offsets_<call> {
- *	u32				<item1>;
- *	u32				<item2>;
+ *	struct trace_array_offset	<item1>;
+ *	struct trace_array_offset	<item2>;
  *	[...]
  * };
  *
- * The __dynamic_array() macro will create each u32 <item>, this is
- * to keep the offset of each array from the beginning of the event.
- * The size of an array is also encoded, in the higher 16 bits of <item>.
+ * The __dynamic_array() macro will create each trace_array_offset <item>, this
+ * is to keep the offset and length of each array from the beginning of the
+ * event.
  */
 
 #undef __field
@@ -123,7 +124,8 @@
 #define __array(type, item, len)
 
 #undef __dynamic_array
-#define __dynamic_array(type, item, len)	u32 item;
+#define __dynamic_array(type, item, len)				\
+		struct trace_array_offset item;
 
 #undef __string
 #define __string(item, src) __dynamic_array(char, item, -1)
@@ -195,7 +197,7 @@
 
 #undef __get_dynamic_array
 #define __get_dynamic_array(field)	\
-		((void *)__entry + (__entry->__data_loc_##field & 0xffff))
+		((void *)__entry + __entry->__data_loc_##field.offset)
 
 #undef __get_str
 #define __get_str(field) (char *)__get_dynamic_array(field)
@@ -373,11 +375,10 @@ ftrace_define_fields_##call(struct ftrace_event_call *event_call)	\
 
 #undef __dynamic_array
 #define __dynamic_array(type, item, len)				\
-	__item_length = (len) * sizeof(type);				\
-	__data_offsets->item = __data_size +				\
+	__data_offsets->item.offset = __data_size +			\
 			       offsetof(typeof(*entry), __data);	\
-	__data_offsets->item |= __item_length << 16;			\
-	__data_size += __item_length;
+	__data_offsets->item.length = (len) * sizeof(type);		\
+	__data_size += __data_offsets->item.length;
 
 #undef __string
 #define __string(item, src) __dynamic_array(char, item,			\
@@ -389,7 +390,6 @@ static inline notrace int ftrace_get_offsets_##call(			\
 	struct ftrace_data_offsets_##call *__data_offsets, proto)       \
 {									\
 	int __data_size = 0;						\
-	int __maybe_unused __item_length;				\
 	struct ftrace_raw_##call __maybe_unused *entry;			\
 									\
 	tstruct;							\
@@ -658,7 +658,7 @@ __attribute__((section("_ftrace_events"))) *__event_##call = &event_##call
 
 #undef __get_dynamic_array
 #define __get_dynamic_array(field)	\
-		((void *)__entry + (__entry->__data_loc_##field & 0xffff))
+		((void *)__entry + __entry->__data_loc_##field.offset)
 
 #undef __get_str
 #define __get_str(field) (char *)__get_dynamic_array(field)
diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index 8a86319..805fc0d 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -234,12 +234,19 @@ static int filter_pred_pchar(struct filter_pred *pred, void *event)
  */
 static int filter_pred_strloc(struct filter_pred *pred, void *event)
 {
-	u32 str_item = *(u32 *)(event + pred->offset);
-	int str_loc = str_item & 0xffff;
-	int str_len = str_item >> 16;
+	struct trace_array_offset *array_offset =
+		(struct trace_array_offset *)(event + pred->offset);
+	int str_loc = array_offset->offset;
+	int str_len = array_offset->length;
 	char *addr = (char *)(event + str_loc);
 	int cmp, match;
 
+	/*
+	 * As struct trace_array_offset is replacing an u32,
+	 * ensure they have the same size.
+	 */
+	BUILD_BUG_ON(sizeof(struct trace_array_offset) != sizeof(u32));
+
 	cmp = pred->regex.match(addr, &pred->regex, str_len);
 
 	match = cmp ^ pred->not;
-- 
1.9.0.279.gdc9e3eb

Re: [PATCH 3/3] tracing: introduce a trace_data_offset struct to store array size

[Steven Rostedt]

You're right, this one will bring up discussion.

On Fri, 28 Feb 2014 21:32:18 -0800
Filipe Brandenburger <filbranden@google.com> wrote:

> Commit 7d536cb3f stores the length of the array in the high 16 bits of
> the offset field. Using a struct with two separate 16 bit fields makes
> it cleaner.
> 
> Tested: Boot kernel with this change, set a 'filename ~ "/usr/bin/pst*"'
> regex filter on events/sched/sched_process_exec/filter, enabled tracing,
> checked that calling pstree would log the trace event as expected.
> 

I just applied this and tested it on my PPC64 box, and it gives me the
following:

without patch:

         pst2pdf-3506  [000]   120.700910: sched_process_exec: filename=/usr/bin/pst2pdf pid=3506 old_pid=3506


With patch:

         pstopnm-4432  [001]  1490.246765: sched_process_exec: filename= pid=4432 old_pid=4432


-- Steve

Re: [PATCH 3/3] tracing: introduce a trace_data_offset struct to store array size

[Steven Rostedt]

On Mon, 3 Mar 2014 15:48:26 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> without patch:
> 
>          pst2pdf-3506  [000]   120.700910: sched_process_exec: filename=/usr/bin/pst2pdf pid=3506 old_pid=3506
> 
> 
> With patch:
> 
>          pstopnm-4432  [001]  1490.246765: sched_process_exec: filename= pid=4432 old_pid=4432

Now, after applying the following patch to your patch, I was able to
get this again:

         pst2pdf-3512  [000]    99.693582: sched_process_exec: filename=/usr/bin/pst2pdf pid=3512 old_pid=3512


-- Steve

diff --git a/include/linux/ftrace_event.h b/include/linux/ftrace_event.h
index 67e4122..2c6d1b0 100644
--- a/include/linux/ftrace_event.h
+++ b/include/linux/ftrace_event.h
@@ -124,8 +124,13 @@ struct trace_event {
 };
 
 struct trace_array_offset {
+#ifdef __BIG_ENDIAN
+	u16			length;
+	u16			offset;
+#else
 	u16			offset;
 	u16			length;
+#endif
 };
 
 extern int register_ftrace_event(struct trace_event *event);