[PATCH] tracing: Allow raw_syscall tracepoints to work from boot

[PATCH] tracing: Allow raw_syscall tracepoints to work from boot

[Michael Ellerman]

In commit 5f893b2639b2 "tracing: Move enabling tracepoints to just after
rcu_init()", tracing was enabled earlier in boot.

This broke tracing of the raw_syscall tracepoints from boot using the
trace_event kernel parameter.

When the registration function for the raw_syscall tracepoints runs, it
iterates over all tasks setting TIF_SYSCALL_TRACEPOINT. However now that
this happens earlier in boot, the loop has no effect because there are
no tasks in existence other than init_task, which is skipped by the
for_each_process_thread() macro.

We can fix it by explicitly setting TIF_SYSCALL_TRACEPOINT for the
init_task. That way when pid 1 is cloned from init_task it will inherit
TIF_SYSCALL_TRACEPOINT.

Fixes: 5f893b2639b2 ("tracing: Move enabling tracepoints to just after rcu_init()")
Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
---
 kernel/tracepoint.c | 6 ++++++
 1 file changed, 6 insertions(+)


It feels a bit naughty to be whacking init_task like this, but it also
seems like the right fix?

Should we also clear it in the unregfunc? I can't see how that would
ever be needed in practice?


diff --git a/kernel/tracepoint.c b/kernel/tracepoint.c
index 3490407dc7b7..43a03e22c16c 100644
--- a/kernel/tracepoint.c
+++ b/kernel/tracepoint.c
@@ -496,6 +496,12 @@ void syscall_regfunc(void)
 
 	if (!sys_tracepoint_refcount) {
 		read_lock(&tasklist_lock);
+		/*
+		 * If we run very early in boot then we need to hit init_task
+		 * directly so that pid 1 will inherit the TIF flag.
+		 */
+		set_tsk_thread_flag(&init_task, TIF_SYSCALL_TRACEPOINT);
+
 		for_each_process_thread(p, t) {
 			set_tsk_thread_flag(t, TIF_SYSCALL_TRACEPOINT);
 		}
-- 
2.1.0

Re: [PATCH] tracing: Allow raw_syscall tracepoints to work from boot

[Steven Rostedt]

On Wed, 14 Jan 2015 09:35:17 +1100
Michael Ellerman <mpe@ellerman.id.au> wrote:

> In commit 5f893b2639b2 "tracing: Move enabling tracepoints to just after
> rcu_init()", tracing was enabled earlier in boot.
> 
> This broke tracing of the raw_syscall tracepoints from boot using the
> trace_event kernel parameter.
> 
> When the registration function for the raw_syscall tracepoints runs, it
> iterates over all tasks setting TIF_SYSCALL_TRACEPOINT. However now that
> this happens earlier in boot, the loop has no effect because there are
> no tasks in existence other than init_task, which is skipped by the
> for_each_process_thread() macro.
> 
> We can fix it by explicitly setting TIF_SYSCALL_TRACEPOINT for the
> init_task. That way when pid 1 is cloned from init_task it will inherit
> TIF_SYSCALL_TRACEPOINT.
> 
> Fixes: 5f893b2639b2 ("tracing: Move enabling tracepoints to just after rcu_init()")

I don't like setting the swap task flag for syscall tracing, as nothing
will unset it.


> Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
> ---
>  kernel/tracepoint.c | 6 ++++++
>  1 file changed, 6 insertions(+)
> 
> 
> It feels a bit naughty to be whacking init_task like this, but it also
> seems like the right fix?

No, I tried the following instead.

> 
> Should we also clear it in the unregfunc? I can't see how that would
> ever be needed in practice?

It just seems hacky to set swapper in the first place.

Try my patch and let me know if it works for you?

-- Steve

>From aae3b6410d536d65204cce7654887095dc41e1cf Mon Sep 17 00:00:00 2001
From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
Date: Wed, 14 Jan 2015 12:53:45 -0500
Subject: [PATCH] tracing: Fix enabling of syscall events on the command line

Commit 5f893b2639b2 "tracing: Move enabling tracepoints to just after
rcu_init()" broke the enabling of system call events from the command
line. The reason was that the enabling of command line trace events
was moved before PID 1 started, and the syscall tracepoints require
that all tasks have the TIF_SYSCALL_TRACEPOINT flag set. But the
swapper task (pid 0) is not part of that. Since the swapper task is the
only task that is running at this early in boot, no task gets the
flag set, and the tracepoint never gets reached.

Instead of setting the swapper task flag (there should be no reason to
do that), re-enabled trace events again after the init thread (PID 1)
has been started. It requires disabling all command line events and
re-enabling them, as just enabling them again will not reset the logic
to set the TIF_SYSCALL_TRACEPOINT flag, as the syscall tracepoint will
be fooled into thinking that it was already set, and wont try setting
it again. For this reason, we must first disable it and re-enable it.

Link: http://lkml.kernel.org/r/1421188517-18312-1-git-send-email-mpe@ellerman.id.au

Reported-by: Michael Ellerman <mpe@ellerman.id.au>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_events.c | 69 ++++++++++++++++++++++++++++++++++++---------
 1 file changed, 55 insertions(+), 14 deletions(-)

diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 366a78a3e61e..b03a0ea77b99 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2429,12 +2429,39 @@ static __init int event_trace_memsetup(void)
 	return 0;
 }
 
