Re: [PATCH 1/2] tracing: Move enabling tracepoints to just after rcu_init()

Re: [PATCH 1/2] tracing: Move enabling tracepoints to just after rcu_init()

[Wang Nan]

Hi Steven Rostedt,

During studying your code we find a problem, please see below.

> 
> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> 
> Enabling tracepoints at boot up can be very useful. The tracepoint
> can be initialized right after RCU has been. There's no need to
> wait for the early_initcall() to be called. That's too late for some
> things that can use tracepoints for debugging. Move the logic to
> enable tracepoints out of the initcalls and into init/main.c to
> right after rcu_init().
> 
> This also allows trace_printk() to be used early too.
> 
> Link: http://lkml.kernel.org/r/alpine.DEB.2.11.1412121539300.16494@nanos
> Link: http://lkml.kernel.org/r/20141214164104.307127356@goodmis.org
> 
> Reviewed-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> Suggested-by: Thomas Gleixner <tglx@linutronix.de>
> Tested-by: Thomas Gleixner <tglx@linutronix.de>
> Acked-by: Thomas Gleixner <tglx@linutronix.de>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

[...]

> +void __init trace_init(void)
> +{
> +	tracer_alloc_buffers();
> +	init_ftrace_syscalls();
> +	trace_event_init();	
> +}
> +

[...]

> +
> +void __init trace_event_init(void)
> +{
> +	event_trace_memsetup();
> +	init_ftrace_syscalls();
> +	event_trace_enable();
> +}
> +

init_ftrace_syscalls() get called twice by trace_init() and trace_event_init(), some resources are wasted.
At lease one of them can be removed.

In addition, could you please have a look at my early kprobe patch series?

http://lists.infradead.org/pipermail/linux-arm-kernel/2015-January/313835.html

Which enables kprobe very early, even before memory initialized. I think it is possible to combine these
early tracing facilities together.

Thank you!

Re: [PATCH 1/2] tracing: Move enabling tracepoints to just after rcu_init()

[Wang Nan]

Ping...

On 2015/1/9 12:06, Wang Nan wrote:
> Hi Steven Rostedt,
> 
> During studying your code we find a problem, please see below.
> 
>>
>> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
>>
>> Enabling tracepoints at boot up can be very useful. The tracepoint
>> can be initialized right after RCU has been. There's no need to
>> wait for the early_initcall() to be called. That's too late for some
>> things that can use tracepoints for debugging. Move the logic to
>> enable tracepoints out of the initcalls and into init/main.c to
>> right after rcu_init().
>>
>> This also allows trace_printk() to be used early too.
>>
>> Link: http://lkml.kernel.org/r/alpine.DEB.2.11.1412121539300.16494@nanos
>> Link: http://lkml.kernel.org/r/20141214164104.307127356@goodmis.org
>>
>> Reviewed-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>> Suggested-by: Thomas Gleixner <tglx@linutronix.de>
>> Tested-by: Thomas Gleixner <tglx@linutronix.de>
>> Acked-by: Thomas Gleixner <tglx@linutronix.de>
>> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> 
> [...]
> 
>> +void __init trace_init(void)
>> +{
>> +	tracer_alloc_buffers();
>> +	init_ftrace_syscalls();
>> +	trace_event_init();	
>> +}
>> +
> 
> [...]
> 
>> +
>> +void __init trace_event_init(void)
>> +{
>> +	event_trace_memsetup();
>> +	init_ftrace_syscalls();
>> +	event_trace_enable();
>> +}
>> +
> 
> init_ftrace_syscalls() get called twice by trace_init() and trace_event_init(), some resources are wasted.
> At lease one of them can be removed.
> 
> In addition, could you please have a look at my early kprobe patch series?
> 
> http://lists.infradead.org/pipermail/linux-arm-kernel/2015-January/313835.html
> 
> Which enables kprobe very early, even before memory initialized. I think it is possible to combine these
> early tracing facilities together.
> 
> Thank you!
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 

Re: [PATCH 1/2] tracing: Move enabling tracepoints to just after rcu_init()

[Namhyung Kim]

