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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-Id: <20180323150241.878778199@goodmis.org>
Date:   Fri, 23 Mar 2018 11:02:41 -0400
From:   Steven Rostedt <rostedt@...dmis.org>
To:     linux-kernel@...r.kernel.org
Cc:     Ingo Molnar <mingo@...nel.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Frederic Weisbecker <fweisbec@...il.com>,
        Thomas Gleixner <tglx@...utronix.de>,
        Abderrahmane Benbachir <abderrahmane.benbachir@...ymtl.ca>,
        AmÃ©rico Wang <xiyou.wangcong@...il.com>,
        Peter Zijlstra <peterz@...radead.org>
Subject: [PATCH 0/3] [RFC] init, tracing: Add initcall trace events

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