Re: [PATCH 0/4 v2] init, tracing: Add initcall trace events

[Steven Rostedt]

Peter, Andrew,

This keeps initcall_debug printing printk()s, but adds the feature of
those locations also being trace events. Are you OK if I add this?

Works with and without TRACEPOINTS enabled.

-- Steve


On Fri, 06 Apr 2018 15:08:54 -0400
Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:

> A while ago we had a boot tracer. But it was eventually removed:
>  commit 30dbb20e68e6f ("tracing: Remove boot tracer").
> 
> The rationale 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.
> Yes the timings are done within the printks, but it slows down the
> boot up tremendously. Tracing can do the same without needing to
> slow down boot up.
> 
> 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?
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
> ftrace/core
> 
> Head SHA1: 7af49b07cb525d36a916b841dc9329c187789e1f
> 
> 
> 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
> 
> ----
> Changes since v1:
> 
>   Added the last patch that makes initcall_debug work even when
>   TRACEPOINTS is not configured. It just goes back to the old
>   method (with if statements, instead of hooking into trace_events).
> 
>  include/trace/events/initcall.h | 66 ++++++++++++++++++++++++++++++++++
>  init/main.c                     | 78 ++++++++++++++++++++++++++++++++---------
>  kernel/printk/printk.c          |  7 +++-
>  security/security.c             |  8 ++++-
>  4 files changed, 141 insertions(+), 18 deletions(-)
>  create mode 100644 include/trace/events/initcall.h