Re: [RFC][PATCH 0/4] tracing: Allow function tracing to start earlier in boot up

[Todd Brandt]

On Wed, 2017-03-08 at 11:15 -0800, Todd Brandt wrote:
> On Tue, 2017-03-07 at 16:28 -0500, Steven Rostedt wrote:
> > I've had people ask about moving tracing up further in the boot process.
> > This patch series looks at function tracing only. It allows for tracing
> > (and function filtering) to be moved right after memory is initialized.
> > To have it happen before memory initialization would require a bit more
> > work with allocating the ring buffer. But this is a start.
> 
> I just tested out the patch and it does move function trace up to about
> 100ms from boot which is nice. What I'd really like is for graph trace
> to start sooner as well.
> 
> P.S. I've noticed that the dmesg log and ftrace log times don't seem to
> match up anymore since the v10.0 release. Is the default still the local
> clock? On v10.0-rc8 I was able to match initcall_debug output with
> do_one_initcall function_graph trace perfectly. But the latest is off by
> anywhere from several microseconds to several milliseconds. Did I just
> get lucky with v10.0-rc8 or should these still align?
> 
> v10.0-rc8 (ftrace time = dmesg time)
> 
> FTRACE:
> 0.519902 |    0)   systemd-1    |               |  do_one_initcall() {
> 0.519921 |    0)   systemd-1    |               |  do_one_initcall() {
> 0.519929 |    0)   systemd-1    |               |  do_one_initcall() {
> 0.519938 |    0)   systemd-1    |               |  do_one_initcall() {
> 0.519946 |    0)   systemd-1    |               |  do_one_initcall() {
> DMESG:
> [    0.519909] calling  init_per_zone_wmark_min+0x0/0x73 @ 1
> [    0.519925] calling  init_zero_pfn+0x0/0x3d @ 1
> [    0.519932] calling  memory_failure_init+0x0/0xa4 @ 1
> [    0.519941] calling  cma_init_reserved_areas+0x0/0x1cd @ 1
> [    0.519949] calling  fsnotify_init+0x0/0x26 @ 1
> 
> v4.11-rc1 (ftrace = dmesg + 5.089 ms)
> 
> FTRACE:
> 0.445317 |    2)   systemd-1    |               |  do_one_initcall() {
> 0.445338 |    2)   systemd-1    |               |  do_one_initcall() {
> 0.445346 |    2)   systemd-1    |               |  do_one_initcall() {
> 0.445355 |    2)   systemd-1    |               |  do_one_initcall() {
> 0.445363 |    2)   systemd-1    |               |  do_one_initcall() {
> DMESG:
> [    0.440232] calling  init_per_zone_wmark_min+0x0/0x73 @ 1
> [    0.440249] calling  init_zero_pfn+0x0/0x3d @ 1
> [    0.440257] calling  memory_failure_init+0x0/0xa4 @ 1
> [    0.440266] calling  cma_init_reserved_areas+0x0/0x1cd @ 1
> [    0.440275] calling  fsnotify_init+0x0/0x26 @ 1

Oops, no sooner than 5 minutes after I sent this did I figure out
there's a trace_clock kernel parameter (not in kernel-parameters.txt).
Once I set it to global all is well. Never mind :)

> 
> 
> > 
> > I placed a hook into free_reserved_area() which is used by all archs
> > to free the init memory. Having it pass the range being freed to ftrace
> > lets ftrace clean up any function that is registered such that it doesn't
> > try to modify code that no longer exists. 
> > 
> > 
> > Steven Rostedt (VMware) (4):
> >       tracing: Split tracing initialization into two for early initialization
> >       ftrace: Move ftrace_init() to right after memory initialization
> >       ftrace: Have function tracing start in early boot up
> >       ftrace: Allow for function tracing to record init functions on boot up
> > 
> > ----
> >  include/linux/ftrace.h         |  5 +++++
> >  include/linux/init.h           |  4 +++-
> >  init/main.c                    |  9 ++++++---
> >  kernel/trace/ftrace.c          | 44 ++++++++++++++++++++++++++++++++++++++++++
> >  kernel/trace/trace.c           |  9 ++++++++-
> >  kernel/trace/trace.h           |  2 ++
> >  kernel/trace/trace_functions.c |  3 +--
> >  mm/page_alloc.c                |  4 ++++
> >  scripts/recordmcount.c         |  1 +
> >  scripts/recordmcount.pl        |  1 +
> >  10 files changed, 75 insertions(+), 7 deletions(-)
>