* [PATCH 1/3] init: Fix initcall0 name as it is "pure" not "early"
2018-03-23 15:02 [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Steven Rostedt
@ 2018-03-23 15:02 ` Steven Rostedt
2018-03-23 15:02 ` [PATCH 2/3] init, tracing: Add initcall trace events Steven Rostedt
` (4 subsequent siblings)
5 siblings, 0 replies; 11+ messages in thread
From: Steven Rostedt @ 2018-03-23 15:02 UTC (permalink / raw)
To: linux-kernel
Cc: Ingo Molnar, Andrew Morton, Frederic Weisbecker, Thomas Gleixner,
Abderrahmane Benbachir, Américo Wang, Peter Zijlstra
[-- 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
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 2/3] init, tracing: Add initcall trace events
2018-03-23 15:02 [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Steven Rostedt
2018-03-23 15:02 ` [PATCH 1/3] init: Fix initcall0 name as it is "pure" not "early" Steven Rostedt
@ 2018-03-23 15:02 ` Steven Rostedt
2018-03-23 15:02 ` [PATCH 3/3] init, tracing: instrument security and console " Steven Rostedt
` (3 subsequent siblings)
5 siblings, 0 replies; 11+ messages in thread
From: Steven Rostedt @ 2018-03-23 15:02 UTC (permalink / raw)
To: linux-kernel
Cc: Ingo Molnar, Andrew Morton, Frederic Weisbecker, Thomas Gleixner,
Abderrahmane Benbachir, Américo Wang, Peter Zijlstra
[-- 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
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 3/3] init, tracing: instrument security and console initcall trace events
2018-03-23 15:02 [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Steven Rostedt
2018-03-23 15:02 ` [PATCH 1/3] init: Fix initcall0 name as it is "pure" not "early" Steven Rostedt
2018-03-23 15:02 ` [PATCH 2/3] init, tracing: Add initcall trace events Steven Rostedt
@ 2018-03-23 15:02 ` Steven Rostedt
2018-03-23 19:50 ` [PATCH 0/3] [RFC] init, tracing: Add " Andrew Morton
` (2 subsequent siblings)
5 siblings, 0 replies; 11+ messages in thread
From: Steven Rostedt @ 2018-03-23 15:02 UTC (permalink / raw)
To: linux-kernel
Cc: Ingo Molnar, Andrew Morton, Frederic Weisbecker, Thomas Gleixner,
Abderrahmane Benbachir, Américo Wang, Peter Zijlstra,
Ingo Molnar
[-- 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
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events
2018-03-23 15:02 [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Steven Rostedt
` (2 preceding siblings ...)
2018-03-23 15:02 ` [PATCH 3/3] init, tracing: instrument security and console " Steven Rostedt
@ 2018-03-23 19:50 ` Andrew Morton
2018-03-23 20:04 ` Steven Rostedt
2018-03-26 17:47 ` [PATCH 4/3] init, tracing: Have printk come through the trace events for initcall_debug Steven Rostedt
2018-03-27 1:50 ` [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Joel Fernandes (Google)
5 siblings, 1 reply; 11+ messages in thread
From: Andrew Morton @ 2018-03-23 19:50 UTC (permalink / raw)
To: Steven Rostedt
Cc: linux-kernel, Ingo Molnar, Frederic Weisbecker, Thomas Gleixner,
Abderrahmane Benbachir, Américo Wang, Peter Zijlstra
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?
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events
2018-03-23 19:50 ` [PATCH 0/3] [RFC] init, tracing: Add " Andrew Morton
@ 2018-03-23 20:04 ` Steven Rostedt
2018-03-26 8:42 ` Peter Zijlstra
0 siblings, 1 reply; 11+ messages in thread
From: Steven Rostedt @ 2018-03-23 20:04 UTC (permalink / raw)
To: Andrew Morton
Cc: linux-kernel, Ingo Molnar, Frederic Weisbecker, Thomas Gleixner,
Abderrahmane Benbachir, Américo Wang, Peter Zijlstra
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events
2018-03-23 20:04 ` Steven Rostedt
@ 2018-03-26 8:42 ` Peter Zijlstra
2018-03-26 14:34 ` Steven Rostedt
0 siblings, 1 reply; 11+ messages in thread
From: Peter Zijlstra @ 2018-03-26 8:42 UTC (permalink / raw)
To: Steven Rostedt
Cc: Andrew Morton, linux-kernel, Ingo Molnar, Frederic Weisbecker,
Thomas Gleixner, Abderrahmane Benbachir, Américo Wang
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.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events
2018-03-26 8:42 ` Peter Zijlstra
@ 2018-03-26 14:34 ` Steven Rostedt
0 siblings, 0 replies; 11+ messages in thread
From: Steven Rostedt @ 2018-03-26 14:34 UTC (permalink / raw)
To: Peter Zijlstra
Cc: Andrew Morton, linux-kernel, Ingo Molnar, Frederic Weisbecker,
Thomas Gleixner, Abderrahmane Benbachir, Américo Wang
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;
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 4/3] init, tracing: Have printk come through the trace events for initcall_debug
2018-03-23 15:02 [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Steven Rostedt
` (3 preceding siblings ...)
2018-03-23 19:50 ` [PATCH 0/3] [RFC] init, tracing: Add " Andrew Morton
@ 2018-03-26 17:47 ` Steven Rostedt
2018-03-27 1:50 ` [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Joel Fernandes (Google)
5 siblings, 0 replies; 11+ messages in thread
From: Steven Rostedt @ 2018-03-26 17:47 UTC (permalink / raw)
To: linux-kernel
Cc: Ingo Molnar, Andrew Morton, Frederic Weisbecker, Thomas Gleixner,
Abderrahmane Benbachir, Américo Wang, Peter Zijlstra
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
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events
2018-03-23 15:02 [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Steven Rostedt
` (4 preceding siblings ...)
2018-03-26 17:47 ` [PATCH 4/3] init, tracing: Have printk come through the trace events for initcall_debug Steven Rostedt
@ 2018-03-27 1:50 ` Joel Fernandes (Google)
2018-03-27 3:02 ` Steven Rostedt
5 siblings, 1 reply; 11+ messages in thread
From: Joel Fernandes (Google) @ 2018-03-27 1:50 UTC (permalink / raw)
To: Steven Rostedt
Cc: Linux Kernel Mailing List, Ingo Molnar, Andrew Morton,
Frederic Weisbecker, Thomas Gleixner, Abderrahmane Benbachir,
Américo Wang, Peter Zijlstra
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
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events
2018-03-27 1:50 ` [PATCH 0/3] [RFC] init, tracing: Add initcall trace events Joel Fernandes (Google)
@ 2018-03-27 3:02 ` Steven Rostedt
0 siblings, 0 replies; 11+ messages in thread
From: Steven Rostedt @ 2018-03-27 3:02 UTC (permalink / raw)
To: Joel Fernandes (Google)
Cc: Linux Kernel Mailing List, Ingo Molnar, Andrew Morton,
Frederic Weisbecker, Thomas Gleixner, Abderrahmane Benbachir,
Américo Wang, Peter Zijlstra
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
^ permalink raw reply [flat|nested] 11+ messages in thread