aarch64 boot time increases with rt

aarch64 boot time increases with rt

[Itai Handler]

Hi,

I observed that aarch64 boot time increases considerably with rt
(PREEMPT_RT_FULL=y).
This is observable also in latest 4.19 rt (4.19.127-rt55).
Following is a fragment from kernel log (with rt) which shows that
bringing up 4 CPUs takes about 210 ms:

[    0.120951] smp: Bringing up secondary CPUs ...
[    0.184860] Detected VIPT I-cache on CPU1
[    0.187344] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[    0.262931] Detected VIPT I-cache on CPU2
[    0.263390] CPU2: Booted secondary processor 0x0000000002 [0x410fd034]
[    0.329296] Detected VIPT I-cache on CPU3
[    0.329872] CPU3: Booted secondary processor 0x0000000003 [0x410fd034]
[    0.331557] smp: Brought up 1 node, 4 CPUs

Note that these times are from qemu, however the problem is also
noticeable on real hardware.

I traced the code and found that the slow down is caused in
workqueue_prepare_cpu().
This function creates the worker threads.

On real hardware, it takes about 8 ms to create each worker thread.
Before digging into it in more detail, I would like to hear your opinion.

Steven, what ftrace command line parameters do you recommend to use in
this case?

Thank you,
Itai Handler

Re: aarch64 boot time increases with rt

[Steven Rostedt]

On Mon, 13 Jul 2020 17:56:05 +0300
Itai Handler <itai.handler@gmail.com> wrote:

> Hi,
> 
> I observed that aarch64 boot time increases considerably with rt
> (PREEMPT_RT_FULL=y).

You mean compared to non PREEMPT_RT_FULL of the same kernel?

> This is observable also in latest 4.19 rt (4.19.127-rt55).
> Following is a fragment from kernel log (with rt) which shows that
> bringing up 4 CPUs takes about 210 ms:

I'd suggest trying 5.4 or even 5.6-rt.

> 
> [    0.120951] smp: Bringing up secondary CPUs ...
> [    0.184860] Detected VIPT I-cache on CPU1
> [    0.187344] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
> [    0.262931] Detected VIPT I-cache on CPU2
> [    0.263390] CPU2: Booted secondary processor 0x0000000002 [0x410fd034]
> [    0.329296] Detected VIPT I-cache on CPU3
> [    0.329872] CPU3: Booted secondary processor 0x0000000003 [0x410fd034]
> [    0.331557] smp: Brought up 1 node, 4 CPUs
> 
> Note that these times are from qemu, however the problem is also
> noticeable on real hardware.
> 
> I traced the code and found that the slow down is caused in
> workqueue_prepare_cpu().
> This function creates the worker threads.
> 
> On real hardware, it takes about 8 ms to create each worker thread.
> Before digging into it in more detail, I would like to hear your opinion.
> 
> Steven, what ftrace command line parameters do you recommend to use in
> this case?

Well, you could try: ftrace=function_graph ftrace_graph_filter workqueue_prepare_cpu

If workqueue_prepare_cpu is a traceable function (not inlined nor notrace set).

-- Steve

Re: aarch64 boot time increases with rt

[Itai Handler]

Hi Steven,

On Tue, Jul 14, 2020 at 4:20 AM Steven Rostedt <rostedt@goodmis.org> wrote:

> You mean compared to non PREEMPT_RT_FULL of the same kernel?

Yes.

> I'd suggest trying 5.4 or even 5.6-rt.

I tried 5.4.47-rt28, and the problem still persists.

> Well, you could try: ftrace=function_graph ftrace_graph_filter workqueue_prepare_cpu
>
> If workqueue_prepare_cpu is a traceable function (not inlined nor notrace set).

I tried "ftrace=function_graph ftrace_graph_filter=workqueue_prepare_cpu",
however, the trace appears to be empty.
The function workqueue_prepare_cpu is not defined inline nor notrace.

Please see log below:
# mount -t debugfs none /sys/kernel/debug
# cd /sys/kernel/debug/tracing/
# cat trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
# cat set_graph_function
workqueue_prepare_cpu
# cat tracing_on
1

Do you have any idea why it's empty?

Thank you,
Itai Handler

Re: aarch64 boot time increases with rt

[Steven Rostedt]

On Tue, 14 Jul 2020 15:18:01 +0300
Itai Handler <itai.handler@gmail.com> wrote:

> I tried "ftrace=function_graph ftrace_graph_filter=workqueue_prepare_cpu",
> however, the trace appears to be empty.
> The function workqueue_prepare_cpu is not defined inline nor notrace.
> 
> Please see log below:
> # mount -t debugfs none /sys/kernel/debug
> # cd /sys/kernel/debug/tracing/
> # cat trace
> # tracer: function_graph
> #
> # CPU  DURATION                  FUNCTION CALLS
> # |     |   |                     |   |   |   |
> # cat set_graph_function
> workqueue_prepare_cpu
> # cat tracing_on
> 1
> 
> Do you have any idea why it's empty?

Hmm, does the place in question happen before ftrace is initialized?

That is, where do you see the message that has something like this:

 ftrace: allocating 41803 entries in 164 pages
 ftrace: allocated 164 pages with 3 groups

