Re: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events

From: Steven Rostedt
Date: Mon Mar 26 2018 - 10:34:58 EST


On Mon, 26 Mar 2018 10:42:42 +0200
Peter Zijlstra <peterz@xxxxxxxxxxxxx> 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;