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

[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:

<idle>-0     [000] ...1     0.000000: initcall_level: level=console
<idle>-0     [000] ...1     0.000000: initcall_start: func=con_init+0x0/0x224
<idle>-0     [000] ...1     0.000000: initcall_finish: func=con_init+0x0/0x224 ret=0
<idle>-0     [000] ...1     0.000000: initcall_start: func=hvc_console_init+0x0/0x19
<idle>-0     [000] ...1     0.000000: initcall_finish: func=hvc_console_init+0x0/0x19 ret=0
<idle>-0     [000] ...1     0.000000: initcall_start: func=xen_cons_init+0x0/0x60
<idle>-0     [000] ...1     0.000000: initcall_finish: func=xen_cons_init+0x0/0x60 ret=0
<idle>-0     [000] ...1     0.000000: initcall_start: func=univ8250_console_init+0x0/0x2d
<idle>-0     [000] ...1     0.000000: 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 1/3] init: Fix initcall0 name as it is "pure" not "early"

[Steven Rostedt]

[-- Attachment #1: 0001-init-Fix-initcall0-name-as-it-is-pure-not-early.patch --]
[-- Type: text/plain, Size: 1006 bytes --]

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

The early_initcall() functions get assigned to __initcall_start[]. These are
called by do_pre_smp_initcalls(). The initcall_levels[] array starts with
__initcall0_start[], and initcall_levels[] are to match the
initcall_level_names[] array. The first name in that array is "early", but
that is not correct. As pure_initcall() functions get assigned to
__initcall0_start[] array.

Change the first name in initcall_level_names[] array to "pure".

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 init/main.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/init/main.c b/init/main.c
index 969eaf140ef0..0ebdd5f15be8 100644
--- a/init/main.c
+++ b/init/main.c
@@ -874,7 +874,7 @@ static initcall_t *initcall_levels[] __initdata = {
 
 /* Keep these in sync with initcalls in include/linux/init.h */
 static char *initcall_level_names[] __initdata = {
-	"early",
+	"pure",
 	"core",
 	"postcore",
 	"arch",
-- 
2.15.1

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

[Steven Rostedt]

[-- Attachment #1: 0002-init-tracing-Add-initcall-trace-events.patch --]
[-- Type: text/plain, Size: 3441 bytes --]

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

Being able to trace the start and stop of initcalls is useful to see where
the timings are an issue. There is already an "initcall_debug" parameter,
but that can cause a large overhead itself, as the printing of the
information may take longer than the initcall functions.

Adding in a start and finish trace event around the initcall functions, as
well as a trace event that records the level of the initcalls, one can get a
much finer measurement of the times and interactions of the initcalls
themselves, as trace events are much lighter than printk()s.

Suggested-by: Abderrahmane Benbachir <abderrahmane.benbachir@polymtl.ca>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/trace/events/initcall.h | 66 +++++++++++++++++++++++++++++++++++++++++
 init/main.c                     |  7 +++++
 2 files changed, 73 insertions(+)
 create mode 100644 include/trace/events/initcall.h

diff --git a/include/trace/events/initcall.h b/include/trace/events/initcall.h
new file mode 100644
index 000000000000..8d6cf10d27c9
--- /dev/null
+++ b/include/trace/events/initcall.h
@@ -0,0 +1,66 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM initcall
+
+#if !defined(_TRACE_INITCALL_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_INITCALL_H
+
+#include <linux/tracepoint.h>
+
+TRACE_EVENT(initcall_level,
+
+	TP_PROTO(const char *level),
+
+	TP_ARGS(level),
+
+	TP_STRUCT__entry(
+		__string(level, level)
+	),
+
+	TP_fast_assign(
+		__assign_str(level, level);
+	),
+
+	TP_printk("level=%s", __get_str(level))
+);
+
+TRACE_EVENT(initcall_start,
+
+	TP_PROTO(initcall_t func),
+
+	TP_ARGS(func),
+
+	TP_STRUCT__entry(
+		__field(initcall_t, func)
+	),
+
+	TP_fast_assign(
+		__entry->func = func;
+	),
+
+	TP_printk("func=%pS", __entry->func)
+);
+
+TRACE_EVENT(initcall_finish,
+
+	TP_PROTO(initcall_t func, int ret),
+
+	TP_ARGS(func, ret),
+
+	TP_STRUCT__entry(
+		__field(initcall_t,	func)
+		__field(int,		ret)
+	),
+
+	TP_fast_assign(
+		__entry->func = func;
+		__entry->ret = ret;
+	),
+
+	TP_printk("func=%pS ret=%d", __entry->func, __entry->ret)
+);
+
+#endif /* if !defined(_TRACE_GPIO_H) || defined(TRACE_HEADER_MULTI_READ) */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/init/main.c b/init/main.c
index 0ebdd5f15be8..2af8f2bb5ca8 100644
--- a/init/main.c
+++ b/init/main.c
@@ -97,6 +97,9 @@
 #include <asm/sections.h>
 #include <asm/cacheflush.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/initcall.h>
+
 static int kernel_init(void *);
 
 extern void init_IRQ(void);
@@ -827,10 +830,12 @@ int __init_or_module do_one_initcall(initcall_t fn)
 	if (initcall_blacklisted(fn))
 		return -EPERM;
 
+	trace_initcall_start(fn);
 	if (initcall_debug)
 		ret = do_one_initcall_debug(fn);
 	else
 		ret = fn();
+	trace_initcall_finish(fn, ret);
 
 	msgbuf[0] = 0;
 
@@ -895,6 +900,7 @@ static void __init do_initcall_level(int level)
 		   level, level,
 		   NULL, &repair_env_string);
 
+	trace_initcall_level(initcall_level_names[level]);
 	for (fn = initcall_levels[level]; fn < initcall_levels[level+1]; fn++)
 		do_one_initcall(*fn);
 }
@@ -929,6 +935,7 @@ static void __init do_pre_smp_initcalls(void)
 {
 	initcall_t *fn;
 
+	trace_initcall_level("early");
 	for (fn = __initcall_start; fn < __initcall0_start; fn++)
 		do_one_initcall(*fn);
 }
-- 
2.15.1

[PATCH 3/3] init, tracing: instrument security and console initcall trace events

[Steven Rostedt]

[-- Attachment #1: 0003-init-tracing-instrument-security-and-console-initcal.patch --]
[-- Type: text/plain, Size: 2272 bytes --]

From: Abderrahmane Benbachir <abderrahmane.benbachir@polymtl.ca>

Trace events have been added around the initcall functions defined in
init/main.c. But console and security have their own initcalls. This adds
the trace events associated for those initcall functions.

Link: http://lkml.kernel.org/r/1521765208.19745.2.camel@polymtl.ca

Cc: Ingo Molnar <mingo@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Signed-off-by: Abderrahmane Benbachir <abderrahmane.benbachir@polymtl.ca>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/printk/printk.c | 7 ++++++-
 security/security.c    | 8 +++++++-
 2 files changed, 13 insertions(+), 2 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index f274fbef821d..cb5b35341d69 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -52,6 +52,7 @@
 #include <linux/uaccess.h>
 #include <asm/sections.h>
 
+#include <trace/events/initcall.h>
 #define CREATE_TRACE_POINTS
 #include <trace/events/printk.h>
 
@@ -2781,6 +2782,7 @@ EXPORT_SYMBOL(unregister_console);
  */
 void __init console_init(void)
 {
+	int ret;
 	initcall_t *call;
 
 	/* Setup the default TTY line discipline. */
@@ -2791,8 +2793,11 @@ void __init console_init(void)
 	 * inform about problems etc..
 	 */
 	call = __con_initcall_start;
+	trace_initcall_level("console");
 	while (call < __con_initcall_end) {
-		(*call)();
+		trace_initcall_start((*call));
+		ret = (*call)();
+		trace_initcall_finish((*call), ret);
 		call++;
 	}
 }
diff --git a/security/security.c b/security/security.c
index 1cd8526cb0b7..987afe3d464c 100644
--- a/security/security.c
+++ b/security/security.c
@@ -30,6 +30,8 @@
 #include <linux/string.h>
 #include <net/flow.h>
 
+#include <trace/events/initcall.h>
+
 #define MAX_LSM_EVM_XATTR	2
 
 /* Maximum number of letters for an LSM name string */
@@ -45,10 +47,14 @@ static __initdata char chosen_lsm[SECURITY_NAME_MAX + 1] =
 
 static void __init do_security_initcalls(void)
 {
+	int ret;
 	initcall_t *call;
 	call = __security_initcall_start;
+	trace_initcall_level("security");
 	while (call < __security_initcall_end) {
-		(*call) ();
+		trace_initcall_start((*call));
+		ret = (*call) ();
+		trace_initcall_finish((*call), ret);
 		call++;
 	}
 }
-- 
2.15.1

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

[Andrew Morton]

On Fri, 23 Mar 2018 11:02:41 -0400 Steven Rostedt <rostedt@goodmis.org> 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

[Steven Rostedt]

On Fri, 23 Mar 2018 12:50:16 -0700
Andrew Morton <akpm@linux-foundation.org> wrote:

> On Fri, 23 Mar 2018 11:02:41 -0400 Steven Rostedt <rostedt@goodmis.org> 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

[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 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;

[PATCH 4/3] init, tracing: Have printk come through the trace events for initcall_debug

[Steven Rostedt]

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

With trace events set before and after the initcall function calls, instead
of having a separate routine for printing out the initcalls when
initcall_debug is specified on the kernel command line, have the code
register a callback to the tracepoints where the initcall trace events are.

This removes the need for having a separate function to do the initcalls as
the tracepoint callbacks can handle the printk. It also includes other
initcalls that are not called by the do_one_initcall() which includes
console and security initcalls.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 init/main.c | 51 +++++++++++++++++++++++++++++++++++----------------
 1 file changed, 35 insertions(+), 16 deletions(-)

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;
-- 
2.13.6

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 <rostedt@goodmis.org> 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:
>
> <idle>-0     [000] ...1     0.000000: initcall_level: level=console
> <idle>-0     [000] ...1     0.000000: initcall_start: func=con_init+0x0/0x224
> <idle>-0     [000] ...1     0.000000: initcall_finish: func=con_init+0x0/0x224 ret=0
> <idle>-0     [000] ...1     0.000000: initcall_start: func=hvc_console_init+0x0/0x19
> <idle>-0     [000] ...1     0.000000: initcall_finish: func=hvc_console_init+0x0/0x19 ret=0
> <idle>-0     [000] ...1     0.000000: initcall_start: func=xen_cons_init+0x0/0x60
> <idle>-0     [000] ...1     0.000000: initcall_finish: func=xen_cons_init+0x0/0x60 ret=0
> <idle>-0     [000] ...1     0.000000: initcall_start: func=univ8250_console_init+0x0/0x2d
> <idle>-0     [000] ...1     0.000000: 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 18:50:32 -0700
"Joel Fernandes (Google)" <joel.opensrc@gmail.com> wrote:

> > <idle>-0     [000] ...1     0.000000: initcall_level: level=console
> > <idle>-0     [000] ...1     0.000000: initcall_start: func=con_init+0x0/0x224
> > <idle>-0     [000] ...1     0.000000: initcall_finish: func=con_init+0x0/0x224 ret=0
> > <idle>-0     [000] ...1     0.000000: initcall_start: func=hvc_console_init+0x0/0x19
> > <idle>-0     [000] ...1     0.000000: initcall_finish: func=hvc_console_init+0x0/0x19 ret=0
> > <idle>-0     [000] ...1     0.000000: initcall_start: func=xen_cons_init+0x0/0x60
> > <idle>-0     [000] ...1     0.000000: initcall_finish: func=xen_cons_init+0x0/0x60 ret=0
> > <idle>-0     [000] ...1     0.000000: initcall_start: func=univ8250_console_init+0x0/0x2d
> > <idle>-0     [000] ...1     0.000000: 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