Messages in this thread Patch in this message | | | Date | Mon, 26 Mar 2018 10:34:49 -0400 | From | Steven Rostedt <> | Subject | Re: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events |
| |
On Mon, 26 Mar 2018 10:42:42 +0200 Peter Zijlstra <peterz@infradead.org> wrote:
> On Fri, Mar 23, 2018 at 04:04:41PM -0400, Steven Rostedt wrote: > > I would even argue that we remove the printks and use the trace events > > instead. There's already an option to make trace events be sent to > > printk(). I could have initcall_debug enable the trace events and send > > them to printk. > > Those printk()'s are so ever much more useful when you fail to boot and > can't get the trace buffer out.
That's why I said have initcall_debug send the trace events to printk. It would go to both the trace buffer and out to printk at the time of the trace event execution. You wouldn't notice a difference even if the system crashed at boot up.
The kernel command line parameter "tp_printk" will cause any tracepoint to be printed via printk() at the time of event execution. Of course this could be dangerous, because some trace events could cause a live lock if you enabled printk on them (scheduler and interrupt trace events). Thus, I would recommend instead just hooking to the trace events if initcall_debug is added. Then from the initcall handler, do the printks.
This patch below (on top of the three here), replaces initcall_debug with using tracepoints, but keeps the same functionality. In fact, it actually adds more, because the original initcall_debug ignored console and security initcalls. We now have this:
[ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] NR_IRQS: 8448, nr_irqs: 488, preallocated irqs: 16 [ 0.000000] calling con_init+0x0/0x224 @ 0 [ 0.000000] Console: colour VGA+ 80x25 [ 0.000000] console [tty0] enabled [ 0.000000] initcall con_init+0x0/0x224 returned 0 after 0 usecs [ 0.000000] calling hvc_console_init+0x0/0x19 @ 0 [ 0.000000] initcall hvc_console_init+0x0/0x19 returned 0 after 0 usecs [ 0.000000] calling xen_cons_init+0x0/0x60 @ 0 [ 0.000000] initcall xen_cons_init+0x0/0x60 returned 0 after 0 usecs [ 0.000000] calling univ8250_console_init+0x0/0x2d @ 0 [ 0.000000] console [ttyS0] enabled [..] [ 0.012001] pid_max: default: 32768 minimum: 301 [ 0.013053] Security Framework initialized [ 0.014004] calling selinux_init+0x0/0x17c @ 0 [ 0.014005] SELinux: Disabled at boot. [ 0.015001] initcall selinux_init+0x0/0x17c returned 0 after 976 usecs [ 0.015003] calling integrity_iintcache_init+0x0/0x33 @ 0 [ 0.015008] initcall integrity_iintcache_init+0x0/0x33 returned 0 after 0 usecs [ 0.016154] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes) [..]
Yes, the timing of the consoles is useless, but we still get to see them.
-- Steve
diff --git a/init/main.c b/init/main.c index 2af8f2bb5ca8..589d1226016e 100644 --- a/init/main.c +++ b/init/main.c @@ -494,6 +494,10 @@ void __init __weak thread_stack_cache_init(void) void __init __weak mem_encrypt_init(void) { } +bool initcall_debug; +core_param(initcall_debug, initcall_debug, bool, 0644); +static void __init initcall_debug_enable(void); + /* * Set up kernel memory allocators */ @@ -615,6 +619,9 @@ asmlinkage __visible void __init start_kernel(void) /* Trace events are available after this */ trace_init(); + if (initcall_debug) + initcall_debug_enable(); + context_tracking_init(); /* init some links before init_ISA_irqs() */ early_irq_init(); @@ -731,9 +738,6 @@ static void __init do_ctors(void) #endif } -bool initcall_debug; -core_param(initcall_debug, initcall_debug, bool, 0644); - #ifdef CONFIG_KALLSYMS struct blacklist_entry { struct list_head next; @@ -803,38 +807,53 @@ static bool __init_or_module initcall_blacklisted(initcall_t fn) #endif __setup("initcall_blacklist=", initcall_blacklist); -static int __init_or_module do_one_initcall_debug(initcall_t fn) +static __init_or_module void +trace_initcall_start_cb(void *data, initcall_t fn) { - ktime_t calltime, delta, rettime; - unsigned long long duration; - int ret; + ktime_t *calltime = (ktime_t *)data; printk(KERN_DEBUG "calling %pF @ %i\n", fn, task_pid_nr(current)); - calltime = ktime_get(); - ret = fn(); + *calltime = ktime_get(); +} + +static __init_or_module void +trace_initcall_finish_cb(void *data, initcall_t fn, int ret) +{ + ktime_t *calltime = (ktime_t *)data; + ktime_t delta, rettime; + unsigned long long duration; + rettime = ktime_get(); - delta = ktime_sub(rettime, calltime); + delta = ktime_sub(rettime, *calltime); duration = (unsigned long long) ktime_to_ns(delta) >> 10; printk(KERN_DEBUG "initcall %pF returned %d after %lld usecs\n", fn, ret, duration); +} - return ret; +static ktime_t initcall_calltime; + +static void __init initcall_debug_enable(void) +{ + int ret; + + ret = register_trace_initcall_start(trace_initcall_start_cb, + &initcall_calltime); + ret |= register_trace_initcall_finish(trace_initcall_finish_cb, + &initcall_calltime); + WARN(ret, "Failed to register initcall tracepoints\n"); } int __init_or_module do_one_initcall(initcall_t fn) { int count = preempt_count(); - int ret; char msgbuf[64]; + int ret; if (initcall_blacklisted(fn)) return -EPERM; trace_initcall_start(fn); - if (initcall_debug) - ret = do_one_initcall_debug(fn); - else - ret = fn(); + ret = fn(); trace_initcall_finish(fn, ret); msgbuf[0] = 0;
| |