+static __init void
+early_enable_events(struct trace_array *tr, bool disable_first)
+{
+	char *buf = bootup_event_buf;
+	char *token;
+	int ret;
+
+	while (true) {
+		token = strsep(&buf, ",");
+
+		if (!token)
+			break;
+		if (!*token)
+			continue;
+
+		/* Restarting syscalls requires that we stop them first */
+		if (disable_first)
+			ftrace_set_clr_event(tr, token, 0);
+
+		ret = ftrace_set_clr_event(tr, token, 1);
+		if (ret)
+			pr_warn("Failed to enable trace event: %s\n", token);
+
+		/* Put back the comma to allow this to be called again */
+		if (buf)
+			*(buf - 1) = ',';
+	}
+}
+
 static __init int event_trace_enable(void)
 {
 	struct trace_array *tr = top_trace_array();
 	struct ftrace_event_call **iter, *call;
-	char *buf = bootup_event_buf;
-	char *token;
 	int ret;
 
 	if (!tr)
@@ -2456,18 +2483,7 @@ static __init int event_trace_enable(void)
 	 */
 	__trace_early_add_events(tr);
 
-	while (true) {
-		token = strsep(&buf, ",");
-
-		if (!token)
-			break;
-		if (!*token)
-			continue;
-
-		ret = ftrace_set_clr_event(tr, token, 1);
-		if (ret)
-			pr_warn("Failed to enable trace event: %s\n", token);
-	}
+	early_enable_events(tr, false);
 
 	trace_printk_start_comm();
 
@@ -2478,6 +2494,31 @@ static __init int event_trace_enable(void)
 	return 0;
 }
 
