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

[Steven Rostedt]

On Mon, 26 Mar 2018 18:50:32 -0700
"Joel Fernandes (Google)"  wrote:

> > -0 [000] ...1 0.00: initcall_level: level=console
> > -0 [000] ...1 0.00: initcall_start: 
> > func=con_init+0x0/0x224
> > -0 [000] ...1 0.00: initcall_finish: 
> > func=con_init+0x0/0x224 ret=0
> > -0 [000] ...1 0.00: initcall_start: 
> > func=hvc_console_init+0x0/0x19
> > -0 [000] ...1 0.00: initcall_finish: 
> > func=hvc_console_init+0x0/0x19 ret=0
> > -0 [000] ...1 0.00: initcall_start: 
> > func=xen_cons_init+0x0/0x60
> > -0 [000] ...1 0.00: initcall_finish: 
> > func=xen_cons_init+0x0/0x60 ret=0
> > -0 [000] ...1 0.00: initcall_start: 
> > func=univ8250_console_init+0x0/0x2d
> > -0 [000] ...1 0.00: initcall_finish: 
> > func=univ8250_console_init+0x0/0x2d ret=0  
> 
> Will this make initcall_debug not work if CONFIG_TRACEPOINTS is turned
> off? Although it builds but I think this initcall_debug feature will

Yeah probably.

> fail, maybe CONFIG_TRACEPOINTS should be selected somewhere?

Agreed. Or I can see if I can find a way to have it fall into its old
behavior when tracepoints are not configured.

-- Steve


> 
> I recently ran into some issues like this for my preemptirq
> tracepoints patch (which I will post again soon :D) where lockdep
> needed the tracepoints and I had to select it.
> 
> thanks,
> 
> - Joel

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

[Steven Rostedt]

On Mon, 26 Mar 2018 18:50:32 -0700
"Joel Fernandes (Google)"  wrote:

> > -0 [000] ...1 0.00: initcall_level: level=console
> > -0 [000] ...1 0.00: initcall_start: 
> > func=con_init+0x0/0x224
> > -0 [000] ...1 0.00: initcall_finish: 
> > func=con_init+0x0/0x224 ret=0
> > -0 [000] ...1 0.00: initcall_start: 
> > func=hvc_console_init+0x0/0x19
> > -0 [000] ...1 0.00: initcall_finish: 
> > func=hvc_console_init+0x0/0x19 ret=0
> > -0 [000] ...1 0.00: initcall_start: 
> > func=xen_cons_init+0x0/0x60
> > -0 [000] ...1 0.00: initcall_finish: 
> > func=xen_cons_init+0x0/0x60 ret=0
> > -0 [000] ...1 0.00: initcall_start: 
> > func=univ8250_console_init+0x0/0x2d
> > -0 [000] ...1 0.00: initcall_finish: 
> > func=univ8250_console_init+0x0/0x2d ret=0  
> 
> Will this make initcall_debug not work if CONFIG_TRACEPOINTS is turned
> off? Although it builds but I think this initcall_debug feature will

Yeah probably.

> fail, maybe CONFIG_TRACEPOINTS should be selected somewhere?

Agreed. Or I can see if I can find a way to have it fall into its old
behavior when tracepoints are not configured.

-- Steve


> 
> I recently ran into some issues like this for my preemptirq
> tracepoints patch (which I will post again soon :D) where lockdep
> needed the tracepoints and I had to select it.
> 
> thanks,
> 
> - Joel

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

[Joel Fernandes (Google)]

Hi Steve,

On Fri, Mar 23, 2018 at 8:02 AM, Steven Rostedt  wrote:
> A while ago we had a boot tracer. But it was eventually removed:
>  commit 30dbb20e68e6f ("tracing: Remove boot tracer").
>
> The rational was because there is already a initcall_debug boot option
> that causes printk()s of all the initcall functions.
>
> The problem with the initcall_debug option is that printk() is awfully slow,
> and makes it difficult to see the real impact of initcalls. Mainly because
> a single printk() is usually slower than most initcall functions.
>
> Instead of bringing back the boot tracer, adding trace events around the
> initcall functions, and even one to denote which level the initcall
> functions are being called from, adds the necessary information to
> analyze the initcalls without the high overhead of printk()s, that
> can substantially slow down the boot process.
>
> Another positive, is that the console initcall functions themselves
> can also be traced. The timestamps are not operational at that time
> but you can see which consoles are being registered. I saw this on
> one of my test boxes:
>
> -0 [000] ...1 0.00: initcall_level: level=console
> -0 [000] ...1 0.00: initcall_start: func=con_init+0x0/0x224
> -0 [000] ...1 0.00: initcall_finish: 
> func=con_init+0x0/0x224 ret=0
> -0 [000] ...1 0.00: initcall_start: 
> func=hvc_console_init+0x0/0x19
> -0 [000] ...1 0.00: initcall_finish: 
> func=hvc_console_init+0x0/0x19 ret=0
> -0 [000] ...1 0.00: initcall_start: 
> func=xen_cons_init+0x0/0x60
> -0 [000] ...1 0.00: initcall_finish: 
> func=xen_cons_init+0x0/0x60 ret=0
> -0 [000] ...1 0.00: initcall_start: 
> func=univ8250_console_init+0x0/0x2d
> -0 [000] ...1 0.00: initcall_finish: 
> func=univ8250_console_init+0x0/0x2d ret=0

