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 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(-)
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(-)
On Wed, 08 Mar 2017 11:32:25 -0800
Todd Brandt <[email protected]> wrote:
> 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.
I can add this. I just wanted this out first.
The one part I want people to notice is the last patch where I add a
hook into the free mem reserve. I'll ping the mm folks to make sure
they are OK with that.
> > [ 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 was just about to ask ;-)
-- Steve
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(-)
>