ftrace: support boot level tracing

Hi Steve.

Initcall's tracing support have been recently added to ftrace, which enables detecting latencies within each initcall function. The main concern here is, enabling initcall's tracing (which is fine-grained) will add a lots of overhead during boot-up. So with boot level tracing we can get the overall picture, with low overhead, then we can use function tracing with filters to dig into more specific path.

This is an example of boot level sequence, with the first initcall and the last initcall that were retrieved dynamically at runtime:

0,console, first=con_init, last=univ8250_console_init
1,security, first=selinux_init, last=integrity_iintcache_init

2,early,    first=trace_init_flags_sys_exit,	last=initialize_ptr_random
3,pure,     first=ipc_ns_init,			last=net_ns_init
4,core,     first=xen_pvh_gnttab_setup,		last=__gnttab_init

5,postcore, first=irq_sysfs_init, last=kobject_uevent_init
6,arch, first=bts_init, last=pci_arch_init
7,subsys, first=init_vdso, last=watchdog_init
8,fs, first=nmi_warning_debugfs, last=acpi_reserve_resources

9,rootfs,   first=populate_rootfs,		last=ir_dev_scope_init
10,device,  first=ia32_binfmt_init,		last=mcheck_init_device
11,late,    first=tboot_late_init,		last=regulator_init_complete

To make it properly work, the idea is to register at boot time function based events on the first and the last initcall of each boot level.

The created events will be recycled when the last sequence is reached.

This patch is only a proof of concept, I didn't use function based events mechanism, I only changed the first and last initcalls to point to some handlers, which worked fine, but need to changed:
+ (*first_initcall_fn) = trace_bootlevel_start_handler;
+ (*last_initcall_fn) = trace_bootlevel_end_handler;

I made this patch to get some feedbacks, and to know if this could be an interresting feature to have in ftrace ?

Trace example when enabling boot level tracing along with function tracing:

[    0.367507] : trace_bootlevel_start_handler: Start console boot level <----
[    0.368240] : con_init <-console_init
...
[    0.371869] : xen_cons_init <-console_init
[    0.372409] : univ8250_console_init <-trace_bootlevel_end_handler
[    0.373116] : trace_bootlevel_end_handler: End console boot level <----
...
[    0.385005] : security_init <-start_kernel
[    0.385550] : trace_bootlevel_start_handler: Start security boot level <----
[    0.386291] : selinux_init <-security_init
[    0.386831] : smack_init <-security_init
[    0.387358] : tomoyo_init <-security_init
[    0.387893] : apparmor_init <-security_init
[    0.390694] : integrity_iintcache_init <-trace_bootlevel_end_handler
[    0.391418] : trace_bootlevel_end_handler: End security boot level <----
...
[    0.455924] : trace_bootlevel_start_handler: Start early boot level <----
[    0.456659] : intel_pmu_init <-init_hw_perf_events
[    0.457299] : p6_pmu_init <-intel_pmu_init
[    0.457851] : numachip_system_init <-do_one_initcall

...

---
 kernel/trace/Makefile          |   1 +
 kernel/trace/trace_bootlevel.c | 137 +++++++++++++++++++++++++++++++++++++++++
 2 files changed, 138 insertions(+)
 create mode 100644 kernel/trace/trace_bootlevel.c

index e2538c7638d4..46fbf0ab81d9 100644
@@ -28,6 +28,7 @@ obj-$(CONFIG_RING_BUFFER) += ring_buffer.o
 obj-$(CONFIG_RING_BUFFER_BENCHMARK) += ring_buffer_benchmark.o
 
 obj-$(CONFIG_TRACING) += trace.o
+obj-$(CONFIG_TRACING) += trace_bootlevel.o
 obj-$(CONFIG_TRACING) += trace_output.o
 obj-$(CONFIG_TRACING) += trace_seq.o
 obj-$(CONFIG_TRACING) += trace_stat.o

2.11.0

Hmm, we had something like this when ftrace was first introduced:

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=d13744cd6e3fef373a3fe656ac349b4e7c49ff79

But was removed because it appeared to be useless...

https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=30dbb20e68e6f7df974b77d2350ebad5eb6f6c9e

What about instead just adding trace_events to the start and stop of init calls, and enable them with trace_event=boot during boot up.

Where the output would be:

       swapper/0-1     [000] ....     0.126563: initcall_level: level=pre_smp_initcalls
       swapper/0-1     [000] ....     0.126566: initcall_start: func=trace_init_flags_sys_exit+0x0/0x14
[..]
       swapper/0-1     [000] ....     0.178691: initcall_finish: func=initialize_ptr_random+0x0/0x3b ret=0
       swapper/0-1     [000] ....     0.307805: initcall_level: level=early
       swapper/0-1     [000] ....     0.307807: initcall_start: func=ipc_ns_init+0x0/0x5c
[..]
       swapper/0-1     [000] ....     0.307877: initcall_finish: func=net_ns_init+0x0/0x15e ret=0
       swapper/0-1     [000] ....     0.307908: initcall_level: level=core
       swapper/0-1     [000] ....     0.307909: initcall_start: func=e820__register_nvs_regions+0x0/0x3d
[..]
       swapper/0-1     [000] ....     0.358655: initcall_finish: func=__gnttab_init+0x0/0x30 ret=-19
       swapper/0-1     [000] ....     0.358686: initcall_level: level=postcore
       swapper/0-1     [000] ....     0.358686: initcall_start: func=irq_sysfs_init+0x0/0x9b