Will this make initcall_debug not work if CONFIG_TRACEPOINTS is turned
off? Although it builds but I think this initcall_debug feature will
fail, maybe CONFIG_TRACEPOINTS should be selected somewhere?

I recently ran into some issues like this for my preemptirq
tracepoints patch (which I will post again soon :D) where lockdep
needed the tracepoints and I had to select it.

thanks,

- Joel

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

[Joel Fernandes (Google)]

Hi Steve,

On Fri, Mar 23, 2018 at 8:02 AM, Steven Rostedt  wrote:
> A while ago we had a boot tracer. But it was eventually removed:
>  commit 30dbb20e68e6f ("tracing: Remove boot tracer").
>
> The rational was because there is already a initcall_debug boot option
> that causes printk()s of all the initcall functions.
>
> The problem with the initcall_debug option is that printk() is awfully slow,
> and makes it difficult to see the real impact of initcalls. Mainly because
> a single printk() is usually slower than most initcall functions.
>
> Instead of bringing back the boot tracer, adding trace events around the
> initcall functions, and even one to denote which level the initcall
> functions are being called from, adds the necessary information to
> analyze the initcalls without the high overhead of printk()s, that
> can substantially slow down the boot process.
>
> Another positive, is that the console initcall functions themselves
> can also be traced. The timestamps are not operational at that time
> but you can see which consoles are being registered. I saw this on
> one of my test boxes:
>
> -0 [000] ...1 0.00: initcall_level: level=console
> -0 [000] ...1 0.00: initcall_start: func=con_init+0x0/0x224
> -0 [000] ...1 0.00: initcall_finish: 
> func=con_init+0x0/0x224 ret=0
> -0 [000] ...1 0.00: initcall_start: 
> func=hvc_console_init+0x0/0x19
> -0 [000] ...1 0.00: initcall_finish: 
> func=hvc_console_init+0x0/0x19 ret=0
> -0 [000] ...1 0.00: initcall_start: 
> func=xen_cons_init+0x0/0x60
> -0 [000] ...1 0.00: initcall_finish: 
> func=xen_cons_init+0x0/0x60 ret=0
> -0 [000] ...1 0.00: initcall_start: 
> func=univ8250_console_init+0x0/0x2d
> -0 [000] ...1 0.00: initcall_finish: 
> func=univ8250_console_init+0x0/0x2d ret=0

Will this make initcall_debug not work if CONFIG_TRACEPOINTS is turned
off? Although it builds but I think this initcall_debug feature will
fail, maybe CONFIG_TRACEPOINTS should be selected somewhere?

I recently ran into some issues like this for my preemptirq
tracepoints patch (which I will post again soon :D) where lockdep
needed the tracepoints and I had to select it.

thanks,

- Joel

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

[Steven Rostedt]

On Mon, 26 Mar 2018 10:42:42 +0200
Peter Zijlstra  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.00] kmemleak: Kernel memory leak detector disabled
[0.00] NR_IRQS: 8448, nr_irqs: 488, preallocated irqs: 16
[0.00] calling  con_init+0x0/0x224 @ 0
[0.00] Console: colour VGA+ 80x25
[0.00] console [tty0] enabled
[0.00] initcall con_init+0x0/0x224 returned 0 after 0 usecs
[0.00] calling  hvc_console_init+0x0/0x19 @ 0
[0.00] initcall hvc_console_init+0x0/0x19 returned 0 after 0 usecs
[0.00] calling  xen_cons_init+0x0/0x60 @ 0
[0.00] initcall xen_cons_init+0x0/0x60 returned 0 after 0 usecs
[0.00] calling  univ8250_console_init+0x0/0x2d @ 0
[0.00] 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,
+   

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

[Steven Rostedt]