On Wed, Jan 14, 2015 at 08:12:40AM +0800, Wang Nan wrote:
> Ping...
> 
> On 2015/1/9 12:06, Wang Nan wrote:
> > Hi Steven Rostedt,
> > 
> > During studying your code we find a problem, please see below.
> > 
> >>
> >> From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
> >>
> >> Enabling tracepoints at boot up can be very useful. The tracepoint
> >> can be initialized right after RCU has been. There's no need to
> >> wait for the early_initcall() to be called. That's too late for some
> >> things that can use tracepoints for debugging. Move the logic to
> >> enable tracepoints out of the initcalls and into init/main.c to
> >> right after rcu_init().
> >>
> >> This also allows trace_printk() to be used early too.
> >>
> >> Link: http://lkml.kernel.org/r/alpine.DEB.2.11.1412121539300.16494@nanos
> >> Link: http://lkml.kernel.org/r/20141214164104.307127356@goodmis.org
> >>
> >> Reviewed-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> >> Suggested-by: Thomas Gleixner <tglx@linutronix.de>
> >> Tested-by: Thomas Gleixner <tglx@linutronix.de>
> >> Acked-by: Thomas Gleixner <tglx@linutronix.de>
> >> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> > 
> > [...]
> > 
> >> +void __init trace_init(void)
> >> +{
> >> +	tracer_alloc_buffers();
> >> +	init_ftrace_syscalls();
> >> +	trace_event_init();	
> >> +}
> >> +
> > 
> > [...]
> > 
> >> +
> >> +void __init trace_event_init(void)
> >> +{
> >> +	event_trace_memsetup();
> >> +	init_ftrace_syscalls();
> >> +	event_trace_enable();
> >> +}
> >> +
> > 
> > init_ftrace_syscalls() get called twice by trace_init() and trace_event_init(), some resources are wasted.
> > At lease one of them can be removed.

I think it's more natural to keep it in the trace_event_init().

Thanks,
Namhyung

Re: [PATCH 1/2] tracing: Move enabling tracepoints to just after rcu_init()

[Steven Rostedt]

On Wed, 14 Jan 2015 10:09:05 +0900
Namhyung Kim <namhyung@kernel.org> wrote:


> > >> +
> > >> +void __init trace_event_init(void)
> > >> +{
> > >> +	event_trace_memsetup();
> > >> +	init_ftrace_syscalls();
> > >> +	event_trace_enable();
> > >> +}
> > >> +
> > > 
> > > init_ftrace_syscalls() get called twice by trace_init() and trace_event_init(), some resources are wasted.
> > > At lease one of them can be removed.
> 
> I think it's more natural to keep it in the trace_event_init().

I agree, I'll remove it. I'm fixing another bug that this change caused
to system call events.

-- Steve

[PATCH 0/2] [GIT PULL] tracing: Enable tracepoints early and allow printk to use them

[Steven Rostedt]

Linus,

As the merge window is still open, and this code was not as complex
as I thought it might be. I'm pushing this in now.

This will allow Thomas to debug his irq work for 3.20.

This adds two new features:

1) Allow traceopoints to be enabled right after mm_init(). By passing
in the trace_event= kernel command line parameter, tracepoints can be
enabled at boot up. For debugging things like the initialization of
interrupts, it is needed to have tracepoints enabled very early. People
have asked about this before and this has been on my todo list. As it
can be helpful for Thomas to debug his upcoming 3.20 IRQ work, I'm
pushing this now. This way he can add tracepoints into the IRQ set up
and have users enable them when things go wrong.

2) Have the tracepoints printed via printk() (the console) when they
are triggered. If the irq code locks up or reboots the box, having the
tracepoint output go into the kernel ring buffer is useless for
debugging. But being able to add the tp_printk kernel command line
option along with the trace_event= option will have these tracepoints
printed as they occur, and that can be really useful for debugging
early lock up or reboot problems.

This code is not that intrusive and it passed all my tests. Thomas tried
them out too and it works for his needs.

 Link: http://lkml.kernel.org/r/20141214201609.126831471@goodmis.org

Please pull the latest trace-3.19-2 tree, which can be found at:


  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
trace-3.19-2

Tag SHA1: 378ef8105fed2dd3299e3232ff3d365a7d9feac9
Head SHA1: 0daa2302968c13b657118d6ac92471f8fd2f3f28


Steven Rostedt (Red Hat) (2):
      tracing: Move enabling tracepoints to just after rcu_init()
      tracing: Add tp_printk cmdline to have tracepoints go to printk()

----
 Documentation/kernel-parameters.txt | 18 ++++++++++++++++
 include/linux/ftrace.h              |  7 +++++++
 init/main.c                         |  4 ++++
 kernel/sysctl.c                     |  7 +++++++
 kernel/trace/trace.c                | 25 +++++++++++++++++++++-
 kernel/trace/trace.h                | 14 +++++++++++++
 kernel/trace/trace_events.c         | 42 +++++++++++++++++++++++++++++++++++--
 kernel/trace/trace_syscalls.c       |  7 ++-----
 8 files changed, 116 insertions(+), 8 deletions(-)

[PATCH 1/2] tracing: Move enabling tracepoints to just after rcu_init()

[Steven Rostedt]

