[RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[Ezequiel Garcia]

This patch splits trace event initialization in two stages:
 * ftrace enable
 * sysfs event entry creation

This allows to capture trace events from an earlier point
by using 'trace_event' kernel parameter and is important
to trace boot-up allocations.

Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
Signed-off-by: Ezequiel Garcia <elezegarcia@gmail.com>
---
 kernel/trace/trace_events.c |   71 ++++++++++++++++++++++++++++++++-----------
 1 files changed, 53 insertions(+), 18 deletions(-)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 29111da..3055bc9 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1450,6 +1450,49 @@ static __init int setup_trace_event(char *str)
 }
 __setup("trace_event=", setup_trace_event);
 
+static __init int event_trace_enable(void)
+{
+	struct ftrace_event_call **iter, *call;
+	char *buf = bootup_event_buf;
+	char *token;
+	int ret;
+
+	for_each_event(iter, __start_ftrace_events, __stop_ftrace_events) {
+
+		call = *iter;
+
+		/* The linker may leave blanks */
+		if (!call->name)
+			continue;
+
+		if (!call->class->raw_init)
+			continue;
+
+		ret = call->class->raw_init(call);
+		if (ret < 0) {
+			if (ret != -ENOSYS)
+				pr_warning("Could not initialize trace events/%s\n",
+						call->name);
+			continue;
+		}
+		list_add(&call->list, &ftrace_events);
+	}
+
+	while (true) {
+		token = strsep(&buf, ",");
+
+		if (!token)
+			break;
+		if (!*token)
+			continue;
+
+		ret = ftrace_set_clr_event(token, 1);
+		if (ret)
+			pr_warning("Failed to enable trace event: %s\n", token);
+	}
+	return 0;
+}
+
 static __init int event_trace_init(void)
 {
 	struct ftrace_event_call **call;
@@ -1457,8 +1500,6 @@ static __init int event_trace_init(void)
 	struct dentry *entry;
 	struct dentry *d_events;
 	int ret;
-	char *buf = bootup_event_buf;
-	char *token;
 
 	d_tracer = tracing_init_dentry();
 	if (!d_tracer)
@@ -1497,24 +1538,17 @@ static __init int event_trace_init(void)
 	if (trace_define_common_fields())
 		pr_warning("tracing: Failed to allocate common fields");
 
+	/*
+	 * Early initialization already enabled ftrace event.
+	 * Now it's only necessary to create the event directory.
+	 */
 	for_each_event(call, __start_ftrace_events, __stop_ftrace_events) {
-		__trace_add_event_call(*call, NULL, &ftrace_event_id_fops,
-				       &ftrace_enable_fops,
-				       &ftrace_event_filter_fops,
-				       &ftrace_event_format_fops);
-	}
-
-	while (true) {
-		token = strsep(&buf, ",");
-
-		if (!token)
-			break;
-		if (!*token)
-			continue;
 
-		ret = ftrace_set_clr_event(token, 1);
-		if (ret)
-			pr_warning("Failed to enable trace event: %s\n", token);
+		event_create_dir(*call, d_events,
+				 &ftrace_event_id_fops,
+				 &ftrace_enable_fops,
+				 &ftrace_event_filter_fops,
+				 &ftrace_event_format_fops);
 	}
 
 	ret = register_module_notifier(&trace_module_nb);
@@ -1523,6 +1557,7 @@ static __init int event_trace_init(void)
 
 	return 0;
 }
+early_initcall(event_trace_enable);
 fs_initcall(event_trace_init);
 
 #ifdef CONFIG_FTRACE_STARTUP_TEST
-- 
1.7.8.6

