tracing: Addition of initcall tracing
Subsystems (3)
Steven Rostedt
maintainercover tracing: Addition of initcall tracing
The last patch keeps initcall_debug working even without CONFIG_TRACEPOINTS enabled. Nobody appears to be against this patch set.
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
for-next
Head SHA1: b0dc52f15e7fe2b973ecfe4f3706f1b35ce3943a
Abderrahmane Benbachir (1):
init, tracing: instrument security and console initcall trace events
Steven Rostedt (VMware) (3):
init, tracing: Add initcall trace events
init, tracing: Have printk come through the trace events for initcall_debug
init: Have initcall_debug still work without CONFIG_TRACEPOINTS
----
include/trace/events/initcall.h | 66 +++++++++++++++++++++++++++++++++ init/main.c | 82 +++++++++++++++++++++++++++++++++-------- kernel/printk/printk.c | 7 +++- security/security.c | 8 +++- 4 files changed, 145 insertions(+), 18 deletions(-) create mode 100644 include/trace/events/initcall.h
Steven Rostedt
maintainerPATCH 1/4 init, tracing: Add initcall trace events
From: "Steven Rostedt (VMware)" <[email protected]>
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.
--- include/trace/events/initcall.h | 66 +++++++++++++++++++++++++++++++++++++++++ init/main.c | 7 +++++ 2 files changed, 73 insertions(+) create mode 100644 include/trace/events/initcall.h
include/trace/events/initcall.h new file +66 -0
@@ -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>
init/main.c +7 -0
@@ -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); }
Signature · 1 line
2.16.3
Steven Rostedt
maintainerPATCH 2/4 init, tracing: instrument security and console initcall trace events
In reply to Steven RostedtFrom: Abderrahmane Benbachir <[email protected]>
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.
--- kernel/printk/printk.c | 7 ++++++- security/security.c | 8 +++++++- 2 files changed, 13 insertions(+), 2 deletions(-)
kernel/printk/printk.c +6 -1
@@ -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++; } }
security/security.c +7 -1
@@ -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++; } }
Signature · 1 line
2.16.3
Steven Rostedt
maintainerPATCH 3/4 init, tracing: Have printk come through the trace events for initcall_debug
In reply to Steven RostedtFrom: "Steven Rostedt (VMware)" <[email protected]>
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.
--- init/main.c | 51 +++++++++++++++++++++++++++++++++++---------------- 1 file changed, 35 insertions(+), 16 deletions(-)
init/main.c +35 -16
@@ -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 ;
Signature · 1 line
2.16.3
Steven Rostedt
maintainerPATCH 4/4 init: Have initcall_debug still work without CONFIG_TRACEPOINTS
In reply to Steven RostedtFrom: "Steven Rostedt (VMware)" <[email protected]>
Add macros around the initcall_debug tracepoint code to have the code to default back to the old method if CONFIG_TRACEPOINTS is not enabled.
--- init/main.c | 28 ++++++++++++++++++++++++++-- 1 file changed, 26 insertions(+), 2 deletions(-)
init/main.c +26 -2
@@ -496,7 +496,14 @@ void __init __weak mem_encrypt_init(void) { }bool initcall_debug;core_param (initcall_debug, initcall_debug, bool,0644 ); + +#ifdef TRACEPOINTS_ENABLED static void __init initcall_debug_enable (void ); +#else +static inline void initcall_debug_enable (void ) +{ +} +#endif /* * Set up kernel memory allocators
@@ -832,6 +839,7 @@ trace_initcall_finish_cb(void *data, initcall_t fn, int ret)static ktime_t initcall_calltime; +#ifdef TRACEPOINTS_ENABLED static void __init initcall_debug_enable (void ) {int ret;
@@ -842,6 +850,22 @@ static void __init initcall_debug_enable(void) &initcall_calltime);WARN (ret,"Failed to register initcall tracepoints\n" ); } +# define do_trace_initcall_start trace_initcall_start +# define do_trace_initcall_finish trace_initcall_finish +#else +static inline void do_trace_initcall_start (initcall_t fn) +{ +if (!initcall_debug) +return ; +trace_initcall_start_cb (&initcall_calltime, fn); +} +static inline void do_trace_initcall_finish (initcall_t fn,int ret) +{ +if (!initcall_debug) +return ; +trace_initcall_finish_cb (&initcall_calltime, fn, ret); +} +#endif /* !TRACEPOINTS_ENABLED */ int __init_or_module do_one_initcall(initcall_t fn) {
@@ -852,9 +876,9 @@ int __init_or_module do_one_initcall(initcall_t fn)if (initcall_blacklisted (fn))return -EPERM ; -trace_initcall_start (fn); +do_trace_initcall_start (fn); ret =fn (); -trace_initcall_finish (fn, ret); +do_trace_initcall_finish (fn, ret); msgbuf[0 ] =0 ;
Signature · 1 line
2.16.3