tracing: Enable tracepoints early and allow printk to use them
Subsystems (4)
Steven Rostedt
maintainerLinus,
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.
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(-)
Steven Rostedt
maintainerPATCH 1/2 tracing: Move enabling tracepoints to just after rcu_init()
From: "Steven Rostedt (Red Hat)" <[email protected]>
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.
--- 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(-)
include/linux/ftrace.h +6 -0
@@ -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 ;
init/main.c +4 -0
@@ -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() */
kernel/trace/trace.c +7 -1
@@ -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);
kernel/trace/trace.h +13 -0
@@ -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 */
kernel/trace/trace_events.c +8 -2
@@ -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
kernel/trace/trace_syscalls.c +2 -5
@@ -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
Signature · 1 line
2.1.3
Re: [PATCH 1/2] tracing: Move enabling tracepoints to just after rcu_init()
Hi Steven Rostedt,
During studying your code we find a problem, please see below.
Quoted 20 lines
From: "Steven Rostedt (Red Hat)" <[email protected]>
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 intoinit/main.cto right afterrcu_init().This also allows
trace_printk()to be used early too.Reviewed-by Paul E. McKenney <[email protected]>Suggested-by Thomas Gleixner <[email protected]>Tested-by Thomas Gleixner <[email protected]>Acked-by Thomas Gleixner <[email protected]>Signed-off-by Steven Rostedt <[email protected]>
[...]
Quoted 7 lines
kernel/trace/trace.c +7
-0+void __init trace_init (void ) +{ +tracer_alloc_buffers (); +init_ftrace_syscalls (); +trace_event_init (); +} +
[...]
kernel/trace/trace_events.c static __init int event_trace_init(void) · line 2487
Quoted 8 lines
kernel/trace/trace_events.c +8
-0+ +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()
Ping...
Quoted 65 lines · Wang Nan
Hi Steven Rostedt,
During studying your code we find a problem, please see below.
Quoted 20 lines
From: "Steven Rostedt (Red Hat)" <[email protected]>
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 intoinit/main.cto right afterrcu_init().This also allows
trace_printk()to be used early too.Reviewed-by Paul E. McKenney <[email protected]>Suggested-by Thomas Gleixner <[email protected]>Tested-by Thomas Gleixner <[email protected]>Acked-by Thomas Gleixner <[email protected]>Signed-off-by Steven Rostedt <[email protected]>[...]
Quoted 7 lines
kernel/trace/trace.c +7
-0+void __init trace_init (void ) +{ +tracer_alloc_buffers (); +init_ftrace_syscalls (); +trace_event_init (); +} +[...]
kernel/trace/trace_events.c static __init int event_trace_init(void) · line 2487
Quoted 8 lines
kernel/trace/trace_events.c +8
-0+ +void __init trace_event_init (void ) +{ +event_trace_memsetup (); +init_ftrace_syscalls (); +event_trace_enable (); +} +
init_ftrace_syscalls()get called twice bytrace_init()andtrace_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 [email protected]
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()
Quoted 51 lines · Wang Nan
Ping...
Quoted 48 lines · Wang Nan
Hi Steven Rostedt,
During studying your code we find a problem, please see below.
Quoted 20 lines
From: "Steven Rostedt (Red Hat)" <[email protected]>
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 intoinit/main.cto right afterrcu_init().This also allows
trace_printk()to be used early too.Reviewed-by Paul E. McKenney <[email protected]>Suggested-by Thomas Gleixner <[email protected]>Tested-by Thomas Gleixner <[email protected]>Acked-by Thomas Gleixner <[email protected]>Signed-off-by Steven Rostedt <[email protected]>[...]
Quoted 7 lines
kernel/trace/trace.c +7
-0+void __init trace_init (void ) +{ +tracer_alloc_buffers (); +init_ftrace_syscalls (); +trace_event_init (); +} +[...]
kernel/trace/trace_events.c static __init int event_trace_init(void) · line 2487
Quoted 8 lines
kernel/trace/trace_events.c +8
-0+ +void __init trace_event_init (void ) +{ +event_trace_memsetup (); +init_ftrace_syscalls (); +event_trace_enable (); +} +
init_ftrace_syscalls()get called twice bytrace_init()andtrace_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
Steven Rostedt
maintainerRe: [PATCH 1/2] tracing: Move enabling tracepoints to just after rcu_init()
Quoted 12 lines · On Wed, 14 Jan 2015 10:09:05 +0900 Namhyung Kim <[email protected]> wrote:
Quoted 11 lines
Quoted 11 lines
kernel/trace/trace_events.c static __init int event_trace_init(void) · line 2487
Quoted 8 lines
kernel/trace/trace_events.c +8
-0+ +void __init trace_event_init (void ) +{ +event_trace_memsetup (); +init_ftrace_syscalls (); +event_trace_enable (); +} +
init_ftrace_syscalls()get called twice bytrace_init()andtrace_event_init(), some resources are wasted. At lease one of them can be removed.
Quoted 1 line
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
Steven Rostedt
maintainerPATCH 2/2 tracing: Add tp_printk cmdline to have tracepoints go to printk()
In reply to Steven RostedtFrom: "Steven Rostedt (Red Hat)" <[email protected]>
Add the kernel command line tp_printk option that will have tracepoints that are active sent to printk() as well as to the trace buffer.
Passing "tp_printk" will activate this. To turn it off, the sysctl /proc/sys/kernel/tracepoint_printk can have '0' echoed into it. Note, this only works if the cmdline option is used. Echoing 1 into the sysctl file without the cmdline option will have no affect.
Note, this is a dangerous option. Having high frequency tracepoints send their data to printk() can possibly cause a live lock. This is another reason why this is only active if the command line option is used.
--- Documentation/kernel-parameters.txt | 18 ++++++++++++++++++ include/linux/ftrace.h | 1 + kernel/sysctl.c | 7 +++++++ kernel/trace/trace.c | 17 +++++++++++++++++ kernel/trace/trace.h | 1 + kernel/trace/trace_events.c | 32 ++++++++++++++++++++++++++++++++ 6 files changed, 76 insertions(+)
Documentation/kernel-parameters.txt +18 -0
@@ -3500,6 +3500,24 @@ bytes respectively. Such letter suffixes can also be entirely omitted. See also Documentation/trace/ftrace.txt "trace options" section. + tp_printk[FTRACE] + Have the tracepoints sent to printk as well as the + tracing ring buffer. This is useful for early boot up + where the system hangs or reboots and does not give the + option for reading the tracing buffer or performing a + ftrace_dump_on_oops. + + To turn off having tracepoints sent to printk, + echo 0 > /proc/sys/kernel/tracepoint_printk + Note, echoing 1 into this file without the + tracepoint_printk kernel cmdline option has no effect. + + ** CAUTION ** + + Having tracepoints sent to printk() and activating high + frequency tracepoints such as irq or sched, can cause + the system to live lock. + traceoff_on_warning [FTRACE] enable this option to disable tracing when a warning is hit. This turns off "tracing_on". Tracing can
include/linux/ftrace.h +1 -0
@@ -879,6 +879,7 @@ static inline int test_tsk_trace_graph(struct task_struct *tsk)enum ftrace_dump_mode ;extern enum ftrace_dump_mode ftrace_dump_on_oops; +extern int tracepoint_printk;extern void disable_trace_on_warning (void );extern int __disable_trace_on_warning;
kernel/sysctl.c +7 -0
@@ -622,6 +622,13 @@ static struct ctl_table kern_table[] = { .mode = 0644, .proc_handler = proc_dointvec, }, + { + .procname = "tracepoint_printk", + .data = &tracepoint_printk, + .maxlen = sizeof(tracepoint_printk), + .mode = 0644, + .proc_handler = proc_dointvec, + },#endif #ifdef CONFIG_KEXEC {
kernel/trace/trace.c +17 -0
@@ -63,6 +63,10 @@ static bool __read_mostly tracing_selftest_running;*/ bool __read_mostly tracing_selftest_disabled; +/* Pipe tracepoints to printk */ +struct trace_iterator *tracepoint_print_iter; +int tracepoint_printk; +/* For tracers that don't implement custom flags */ static struct tracer_opt dummy_tracer_opt[] = { { }
@@ -193,6 +197,13 @@ static int __init set_trace_boot_clock(char *str) }__setup ("trace_clock=" , set_trace_boot_clock); +static int __init set_tracepoint_printk (char *str) +{ +if ((strcmp (str,"=0" ) !=0 &&strcmp (str,"=off" ) !=0 )) + tracepoint_printk =1 ; +return 1 ; +} +__setup ("tp_printk" , set_tracepoint_printk);unsigned long long ns2usecs (cycle_t nsec) {
@@ -6878,6 +6889,12 @@ out:void __init trace_init (void ) { +if (tracepoint_printk) { + tracepoint_print_iter = +kmalloc (sizeof (*tracepoint_print_iter),GFP_KERNEL ); +if (WARN_ON (!tracepoint_print_iter)) + tracepoint_printk =0 ; + }tracer_alloc_buffers ();init_ftrace_syscalls ();trace_event_init ();
kernel/trace/trace.h +1 -0
@@ -1313,5 +1313,6 @@ void trace_event_init(void);static inline void __init trace_event_init (void ) { }#endif +extern struct trace_iterator *tracepoint_print_iter;#endif /* _LINUX_KERNEL_TRACE_H */
kernel/trace/trace_events.c +32 -0
@@ -212,8 +212,40 @@ void *ftrace_event_buffer_reserve(struct ftrace_event_buffer *fbuffer, }EXPORT_SYMBOL_GPL (ftrace_event_buffer_reserve); +static DEFINE_SPINLOCK (tracepoint_iter_lock); + +static void output_printk (struct ftrace_event_buffer *fbuffer) +{ +struct ftrace_event_call *event_call; +struct trace_event *event; +unsigned long flags; +struct trace_iterator *iter = tracepoint_print_iter; + +if (!iter) +return ; + + event_call = fbuffer->ftrace_file->event_call; +if (!event_call || !event_call->event.funcs || + !event_call->event.funcs->trace) +return ; + + event = &fbuffer->ftrace_file->event_call->event; + +spin_lock_irqsave (&tracepoint_iter_lock, flags); +trace_seq_init (&iter->seq); + iter->ent = fbuffer->entry; + event_call->event.funcs->trace (iter,0 , event); +trace_seq_putc (&iter->seq,0 ); +printk ("%s" , iter->seq.buffer); + +spin_unlock_irqrestore (&tracepoint_iter_lock, flags); +} +void ftrace_event_buffer_commit (struct ftrace_event_buffer *fbuffer) { +if (tracepoint_printk) +output_printk (fbuffer); +event_trigger_unlock_commit (fbuffer->ftrace_file, fbuffer->buffer, fbuffer->event, fbuffer->entry, fbuffer->flags, fbuffer->pc);
Signature · 1 line
2.1.3