[..]
       swapper/0-1     [002] ....     0.382277: initcall_finish: func=kobject_uevent_init+0x0/0x12 ret=0
       swapper/0-1     [002] ....     0.382308: initcall_level: level=arch
       swapper/0-1     [002] ....     0.382309: initcall_start: func=bts_init+0x0/0xc2
[..]
       swapper/0-1     [002] ....     0.422657: initcall_finish: func=pci_arch_init+0x0/0x6b ret=0
       swapper/0-1     [002] ....     0.422688: initcall_level: level=subsys
       swapper/0-1     [002] ....     0.422688: initcall_start: func=init_vdso+0x0/0x3a
[..]
       swapper/0-1     [005] ....     0.995475: initcall_finish: func=watchdog_init+0x0/0x9f ret=0
       swapper/0-1     [005] ....     0.995509: initcall_level: level=fs
       swapper/0-1     [005] ....     0.995510: initcall_start: func=nmi_warning_debugfs+0x0/0x2c
[..]
       swapper/0-1     [001] ....     1.625378: initcall_finish: func=ir_dev_scope_init+0x0/0x38 ret=0
       swapper/0-1     [001] ....     1.625416: initcall_level: level=device
       swapper/0-1     [001] ....     1.625416: initcall_start: func=ia32_binfmt_init+0x0/0x19
[..]
       swapper/0-1     [003] ....     2.922618: initcall_finish: func=mcheck_init_device+0x0/0x13b ret=0
       swapper/0-1     [003] ....     2.922651: initcall_level: level=late
       swapper/0-1     [003] ....     2.922651: initcall_start: func=tboot_late_init+0x0/0x292
[..]
       swapper/0-1     [000] ....    13.501018: initcall_finish: func=pci_sysfs_init+0x0/0x5a ret=0

And you could even get what tests ran the longest. Like above, if you are wondering about that 13 second timestamp, it's because I had my ring buffer test enabled, which runs for some time:

       swapper/0-1     [003] ....     2.985688: initcall_start: func=test_ringbuffer+0x0/0x49c
       swapper/0-1     [000] ....    13.495516: initcall_finish: func=test_ringbuffer+0x0/0x49c ret=0

Would something like this work for you?

-- Steve

new file mode 100644
index 000000000000..0a1d53a848ae
@@ -0,0 +1,66 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM boot
+
+#if !defined(_TRACE_BOOT_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_BOOT_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>

index a8100b954839..498e08237569 100644
@@ -96,6 +96,9 @@
 #include <asm/sections.h>
 #include <asm/cacheflush.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/boot.h>
+
 static int kernel_init(void *);
 
 extern void init_IRQ(void);

@@ -826,10 +829,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;
 

@@ -894,6 +899,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);
 }

@@ -928,6 +934,7 @@ static void __init do_pre_smp_initcalls(void)
 {
 	initcall_t *fn;
 
+	trace_initcall_level("pre_smp_initcalls");
 	for (fn = __initcall_start; fn < __initcall0_start; fn++)
 		do_one_initcall(*fn);
 }

Steven Rostedt <[email protected]> a écrit :

Yes this is working great. I have also instrumented console and security initcalls, I used your previous patch, changes are below.

[    0.327032]   <idle>-0       0.... 89576us : initcall_level: level=console
[    0.327454]   <idle>-0       0.... 135819us : initcall_level: level=security
[    0.327887] swapper/-1       0.... 261166us : initcall_level: level=early
[    0.328306] swapper/-1       0.... 265248us : initcall_level: level=early
[    0.328742] swapper/-1       0.... 267969us : initcall_level: level=core
[    0.329158] swapper/-1       0.... 270111us : initcall_level: level=postcore
[    0.329590] swapper/-1       0.... 271111us : initcall_level: level=arch
[    0.330007] swapper/-1       0.... 272217us : initcall_level: level=subsys
[    0.330429] swapper/-1       0.... 316236us : initcall_level: level=fs
[    0.330833] swapper/-1       0.... 340523us : initcall_level: level=device
[    0.331254] swapper/-1       0.... 388737us : initcall_level: level=late

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

new file mode 100644
index 000000000000..ba0272a95813
@@ -0,0 +1,66 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM boot
+
+#if !defined(_TRACE_BOOT_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_BOOT_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>
\ No newline at end of file

index 969eaf140ef0..765189b3a92e 100644
@@ -97,6 +97,9 @@
 #include <asm/sections.h>
 #include <asm/cacheflush.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/boot.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(initcall_level_names[0]);
 	for (fn = __initcall_start; fn < __initcall0_start; fn++)
 		do_one_initcall(*fn);
 }

index f274fbef821d..0f10cfd1588e 100644
@@ -52,6 +52,7 @@
 #include <linux/uaccess.h>
 #include <asm/sections.h>
 
+#include <trace/events/boot.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++;
 	}
 }

index 1cd8526cb0b7..9de51d599bb4 100644
@@ -30,6 +30,8 @@
 #include <linux/string.h>
 #include <net/flow.h>
 
+#include <trace/events/boot.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++;
 	}
 }

Hmm, I think I found an issue with what's there. I made up that name because "early" was already taken.

Noticed you have two "early"s.

The second early should be "pure". But that's an issue with init.c.

I'll apply mine (with minor updates) and add diffs by you. Care to give me a "signed-off-by" for the console and security change.

-- Steve