+/*
+ * event_trace_enable() is called from trace_event_init() first to
+ * initialize events and perhaps start any events that are on the
+ * command line. Unfortunately, there are some events that will not
+ * start this early, like the system call tracepoints that need
+ * to set the TIF_SYSCALL_TRACEPOINT flag of pid 1. But event_trace_enable()
+ * is called before pid 1 starts, and this flag is never set, making
+ * the syscall tracepoint never get reached, but the event is enabled
+ * regardless (and not doing anything).
+ */
+static __init int event_trace_enable_again(void)
+{
+	struct trace_array *tr;
+
+	tr = top_trace_array();
+	if (!tr)
+		return -ENODEV;
+
+	early_enable_events(tr, true);
+
+	return 0;
+}
+
+early_initcall(event_trace_enable_again);
+
 static __init int event_trace_init(void)
 {
 	struct trace_array *tr;
-- 
1.8.1.4

Re: [PATCH] tracing: Allow raw_syscall tracepoints to work from boot

[Michael Ellerman]

On Wed, 2015-01-14 at 13:03 -0500, Steven Rostedt wrote:
> On Wed, 14 Jan 2015 09:35:17 +1100
> Michael Ellerman <mpe@ellerman.id.au> wrote:
> 
> > In commit 5f893b2639b2 "tracing: Move enabling tracepoints to just after
> > rcu_init()", tracing was enabled earlier in boot.
> > 
> > This broke tracing of the raw_syscall tracepoints from boot using the
> > trace_event kernel parameter.
> > 
> > We can fix it by explicitly setting TIF_SYSCALL_TRACEPOINT for the
> > init_task. That way when pid 1 is cloned from init_task it will inherit
> > TIF_SYSCALL_TRACEPOINT.
> 
> I don't like setting the swap task flag for syscall tracing, as nothing
> will unset it.

We could unset it in the unregfunc(), I did that in my original patch but took
it out because I wasn't sure it was necessary.

> > It feels a bit naughty to be whacking init_task like this, but it also
> > seems like the right fix?
> 
> No, I tried the following instead.
> 
> > Should we also clear it in the unregfunc? I can't see how that would
> > ever be needed in practice?
> 
> It just seems hacky to set swapper in the first place.

Actually I thought it was neat, basically everything else comes from init_task
via copy_process().
 
> Try my patch and let me know if it works for you?

Sure. It works.

I can still see the first syscalls in the trace:

    # entries-in-buffer/entries-written: 1021354/1021354   #P:8
    #
    #                              _-----=> irqs-off
    #                             / _----=> need-resched
    #                            | / _---=> hardirq/softirq
    #                            || / _--=> preempt-depth
    #                            ||| /     delay
    #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
    #              | |       |   ||||       |         |
                init-1     [000] ....     3.706370: sys_exit: NR -1 = 0
                init-1     [000] ....     3.706394: sys_enter: NR 45 (0, 0, 3fffa2e20000, 3fffcfd4eac2, 80, 3fffa2e61820)
                init-1     [000] ....     3.706395: sys_exit: NR 45 = 70367490932736
                init-1     [000] ....     3.706409: sys_enter: NR 33 (3fffa2e694d0, 0, 3fffa2e7be20, 0, 1, ffffffffe0000000)
                init-1     [000] ....     3.713325: sys_exit: NR 33 = -2
    

I like my version better, but your call.

cheers

Re: [PATCH] tracing: Allow raw_syscall tracepoints to work from boot

[Steven Rostedt]

On Thu, 15 Jan 2015 17:10:40 +1100
Michael Ellerman <mpe@ellerman.id.au> wrote:

> > 
> > I don't like setting the swap task flag for syscall tracing, as
> > nothing will unset it.
> 
> We could unset it in the unregfunc(), I did that in my original patch
> but took it out because I wasn't sure it was necessary.

Yes we could but that shows the issue with this approach. We can not
just use for_each_process_thread(). swapper is special, and we really
shouldn't touch it for this special case (cmdline usage).

> 
> Actually I thought it was neat, basically everything else comes from
> init_task via copy_process().

Yes, but only at boot up. After that, the swapper is not part of the
game. That's why its not part of for_each_process_thread().

>  
> > Try my patch and let me know if it works for you?
> 
> Sure. It works.
> 
> I can still see the first syscalls in the trace:
> 
>     # entries-in-buffer/entries-written: 1021354/1021354   #P:8
>     #
>     #                              _-----=> irqs-off
>     #                             / _----=> need-resched
>     #                            | / _---=> hardirq/softirq
>     #                            || / _--=> preempt-depth
>     #                            ||| /     delay
>     #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
>     #              | |       |   ||||       |         |
>                 init-1     [000] ....     3.706370: sys_exit: NR -1 =
> 0 init-1     [000] ....     3.706394: sys_enter: NR 45 (0, 0,
> 3fffa2e20000, 3fffcfd4eac2, 80, 3fffa2e61820) init-1
> [000] ....     3.706395: sys_exit: NR 45 = 70367490932736 init-1
> [000] ....     3.706409: sys_enter: NR 33 (3fffa2e694d0, 0,
> 3fffa2e7be20, 0, 1, ffffffffe0000000) init-1     [000] ....
> 3.713325: sys_exit: NR 33 = -2 
> 
> I like my version better, but your call.

Of course you do :-)

I thought about it a bit, and both versions are really hacks. But in
the end, I'd rather not touch the swapper task because that might give
us some unwanted side effects.

I don't really like my approach where I need to disable and re-enable
all tracepoints. I was thinking of only enabling and disabling just the
syscall ones, but I could imagine another tracepoint with a reg that
could be affected by early boot as well, so I left it touching all
events. My patch is fine for mainline, but I could make a patch for
3.20 that will only restart a tracepoint if it has its own reg/unreg
functions and does not use the default ones.

Your patch fixes syscall events. I wanted something that will fix any
event with its own special registration that might also use
for_each_process_thread() or some other call that does not work before
init is created.

Thanks,

-- Steve

Re: [PATCH] tracing: Allow raw_syscall tracepoints to work from boot

[Michael Ellerman]

On Thu, 2015-01-15 at 08:58 -0500, Steven Rostedt wrote:
> On Thu, 15 Jan 2015 17:10:40 +1100
> Michael Ellerman <mpe@ellerman.id.au> wrote:
> > 
> > I like my version better, but your call.
> 
> Of course you do :-)

You've got to admit mine is a lot neater looking :)

> I thought about it a bit, and both versions are really hacks. But in
> the end, I'd rather not touch the swapper task because that might give
> us some unwanted side effects.

Yeah that's true. I don't *think* there would be, but touching swapper is
certainly something one should do with caution.

> I don't really like my approach where I need to disable and re-enable
> all tracepoints. I was thinking of only enabling and disabling just the
> syscall ones, but I could imagine another tracepoint with a reg that
> could be affected by early boot as well, so I left it touching all
> events. My patch is fine for mainline, but I could make a patch for
> 3.20 that will only restart a tracepoint if it has its own reg/unreg
> functions and does not use the default ones.
> 
> Your patch fixes syscall events. I wanted something that will fix any
> event with its own special registration that might also use
> for_each_process_thread() or some other call that does not work before
> init is created.

Yep, that is definitely a benefit. I don't think there are heaps of folks using
tracepoints from boot, so it's possible something else was broken and we
haven't noticed yet.

cheers