Re: [RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[Steven Rostedt]

On Wed, 2012-08-15 at 12:18 -0300, Ezequiel Garcia wrote:
> This patch splits trace event initialization in two stages:
>  * ftrace enable
>  * sysfs event entry creation
> 
> This allows to capture trace events from an earlier point
> by using 'trace_event' kernel parameter and is important
> to trace boot-up allocations.
> 
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Ingo Molnar <mingo@redhat.com>
> Signed-off-by: Ezequiel Garcia <elezegarcia@gmail.com>
> ---
>  kernel/trace/trace_events.c |   71 ++++++++++++++++++++++++++++++++-----------
>  1 files changed, 53 insertions(+), 18 deletions(-)
> 
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index 29111da..3055bc9 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -1450,6 +1450,49 @@ static __init int setup_trace_event(char *str)
>  }
>  __setup("trace_event=", setup_trace_event);
>  
> +static __init int event_trace_enable(void)
> +{
> +	struct ftrace_event_call **iter, *call;
> +	char *buf = bootup_event_buf;
> +	char *token;
> +	int ret;
> +
> +	for_each_event(iter, __start_ftrace_events, __stop_ftrace_events) {
> +
> +		call = *iter;
> +
> +		/* The linker may leave blanks */

Actually, this shouldn't be true anymore. I know you copied the comment,
but with the new pointer settings, there should be no blanks. We
probably should turn this into a WARN_ON().


> +		if (!call->name)
> +			continue;
> +
> +		if (!call->class->raw_init)
> +			continue;
> +
> +		ret = call->class->raw_init(call);
> +		if (ret < 0) {
> +			if (ret != -ENOSYS)
> +				pr_warning("Could not initialize trace events/%s\n",
> +						call->name);
> +			continue;
> +		}
> +		list_add(&call->list, &ftrace_events);

Anyway, this code is duplicated now here and in
__trace_add_event_call(). A helper function should be created to store
this in both locations.

> +	}
> +
> +	while (true) {
> +		token = strsep(&buf, ",");
> +
> +		if (!token)
> +			break;
> +		if (!*token)
> +			continue;
> +
> +		ret = ftrace_set_clr_event(token, 1);
> +		if (ret)
> +			pr_warning("Failed to enable trace event: %s\n", token);
> +	}
> +	return 0;
> +}
> +
>  static __init int event_trace_init(void)
>  {
>  	struct ftrace_event_call **call;
> @@ -1457,8 +1500,6 @@ static __init int event_trace_init(void)
>  	struct dentry *entry;
>  	struct dentry *d_events;
>  	int ret;
> -	char *buf = bootup_event_buf;
> -	char *token;
>  
>  	d_tracer = tracing_init_dentry();
>  	if (!d_tracer)
> @@ -1497,24 +1538,17 @@ static __init int event_trace_init(void)
>  	if (trace_define_common_fields())
>  		pr_warning("tracing: Failed to allocate common fields");
>  
> +	/*
> +	 * Early initialization already enabled ftrace event.
> +	 * Now it's only necessary to create the event directory.
> +	 */
>  	for_each_event(call, __start_ftrace_events, __stop_ftrace_events) {
> -		__trace_add_event_call(*call, NULL, &ftrace_event_id_fops,
> -				       &ftrace_enable_fops,
> -				       &ftrace_event_filter_fops,
> -				       &ftrace_event_format_fops);
> -	}
> -
> -	while (true) {
> -		token = strsep(&buf, ",");
> -
> -		if (!token)
> -			break;
> -		if (!*token)
> -			continue;
>  
> -		ret = ftrace_set_clr_event(token, 1);
> -		if (ret)
> -			pr_warning("Failed to enable trace event: %s\n", token);
> +		event_create_dir(*call, d_events,
> +				 &ftrace_event_id_fops,
> +				 &ftrace_enable_fops,
> +				 &ftrace_event_filter_fops,
> +				 &ftrace_event_format_fops);

This changes how events are currently. If we fail to create the
directory, we still keep the event. This can become confusing as events
and the directories will not match anymore. A failure should be checked
for, and if it happens, the event should be removed.

-- Steve

>  	}
>  
>  	ret = register_module_notifier(&trace_module_nb);
> @@ -1523,6 +1557,7 @@ static __init int event_trace_init(void)
>  
>  	return 0;
>  }
> +early_initcall(event_trace_enable);
>  fs_initcall(event_trace_init);
>  
>  #ifdef CONFIG_FTRACE_STARTUP_TEST