On Mon, 26 Mar 2018 10:42:42 +0200
Peter Zijlstra  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.00] kmemleak: Kernel memory leak detector disabled
[0.00] NR_IRQS: 8448, nr_irqs: 488, preallocated irqs: 16
[0.00] calling  con_init+0x0/0x224 @ 0
[0.00] Console: colour VGA+ 80x25
[0.00] console [tty0] enabled
[0.00] initcall con_init+0x0/0x224 returned 0 after 0 usecs
[0.00] calling  hvc_console_init+0x0/0x19 @ 0
[0.00] initcall hvc_console_init+0x0/0x19 returned 0 after 0 usecs
[0.00] calling  xen_cons_init+0x0/0x60 @ 0
[0.00] initcall xen_cons_init+0x0/0x60 returned 0 after 0 usecs
[0.00] calling  univ8250_console_init+0x0/0x2d @ 0
[0.00] 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,
+ 

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

[Peter Zijlstra]

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.

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

[Peter Zijlstra]

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.

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

[Steven Rostedt]

On Fri, 23 Mar 2018 12:50:16 -0700
Andrew Morton  wrote:

> On Fri, 23 Mar 2018 11:02:41 -0400 Steven Rostedt  wrote:
> 
> > A while ago we had a boot tracer. But it was eventually removed:
> >  commit 30dbb20e68e6f ("tracing: Remove boot tracer").
> > 
> > The rational was because there is already a initcall_debug boot option
> > that causes printk()s of all the initcall functions.  
> 
> "rationale" :)

I hate English.

> 
> > The problem with the initcall_debug option is that printk() is awfully slow,
> > and makes it difficult to see the real impact of initcalls. Mainly because
> > a single printk() is usually slower than most initcall functions.  
> 
> Not understanding this.  We do it correctly:
> 
>   calltime = ktime_get();
>   ret = fn();
>   rettime = ktime_get();
> 
> so the displayed initcall timing is independent of the printk()
> execution time?
> 

It's not just the timing, it's the fact that init_debug printks disrupts
the boot process, where as tracing is less invasive to the
general runtime.

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.

-- Steve

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

[Steven Rostedt]

On Fri, 23 Mar 2018 12:50:16 -0700
Andrew Morton  wrote:

> On Fri, 23 Mar 2018 11:02:41 -0400 Steven Rostedt  wrote:
> 
> > A while ago we had a boot tracer. But it was eventually removed:
> >  commit 30dbb20e68e6f ("tracing: Remove boot tracer").
> > 
> > The rational was because there is already a initcall_debug boot option
> > that causes printk()s of all the initcall functions.  
> 
> "rationale" :)

I hate English.

> 
> > The problem with the initcall_debug option is that printk() is awfully slow,
> > and makes it difficult to see the real impact of initcalls. Mainly because
> > a single printk() is usually slower than most initcall functions.  
> 
> Not understanding this.  We do it correctly:
> 
>   calltime = ktime_get();
>   ret = fn();
>   rettime = ktime_get();
> 
> so the displayed initcall timing is independent of the printk()
> execution time?
> 

It's not just the timing, it's the fact that init_debug printks disrupts
the boot process, where as tracing is less invasive to the
general runtime.

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.

-- Steve

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

[Andrew Morton]

On Fri, 23 Mar 2018 11:02:41 -0400 Steven Rostedt  wrote:

> A while ago we had a boot tracer. But it was eventually removed:
>  commit 30dbb20e68e6f ("tracing: Remove boot tracer").
> 
> The rational was because there is already a initcall_debug boot option
> that causes printk()s of all the initcall functions.

"rationale" :)

> The problem with the initcall_debug option is that printk() is awfully slow,
> and makes it difficult to see the real impact of initcalls. Mainly because
> a single printk() is usually slower than most initcall functions.

Not understanding this.  We do it correctly:

calltime = ktime_get();
ret = fn();
rettime = ktime_get();

so the displayed initcall timing is independent of the printk()
execution time?

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

[Andrew Morton]

On Fri, 23 Mar 2018 11:02:41 -0400 Steven Rostedt  wrote:

> A while ago we had a boot tracer. But it was eventually removed:
>  commit 30dbb20e68e6f ("tracing: Remove boot tracer").
> 
> The rational was because there is already a initcall_debug boot option
> that causes printk()s of all the initcall functions.

"rationale" :)

> The problem with the initcall_debug option is that printk() is awfully slow,
> and makes it difficult to see the real impact of initcalls. Mainly because
> a single printk() is usually slower than most initcall functions.

Not understanding this.  We do it correctly:

calltime = ktime_get();
ret = fn();
rettime = ktime_get();

so the displayed initcall timing is independent of the printk()
execution time?

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

[Steven Rostedt]

A while ago we had a boot tracer. But it was eventually removed:
 commit 30dbb20e68e6f ("tracing: Remove boot tracer").

The rational was because there is already a initcall_debug boot option
that causes printk()s of all the initcall functions.

