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

[Todd Brandt]

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


> 
> 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(-)