-- Steve

Re: aarch64 boot time increases with rt

[Steven Rostedt]

On Tue, 14 Jul 2020 15:18:01 +0300
Itai Handler <itai.handler@gmail.com> wrote:

> Hi Steven,
> 
> On Tue, Jul 14, 2020 at 4:20 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > You mean compared to non PREEMPT_RT_FULL of the same kernel?  
> 
> Yes.
> 
> > I'd suggest trying 5.4 or even 5.6-rt.  
> 
> I tried 5.4.47-rt28, and the problem still persists.
> 
> > Well, you could try: ftrace=function_graph ftrace_graph_filter workqueue_prepare_cpu
> >
> > If workqueue_prepare_cpu is a traceable function (not inlined nor notrace set).  
> 
> I tried "ftrace=function_graph ftrace_graph_filter=workqueue_prepare_cpu",
> however, the trace appears to be empty.
> The function workqueue_prepare_cpu is not defined inline nor notrace.
> 
> Please see log below:
> # mount -t debugfs none /sys/kernel/debug
> # cd /sys/kernel/debug/tracing/
> # cat trace
> # tracer: function_graph
> #
> # CPU  DURATION                  FUNCTION CALLS
> # |     |   |                     |   |   |   |
> # cat set_graph_function
> workqueue_prepare_cpu
> # cat tracing_on
> 1
> 
> Do you have any idea why it's empty?

To rule out that this may be an issue with the function_graph tracer,
can you also try it with:

 ftrace=function ftrace_filter=worqueue_prepare_cpu

And see if the function tracer shows anything.

/me just looked at the code.

Yes, the function tracer is set up to trace really early, but the
function_graph tracer is initialized by core_initcall(), which is much
later.

Perhaps try this patch (note, it's from latest mainline):

And retry the function_graph tracer.

-- Steve


diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 4aab712f9567..35bcac3edcee 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -9475,6 +9475,7 @@ __init static int tracer_alloc_buffers(void)
 
 	/* Function tracing may start here (via kernel command line) */
 	init_function_trace();
+	init_graph_trace();
 
 	/* All seems OK, enable tracing */
 	tracing_disabled = 0;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index f21607f87189..d861bd34dfb6 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1129,6 +1129,11 @@ void ftrace_init_tracefs_toplevel(struct trace_array *tr,
 void ftrace_clear_pids(struct trace_array *tr);
 int init_function_trace(void);
 void ftrace_pid_follow_fork(struct trace_array *tr, bool enable);
+# ifdef CONFIG_FUNCTION_GRAPH_TRACER
+int init_graph_trace(void);
+# else
+static inline int init_graph_trace(void) { return 0; }
+# endif
 #else
 static inline int ftrace_trace_task(struct trace_array *tr)
 {
@@ -1149,6 +1154,7 @@ static inline void ftrace_init_tracefs(struct trace_array *tr, struct dentry *d)
 static inline void ftrace_init_tracefs_toplevel(struct trace_array *tr, struct dentry *d) { }
 static inline void ftrace_clear_pids(struct trace_array *tr) { }
 static inline int init_function_trace(void) { return 0; }
+static inline int init_graph_trace(void) { return 0; }
 static inline void ftrace_pid_follow_fork(struct trace_array *tr, bool enable) { }
 /* ftace_func_t type is not defined, use macro instead of static inline */
 #define ftrace_init_array_ops(tr, func) do { } while (0)
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 4a9c49c08ec9..e18cc90585fb 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -1349,7 +1349,7 @@ static __init int init_graph_tracefs(void)
 }
 fs_initcall(init_graph_tracefs);
 
-static __init int init_graph_trace(void)
+__init int init_graph_trace(void)
 {
 	max_bytes_for_cpu = snprintf(NULL, 0, "%u", nr_cpu_ids - 1);
 
@@ -1365,5 +1365,3 @@ static __init int init_graph_trace(void)
 
 	return register_tracer(&graph_trace);
 }
-
-core_initcall(init_graph_trace);

Re: aarch64 boot time increases with rt

[Itai Handler]

Hi Steven,

On Wed, Jul 15, 2020 at 10:36 PM Steven Rostedt <rostedt@goodmis.org> wrote:

> To rule out that this may be an issue with the function_graph tracer,
> can you also try it with:
>
>  ftrace=function ftrace_filter=worqueue_prepare_cpu
>
> And see if the function tracer shows anything.
>
> /me just looked at the code.
>
> Yes, the function tracer is set up to trace really early, but the
> function_graph tracer is initialized by core_initcall(), which is much
> later.
>
> Perhaps try this patch (note, it's from latest mainline):
>
> And retry the function_graph tracer.

With this patch, the function graph tracer doesn't work at boot time.
Please see the log below:

# mount -t debugfs debugfs /sys/kernel/debug/
# cd /sys/kernel/debug/tracing/trace
# cat current_tracer
nop

Note that I tested it both on 5.4.47-rt28 and 5.6.19-rt11 (but not on
latest mainline).

Regarding the function tracer, you were correct: it can trace
workqueue_prepare_cpu
without any issue.

Thank you,
Itai Handler