The problem with the initcall_debug option is that printk() is awfully slow,
and makes it difficult to see the real impact of initcalls. Mainly because
a single printk() is usually slower than most initcall functions.

Instead of bringing back the boot tracer, adding trace events around the
initcall functions, and even one to denote which level the initcall
functions are being called from, adds the necessary information to
analyze the initcalls without the high overhead of printk()s, that
can substantially slow down the boot process.

Another positive, is that the console initcall functions themselves
can also be traced. The timestamps are not operational at that time
but you can see which consoles are being registered. I saw this on
one of my test boxes:

-0 [000] ...1 0.00: initcall_level: level=console
-0 [000] ...1 0.00: initcall_start: func=con_init+0x0/0x224
-0 [000] ...1 0.00: initcall_finish: func=con_init+0x0/0x224 
ret=0
-0 [000] ...1 0.00: initcall_start: 
func=hvc_console_init+0x0/0x19
-0 [000] ...1 0.00: initcall_finish: 
func=hvc_console_init+0x0/0x19 ret=0
-0 [000] ...1 0.00: initcall_start: 
func=xen_cons_init+0x0/0x60
-0 [000] ...1 0.00: initcall_finish: 
func=xen_cons_init+0x0/0x60 ret=0
-0 [000] ...1 0.00: initcall_start: 
func=univ8250_console_init+0x0/0x2d
-0 [000] ...1 0.00: initcall_finish: 
func=univ8250_console_init+0x0/0x2d ret=0

I didn't even realize that I had some of those consoles configured.

Anyone have any issues with me adding this?

-- Steve
 

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
ftrace/initcall

Head SHA1: d79328aaa2173bc72c938fa6f33ff6142ad79336


Abderrahmane Benbachir (1):
  init, tracing: instrument security and console initcall trace events

Steven Rostedt (VMware) (2):
  init: Fix initcall0 name as it is "pure" not "early"
  init, tracing: Add initcall trace events


 include/trace/events/initcall.h | 66 +
 init/main.c |  9 +-
 kernel/printk/printk.c  |  7 -
 security/security.c |  8 -
 4 files changed, 87 insertions(+), 3 deletions(-)
 create mode 100644 include/trace/events/initcall.h

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

[Steven Rostedt]

A while ago we had a boot tracer. But it was eventually removed:
 commit 30dbb20e68e6f ("tracing: Remove boot tracer").

The rational was because there is already a initcall_debug boot option
that causes printk()s of all the initcall functions.

The problem with the initcall_debug option is that printk() is awfully slow,
and makes it difficult to see the real impact of initcalls. Mainly because
a single printk() is usually slower than most initcall functions.

Instead of bringing back the boot tracer, adding trace events around the
initcall functions, and even one to denote which level the initcall
functions are being called from, adds the necessary information to
analyze the initcalls without the high overhead of printk()s, that
can substantially slow down the boot process.

Another positive, is that the console initcall functions themselves
can also be traced. The timestamps are not operational at that time
but you can see which consoles are being registered. I saw this on
one of my test boxes:

-0 [000] ...1 0.00: initcall_level: level=console
-0 [000] ...1 0.00: initcall_start: func=con_init+0x0/0x224
-0 [000] ...1 0.00: initcall_finish: func=con_init+0x0/0x224 
ret=0
-0 [000] ...1 0.00: initcall_start: 
func=hvc_console_init+0x0/0x19
-0 [000] ...1 0.00: initcall_finish: 
func=hvc_console_init+0x0/0x19 ret=0
-0 [000] ...1 0.00: initcall_start: 
func=xen_cons_init+0x0/0x60
-0 [000] ...1 0.00: initcall_finish: 
func=xen_cons_init+0x0/0x60 ret=0
-0 [000] ...1 0.00: initcall_start: 
func=univ8250_console_init+0x0/0x2d
-0 [000] ...1 0.00: initcall_finish: 
func=univ8250_console_init+0x0/0x2d ret=0

I didn't even realize that I had some of those consoles configured.

Anyone have any issues with me adding this?

-- Steve
 

  git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
ftrace/initcall

Head SHA1: d79328aaa2173bc72c938fa6f33ff6142ad79336


Abderrahmane Benbachir (1):
  init, tracing: instrument security and console initcall trace events

Steven Rostedt (VMware) (2):
  init: Fix initcall0 name as it is "pure" not "early"
  init, tracing: Add initcall trace events


 include/trace/events/initcall.h | 66 +
 init/main.c |  9 +-
 kernel/printk/printk.c  |  7 -
 security/security.c |  8 -
 4 files changed, 87 insertions(+), 3 deletions(-)
 create mode 100644 include/trace/events/initcall.h