Re: [RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[Ezequiel Garcia]

Hi Steven,

On Thu, Aug 16, 2012 at 6:18 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 2012-08-15 at 12:18 -0300, Ezequiel Garcia wrote:
>> This patch splits trace event initialization in two stages:
>>  * ftrace enable
>>  * sysfs event entry creation
>>
>> This allows to capture trace events from an earlier point
>> by using 'trace_event' kernel parameter and is important
>> to trace boot-up allocations.
>>
>> Cc: Steven Rostedt <rostedt@goodmis.org>
>> Cc: Frederic Weisbecker <fweisbec@gmail.com>
>> Cc: Ingo Molnar <mingo@redhat.com>
>> Signed-off-by: Ezequiel Garcia <elezegarcia@gmail.com>
>> ---
>>  kernel/trace/trace_events.c |   71 ++++++++++++++++++++++++++++++++-----------
>>  1 files changed, 53 insertions(+), 18 deletions(-)
>>
>> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
>> index 29111da..3055bc9 100644
>> --- a/kernel/trace/trace_events.c
>> +++ b/kernel/trace/trace_events.c
>> @@ -1450,6 +1450,49 @@ static __init int setup_trace_event(char *str)
>>  }
>>  __setup("trace_event=", setup_trace_event);
>>
>> +static __init int event_trace_enable(void)
>> +{
>> +     struct ftrace_event_call **iter, *call;
>> +     char *buf = bootup_event_buf;
>> +     char *token;
>> +     int ret;
>> +
>> +     for_each_event(iter, __start_ftrace_events, __stop_ftrace_events) {
>> +
>> +             call = *iter;
>> +
>> +             /* The linker may leave blanks */
>
> Actually, this shouldn't be true anymore. I know you copied the comment,
> but with the new pointer settings, there should be no blanks. We
> probably should turn this into a WARN_ON().
>
>
>> +             if (!call->name)
>> +                     continue;
>> +
>> +             if (!call->class->raw_init)
>> +                     continue;
>> +
>> +             ret = call->class->raw_init(call);
>> +             if (ret < 0) {
>> +                     if (ret != -ENOSYS)
>> +                             pr_warning("Could not initialize trace events/%s\n",
>> +                                             call->name);
>> +                     continue;
>> +             }
>> +             list_add(&call->list, &ftrace_events);
>
> Anyway, this code is duplicated now here and in
> __trace_add_event_call(). A helper function should be created to store
> this in both locations.
>
>> +     }
>> +
>> +     while (true) {
>> +             token = strsep(&buf, ",");
>> +
>> +             if (!token)
>> +                     break;
>> +             if (!*token)
>> +                     continue;
>> +
>> +             ret = ftrace_set_clr_event(token, 1);
>> +             if (ret)
>> +                     pr_warning("Failed to enable trace event: %s\n", token);
>> +     }
>> +     return 0;
>> +}
>> +
>>  static __init int event_trace_init(void)
>>  {
>>       struct ftrace_event_call **call;
>> @@ -1457,8 +1500,6 @@ static __init int event_trace_init(void)
>>       struct dentry *entry;
>>       struct dentry *d_events;
>>       int ret;
>> -     char *buf = bootup_event_buf;
>> -     char *token;
>>
>>       d_tracer = tracing_init_dentry();
>>       if (!d_tracer)
>> @@ -1497,24 +1538,17 @@ static __init int event_trace_init(void)
>>       if (trace_define_common_fields())
>>               pr_warning("tracing: Failed to allocate common fields");
>>
>> +     /*
>> +      * Early initialization already enabled ftrace event.
>> +      * Now it's only necessary to create the event directory.
>> +      */
>>       for_each_event(call, __start_ftrace_events, __stop_ftrace_events) {
>> -             __trace_add_event_call(*call, NULL, &ftrace_event_id_fops,
>> -                                    &ftrace_enable_fops,
>> -                                    &ftrace_event_filter_fops,
>> -                                    &ftrace_event_format_fops);
>> -     }
>> -
>> -     while (true) {
>> -             token = strsep(&buf, ",");
>> -
>> -             if (!token)
>> -                     break;
>> -             if (!*token)
>> -                     continue;
>>
>> -             ret = ftrace_set_clr_event(token, 1);
>> -             if (ret)
>> -                     pr_warning("Failed to enable trace event: %s\n", token);
>> +             event_create_dir(*call, d_events,
>> +                              &ftrace_event_id_fops,
>> +                              &ftrace_enable_fops,
>> +                              &ftrace_event_filter_fops,
>> +                              &ftrace_event_format_fops);
>
> This changes how events are currently. If we fail to create the
> directory, we still keep the event. This can become confusing as events
> and the directories will not match anymore. A failure should be checked
> for, and if it happens, the event should be removed.
>

Thanks for your comments, I'll send a v2 addressing them.

Regarding the 'complete solution': to be able to capture events from
the very beggining...
Have you thought about this?
Could you give me a hint on how could I implement it?

Thanks a lot,
Ezequiel.

Re: [RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[Steven Rostedt]

On Fri, 2012-08-17 at 08:01 -0300, Ezequiel Garcia wrote:

> Regarding the 'complete solution': to be able to capture events from
> the very beggining...
> Have you thought about this?
> Could you give me a hint on how could I implement it?

How far in the "beginning"? Before memory is set up? I wouldn't do that.
I have in the past (set up before memory was finished being
initialized), but things have changed since then.

One thing that we could do for those that want really early tracing, is
to add a config option to add a static temporary ring buffer, that gets
copied into the default ring buffer after memory is set up. That may be
the easiest way.

Once memory is set up, the ring buffer can be allocated and events can
be traced, but the ring buffer needs to be set up first. All it would
take is some calls in init/main.c start_kernel() to the initialization.

-- Steve

Re: [RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[Ezequiel Garcia]

On Fri, Aug 17, 2012 at 10:55 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Fri, 2012-08-17 at 08:01 -0300, Ezequiel Garcia wrote:
>
>> Regarding the 'complete solution': to be able to capture events from
>> the very beggining...
>> Have you thought about this?
>> Could you give me a hint on how could I implement it?
>
> How far in the "beginning"? Before memory is set up?

Yes.

> I wouldn't do that.

Yeah, perhaps it sounds crazy. It makes some sense for kmem events, though.

> I have in the past (set up before memory was finished being
> initialized), but things have changed since then.
>
> One thing that we could do for those that want really early tracing, is
> to add a config option to add a static temporary ring buffer, that gets

Yes, something like this would be ideal. How would this ring buffer be
allocated?
Perhaps as static and __initdata?
This way it would be released afterwards, right?

> copied into the default ring buffer after memory is set up. That may be
> the easiest way.
>
> Once memory is set up, the ring buffer can be allocated and events can
> be traced, but the ring buffer needs to be set up first. All it would
> take is some calls in init/main.c start_kernel() to the initialization.
>

Note that my main concern is on trace_events (kmem events to be precise).
However this are registered through tracepoints and in turn this tracepoints
depend on kmalloc and friends. So, right now is a chicken-egg problem.

Thanks,
Ezequiel.

Re: [RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[Steven Rostedt]

On Fri, 2012-08-17 at 11:04 -0300, Ezequiel Garcia wrote:
> On Fri, Aug 17, 2012 at 10:55 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> > On Fri, 2012-08-17 at 08:01 -0300, Ezequiel Garcia wrote:
> >
> >> Regarding the 'complete solution': to be able to capture events from
> >> the very beggining...
> >> Have you thought about this?
> >> Could you give me a hint on how could I implement it?
> >
> > How far in the "beginning"? Before memory is set up?
> 
> Yes.
> 
> > I wouldn't do that.
> 
> Yeah, perhaps it sounds crazy. It makes some sense for kmem events, though.

It doesn't sound crazy, because I've done it before. There may be ways
to do it.

> 
> > I have in the past (set up before memory was finished being
> > initialized), but things have changed since then.
> >
> > One thing that we could do for those that want really early tracing, is
> > to add a config option to add a static temporary ring buffer, that gets
> 
> Yes, something like this would be ideal. How would this ring buffer be
> allocated?
> Perhaps as static and __initdata?

Yes.

> This way it would be released afterwards, right?

Correct.

> 
> > copied into the default ring buffer after memory is set up. That may be
> > the easiest way.
> >
> > Once memory is set up, the ring buffer can be allocated and events can
> > be traced, but the ring buffer needs to be set up first. All it would
> > take is some calls in init/main.c start_kernel() to the initialization.
> >
> 
> Note that my main concern is on trace_events (kmem events to be precise).
> However this are registered through tracepoints and in turn this tracepoints
> depend on kmalloc and friends. So, right now is a chicken-egg problem.

I don't think kmalloc is the issue. The big problem in front of you is
jump labels. That's what enables and disables trace points, and it gets
initialized just after memory is set up. You may have to force jump
labels off when doing early tracing :-/ Although I'm not sure it
requires allocations.

-- Steve

Re: [RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[Jason Baron]

On Fri, Aug 17, 2012 at 10:39:39AM -0400, Steven Rostedt wrote:
> On Fri, 2012-08-17 at 11:04 -0300, Ezequiel Garcia wrote:
> > On Fri, Aug 17, 2012 at 10:55 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> > > On Fri, 2012-08-17 at 08:01 -0300, Ezequiel Garcia wrote:
> > >
> > >> Regarding the 'complete solution': to be able to capture events from
> > >> the very beggining...
> > >> Have you thought about this?
> > >> Could you give me a hint on how could I implement it?
> > >
> > > How far in the "beginning"? Before memory is set up?
> > 
> > Yes.
> > 
> > > I wouldn't do that.
> > 
> > Yeah, perhaps it sounds crazy. It makes some sense for kmem events, though.
> 
> It doesn't sound crazy, because I've done it before. There may be ways
> to do it.
> 
> > 
> > > I have in the past (set up before memory was finished being
> > > initialized), but things have changed since then.
> > >
> > > One thing that we could do for those that want really early tracing, is
> > > to add a config option to add a static temporary ring buffer, that gets
> > 
> > Yes, something like this would be ideal. How would this ring buffer be
> > allocated?
> > Perhaps as static and __initdata?
> 
> Yes.
> 
> > This way it would be released afterwards, right?
> 
> Correct.
> 
> > 
> > > copied into the default ring buffer after memory is set up. That may be
> > > the easiest way.
> > >
> > > Once memory is set up, the ring buffer can be allocated and events can
> > > be traced, but the ring buffer needs to be set up first. All it would
> > > take is some calls in init/main.c start_kernel() to the initialization.
> > >
> > 
> > Note that my main concern is on trace_events (kmem events to be precise).
> > However this are registered through tracepoints and in turn this tracepoints
> > depend on kmalloc and friends. So, right now is a chicken-egg problem.
> 
> I don't think kmalloc is the issue. The big problem in front of you is
> jump labels. That's what enables and disables trace points, and it gets
> initialized just after memory is set up. You may have to force jump
> labels off when doing early tracing :-/ Although I'm not sure it
> requires allocations.
> 

The only allocation jump labels should do is when modules are loaded. So
I think you should be able to move them earlier, if need be.

Thanks,

-Jason

Re: [RFC PATCH 1/1] trace: Move trace event enable from fs_initcall to early_initcall

[Ezequiel Garcia]

Hi Steven,

On Fri, Aug 17, 2012 at 11:39 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
>
> I don't think kmalloc is the issue. The big problem in front of you is
> jump labels. That's what enables and disables trace points, and it gets
> initialized just after memory is set up. You may have to force jump
> labels off when doing early tracing :-/ Although I'm not sure it
> requires allocations.
>

Well, I wasn't thinking *that* early actually. So, I'm trying to enable tracing
at some point after jump_labels (could be near perf_event_init).

Right now, the static ring buffer part is done and I'm having some
problems copying this ring buffer into the *real* one.

Mind giving me another hint?

Thanks a lot for your help so far,
Ezequiel.