[-- Attachment #1: 0001-tracing-Move-enabling-tracepoints-to-just-after-rcu_.patch --]
[-- Type: text/plain, Size: 4581 bytes --]

From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>

Enabling tracepoints at boot up can be very useful. The tracepoint
can be initialized right after RCU has been. There's no need to
wait for the early_initcall() to be called. That's too late for some
things that can use tracepoints for debugging. Move the logic to
enable tracepoints out of the initcalls and into init/main.c to
right after rcu_init().

This also allows trace_printk() to be used early too.

Link: http://lkml.kernel.org/r/alpine.DEB.2.11.1412121539300.16494@nanos
Link: http://lkml.kernel.org/r/20141214164104.307127356@goodmis.org

Reviewed-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Suggested-by: Thomas Gleixner <tglx@linutronix.de>
Tested-by: Thomas Gleixner <tglx@linutronix.de>
Acked-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/ftrace.h        |  6 ++++++
 init/main.c                   |  4 ++++
 kernel/trace/trace.c          |  8 +++++++-
 kernel/trace/trace.h          | 13 +++++++++++++
 kernel/trace/trace_events.c   | 10 ++++++++--
 kernel/trace/trace_syscalls.c |  7 ++-----
 6 files changed, 40 insertions(+), 8 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index ed501953f0b2..f4bc14b7d444 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -39,6 +39,12 @@
 # define FTRACE_FORCE_LIST_FUNC 0
 #endif
 
+/* Main tracing buffer and events set up */
+#ifdef CONFIG_TRACING
+void trace_init(void);
+#else
+static inline void trace_init(void) { }
+#endif
 
 struct module;
 struct ftrace_hash;
diff --git a/init/main.c b/init/main.c
index 800a0daede7e..70687069f8e2 100644
--- a/init/main.c
+++ b/init/main.c
@@ -577,6 +577,10 @@ asmlinkage __visible void __init start_kernel(void)
 		local_irq_disable();
 	idr_init_cache();
 	rcu_init();
+
+	/* trace_printk() and trace points may be used after this */
+	trace_init();
+
 	context_tracking_init();
 	radix_tree_init();
 	/* init some links before init_ISA_irqs() */
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 4ceb2546c7ef..ec3ca694665f 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6876,6 +6876,13 @@ out:
 	return ret;
 }
 
+void __init trace_init(void)
+{
+	tracer_alloc_buffers();
+	init_ftrace_syscalls();
+	trace_event_init();	
+}
+
 __init static int clear_boot_tracer(void)
 {
 	/*
@@ -6895,6 +6902,5 @@ __init static int clear_boot_tracer(void)
 	return 0;
 }
 
-early_initcall(tracer_alloc_buffers);
 fs_initcall(tracer_init_debugfs);
 late_initcall(clear_boot_tracer);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 3255dfb054a0..c138c149d6ef 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1301,4 +1301,17 @@ int perf_ftrace_event_register(struct ftrace_event_call *call,
 #define perf_ftrace_event_register NULL
 #endif
 
+#ifdef CONFIG_FTRACE_SYSCALLS
+void init_ftrace_syscalls(void);
+#else
+static inline void init_ftrace_syscalls(void) { }
+#endif
+
+#ifdef CONFIG_EVENT_TRACING
+void trace_event_init(void);
+#else
+static inline void __init trace_event_init(void) { }
+#endif
+
+
 #endif /* _LINUX_KERNEL_TRACE_H */
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index f9d0cbe014b7..fd9deb0e03f0 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -2477,8 +2477,14 @@ static __init int event_trace_init(void)
 #endif
 	return 0;
 }
-early_initcall(event_trace_memsetup);
-core_initcall(event_trace_enable);
+
+void __init trace_event_init(void)
+{
+	event_trace_memsetup();
+	init_ftrace_syscalls();
+	event_trace_enable();
+}
+
 fs_initcall(event_trace_init);
 
 #ifdef CONFIG_FTRACE_STARTUP_TEST
diff --git a/kernel/trace/trace_syscalls.c b/kernel/trace/trace_syscalls.c
index a72f3d8d813e..ec239771c175 100644
--- a/kernel/trace/trace_syscalls.c
+++ b/kernel/trace/trace_syscalls.c
@@ -514,7 +514,7 @@ unsigned long __init __weak arch_syscall_addr(int nr)
 	return (unsigned long)sys_call_table[nr];
 }
 
-static int __init init_ftrace_syscalls(void)
+void __init init_ftrace_syscalls(void)
 {
 	struct syscall_metadata *meta;
 	unsigned long addr;
@@ -524,7 +524,7 @@ static int __init init_ftrace_syscalls(void)
 				    GFP_KERNEL);
 	if (!syscalls_metadata) {
 		WARN_ON(1);
-		return -ENOMEM;
+		return;
 	}
 
 	for (i = 0; i < NR_syscalls; i++) {
@@ -536,10 +536,7 @@ static int __init init_ftrace_syscalls(void)
 		meta->syscall_nr = i;
 		syscalls_metadata[i] = meta;
 	}
-
-	return 0;
 }
-early_initcall(init_ftrace_syscalls);
 
 #ifdef CONFIG_PERF_EVENTS
 
-- 
2.1.3