[PATCH v3 0/2] tracing: make tracer_init_tracefs initcall asynchronous

[PATCH v3 0/2] tracing: make tracer_init_tracefs initcall asynchronous

[Mark-PK Tsai]

Move trace_eval_init() to subsys_initcall to make it start
earlier.
And to avoid tracer_init_tracefs being blocked by
trace_event_sem which trace_eval_init() hold [1],
queue tracer_init_tracefs() to eval_map_wq to let
the two works being executed sequentially.

It can speed up the initialization of kernel as result
of making tracer_init_tracefs asynchronous.

On my arm64 platform, it reduce ~20ms of 125ms which total
time do_initcalls spend.

Mark-PK Tsai (2):
  tracing: Avoid adding tracer option before update_tracer_options
  tracing: make tracer_init_tracefs initcall asynchronous

 kernel/trace/trace.c | 38 ++++++++++++++++++++++++++++----------
 1 file changed, 28 insertions(+), 10 deletions(-)

-- 
2.18.0

[PATCH v3 1/2] tracing: Avoid adding tracer option before update_tracer_options

[Mark-PK Tsai]

To prepare for support asynchronous tracer_init_tracefs initcall,
avoid calling create_trace_option_files before __update_tracer_options.
Otherwise, create_trace_option_files will show warning because
some tracers in trace_types list are already in tr->topts.

For example, hwlat_tracer call register_tracer in late_initcall,
and global_trace.dir is already created in tracing_init_dentry,
hwlat_tracer will be put into tr->topts.
Then if the __update_tracer_options is executed after hwlat_tracer
registered, create_trace_option_files find that hwlat_tracer is
already in tr->topts.

Link: https://lore.kernel.org/lkml/20220322133339.GA32582@xsang-OptiPlex-9020/
Reported-by: kernel test robot <oliver.sang@intel.com>
Signed-off-by: Mark-PK Tsai <mark-pk.tsai@mediatek.com>
---
 kernel/trace/trace.c | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index eb44418574f9..85ec758c4455 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -6317,12 +6317,18 @@ static void tracing_set_nop(struct trace_array *tr)
 	tr->current_trace = &nop_trace;
 }
 
+static bool tracer_options_updated;
+
 static void add_tracer_options(struct trace_array *tr, struct tracer *t)
 {
 	/* Only enable if the directory has been created already. */
 	if (!tr->dir)
 		return;
 
+	/* Only create trace option files after update_tracer_options finish */
+	if (!tracer_options_updated)
+		return;
+
 	create_trace_option_files(tr, t);
 }
 
@@ -9133,6 +9139,7 @@ static void update_tracer_options(struct trace_array *tr)
 {
 	mutex_lock(&trace_types_lock);
 	__update_tracer_options(tr);
+	tracer_options_updated = true;
 	mutex_unlock(&trace_types_lock);
 }
 
-- 
2.18.0

[PATCH v3 2/2] tracing: make tracer_init_tracefs initcall asynchronous

[Mark-PK Tsai]

Move trace_eval_init() to subsys_initcall to make it start
earlier.
And to avoid tracer_init_tracefs being blocked by
trace_event_sem which trace_eval_init() hold [1],
queue tracer_init_tracefs() to eval_map_wq to let
the two works being executed sequentially.

It can speed up the initialization of kernel as result
of making tracer_init_tracefs asynchronous.

On my arm64 platform, it reduce ~20ms of 125ms which total
time do_initcalls spend.

[1]: https://lore.kernel.org/r/68d7b3327052757d0cd6359a6c9015a85b437232.camel@pengutronix.de
Signed-off-by: Mark-PK Tsai <mark-pk.tsai@mediatek.com>
---
 kernel/trace/trace.c | 31 +++++++++++++++++++++----------
 1 file changed, 21 insertions(+), 10 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 85ec758c4455..2974ae056068 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -9571,6 +9571,7 @@ extern struct trace_eval_map *__stop_ftrace_eval_maps[];
 
 static struct workqueue_struct *eval_map_wq __initdata;
 static struct work_struct eval_map_work __initdata;
+static struct work_struct tracerfs_init_work __initdata;
 
 static void __init eval_map_work_func(struct work_struct *work)
 {
@@ -9596,6 +9597,8 @@ static int __init trace_eval_init(void)
 	return 0;
 }
 
+subsys_initcall(trace_eval_init);
+
 static int __init trace_eval_sync(void)
 {
 	/* Make sure the eval map updates are finished */
@@ -9678,15 +9681,8 @@ static struct notifier_block trace_module_nb = {
 };
 #endif /* CONFIG_MODULES */
 
-static __init int tracer_init_tracefs(void)
+static __init void tracer_init_tracefs_work_func(struct work_struct *work)
 {
-	int ret;
-
-	trace_access_lock_init();
-
-	ret = tracing_init_dentry();
-	if (ret)
-		return 0;
 
 	event_trace_init();
 
@@ -9708,8 +9704,6 @@ static __init int tracer_init_tracefs(void)
 	trace_create_file("saved_tgids", TRACE_MODE_READ, NULL,
 			NULL, &tracing_saved_tgids_fops);
 
-	trace_eval_init();
-
 	trace_create_eval_file(NULL);
 
 #ifdef CONFIG_MODULES
@@ -9724,6 +9718,23 @@ static __init int tracer_init_tracefs(void)
 	create_trace_instances(NULL);
 
 	update_tracer_options(&global_trace);
+}
+
+static __init int tracer_init_tracefs(void)
+{
+	int ret;
+
+	trace_access_lock_init();
+
+	ret = tracing_init_dentry();
+	if (ret)
+		return 0;
+
+	INIT_WORK(&tracerfs_init_work, tracer_init_tracefs_work_func);
+	if (!eval_map_wq)
+		tracer_init_tracefs_work_func(&tracerfs_init_work);
+	else
+		queue_work(eval_map_wq, &tracerfs_init_work);
 
 	return 0;
 }
-- 
2.18.0

[PATCH v3 0/2] tracing: make tracer_init_tracefs initcall asynchronous

[Mark-PK Tsai]

Hi Steve,

Could you please help to review this patch?
Sorry to disturb you, I just want to make sure it has not been
forgotten.

> Move trace_eval_init() to subsys_initcall to make it start
> earlier.
> And to avoid tracer_init_tracefs being blocked by
> trace_event_sem which trace_eval_init() hold [1],
> queue tracer_init_tracefs() to eval_map_wq to let
> the two works being executed sequentially.
> 
> It can speed up the initialization of kernel as result
> of making tracer_init_tracefs asynchronous.
> 
> On my arm64 platform, it reduce ~20ms of 125ms which total
> time do_initcalls spend.
> 
> Mark-PK Tsai (2):
>   tracing: Avoid adding tracer option before update_tracer_options
>   tracing: make tracer_init_tracefs initcall asynchronous
> 
>  kernel/trace/trace.c | 38 ++++++++++++++++++++++++++++----------
>  1 file changed, 28 insertions(+), 10 deletions(-)
> 
> -- 
> 2.18.0

Re: [PATCH v3 0/2] tracing: make tracer_init_tracefs initcall asynchronous

[Steven Rostedt]

On Fri, 22 Apr 2022 17:27:51 +0800
Mark-PK Tsai <mark-pk.tsai@mediatek.com> wrote:

> Could you please help to review this patch?
> Sorry to disturb you, I just want to make sure it has not been
> forgotten.

No problem. Sorry for not getting to it, but my queue is rather deep :-p

Hopefully I can get to it by next week. Feel free to remind me again in a
week in case you do not hear back from me. But it is in my local patchwork,
but so is a lot of other patches I need to review :-/

-- Steve

Re: [PATCH v3 1/2] tracing: Avoid adding tracer option before update_tracer_options

[Steven Rostedt]

On Wed, 23 Mar 2022 23:22:56 +0800
Mark-PK Tsai <mark-pk.tsai@mediatek.com> wrote:

> To prepare for support asynchronous tracer_init_tracefs initcall,
> avoid calling create_trace_option_files before __update_tracer_options.
> Otherwise, create_trace_option_files will show warning because
> some tracers in trace_types list are already in tr->topts.
> 
> For example, hwlat_tracer call register_tracer in late_initcall,
> and global_trace.dir is already created in tracing_init_dentry,
> hwlat_tracer will be put into tr->topts.
> Then if the __update_tracer_options is executed after hwlat_tracer
> registered, create_trace_option_files find that hwlat_tracer is
> already in tr->topts.
> 
> Link: https://lore.kernel.org/lkml/20220322133339.GA32582@xsang-OptiPlex-9020/
> Reported-by: kernel test robot <oliver.sang@intel.com>
> Signed-off-by: Mark-PK Tsai <mark-pk.tsai@mediatek.com>

Before this patch:

 # ls /sys/kernel/tracing/options
annotate	   funcgraph-duration  hex		stacktrace
bin		   funcgraph-irqs      irq-info		sym-addr
blk_cgname	   funcgraph-overhead  latency-format	sym-offset
blk_cgroup	   funcgraph-overrun   markers		sym-userobj
blk_classic	   funcgraph-proc      overwrite	test_nop_accept
block		   funcgraph-tail      pause-on-trace	test_nop_refuse
context-info	   func-no-repeats     printk-msg-only	trace_printk
disable_on_free    func_stack_trace    print-parent	userstacktrace
display-graph	   function-fork       raw		verbose
event-fork	   function-trace      record-cmd
funcgraph-abstime  graph-time	       record-tgid
funcgraph-cpu	   hash-ptr	       sleep-time


After this patch:

 # ls /sys/kernel/tracing/options
annotate      disable_on_free  irq-info         raw          trace_printk
bin           display-graph    latency-format   record-cmd   userstacktrace
blk_cgname    event-fork       markers          record-tgid  verbose
blk_cgroup    function-fork    overwrite        stacktrace
blk_classic   function-trace   pause-on-trace   sym-addr
block         hash-ptr         printk-msg-only  sym-offset
context-info  hex              print-parent     sym-userobj

Not good.

> ---
>  kernel/trace/trace.c | 7 +++++++
>  1 file changed, 7 insertions(+)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index eb44418574f9..85ec758c4455 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -6317,12 +6317,18 @@ static void tracing_set_nop(struct trace_array *tr)
>  	tr->current_trace = &nop_trace;
>  }
>  
> +static bool tracer_options_updated;
> +
>  static void add_tracer_options(struct trace_array *tr, struct tracer *t)
>  {
>  	/* Only enable if the directory has been created already. */
>  	if (!tr->dir)
>  		return;
>  
> +	/* Only create trace option files after update_tracer_options finish */
> +	if (!tracer_options_updated)
> +		return;
> +
>  	create_trace_option_files(tr, t);
>  }
>  
> @@ -9133,6 +9139,7 @@ static void update_tracer_options(struct trace_array *tr)
>  {
>  	mutex_lock(&trace_types_lock);
>  	__update_tracer_options(tr);
> +	tracer_options_updated = true;

I think you want to set this before the __update, as doing it after just
makes the update a nop.

-- Steve


>  	mutex_unlock(&trace_types_lock);
>  }
>  

Re: [PATCH v3 2/2] tracing: make tracer_init_tracefs initcall asynchronous

[Steven Rostedt]

On Wed, 23 Mar 2022 23:22:57 +0800
Mark-PK Tsai <mark-pk.tsai@mediatek.com> wrote:

> +static __init int tracer_init_tracefs(void)
> +{
> +	int ret;
> +
> +	trace_access_lock_init();
> +
> +	ret = tracing_init_dentry();
> +	if (ret)
> +		return 0;
> +
> +	INIT_WORK(&tracerfs_init_work, tracer_init_tracefs_work_func);
> +	if (!eval_map_wq)
> +		tracer_init_tracefs_work_func(&tracerfs_init_work);

Why go through the bother of doing the INIT_WORK if eval_map_wq is not
created? Just do:

	if (eval_map_wq) {
		INIT_WORK(&tracerfs_init_work, tracer_init_tracefs_work_func);
		queue_work(eval_map_wq, &tracerfs_init_work);
	} else {
		tracer_init_tracefs_work_func(NULL);
	}

But that's just a nit anyway.

-- Steve



> +	else
> +		queue_work(eval_map_wq, &tracerfs_init_work);
>  
>  	return 0;
>  }

Re: [PATCH v3 2/2] tracing: make tracer_init_tracefs initcall asynchronous

[Mark-PK Tsai]

> > +static __init int tracer_init_tracefs(void)
> > +{
> > +	int ret;
> > +
> > +	trace_access_lock_init();
> > +
> > +	ret = tracing_init_dentry();
> > +	if (ret)
> > +		return 0;
> > +
> > +	INIT_WORK(&tracerfs_init_work, tracer_init_tracefs_work_func);
> > +	if (!eval_map_wq)
> > +		tracer_init_tracefs_work_func(&tracerfs_init_work);
> 
> Why go through the bother of doing the INIT_WORK if eval_map_wq is not
> created? Just do:
> 
> 	if (eval_map_wq) {
> 		INIT_WORK(&tracerfs_init_work, tracer_init_tracefs_work_func);
> 		queue_work(eval_map_wq, &tracerfs_init_work);
> 	} else {
> 		tracer_init_tracefs_work_func(NULL);
> 	}

Got it, I will update it in v4.
Thanks!

> 
> But that's just a nit anyway.
> 
> -- Steve
> 
> 
> 
> > +	else
> > +		queue_work(eval_map_wq, &tracerfs_init_work);
> >  
> >  	return 0;
> >  }

Re: [PATCH v3 1/2] tracing: Avoid adding tracer option before update_tracer_options

[Mark-PK Tsai]

> > To prepare for support asynchronous tracer_init_tracefs initcall,
> > avoid calling create_trace_option_files before __update_tracer_options.
> > Otherwise, create_trace_option_files will show warning because
> > some tracers in trace_types list are already in tr->topts.
> > 
> > For example, hwlat_tracer call register_tracer in late_initcall,
> > and global_trace.dir is already created in tracing_init_dentry,
> > hwlat_tracer will be put into tr->topts.
> > Then if the __update_tracer_options is executed after hwlat_tracer
> > registered, create_trace_option_files find that hwlat_tracer is
> > already in tr->topts.
> > 
> > Link: https://lore.kernel.org/lkml/20220322133339.GA32582@xsang-OptiPlex-9020/
> > Reported-by: kernel test robot <oliver.sang@intel.com>
> > Signed-off-by: Mark-PK Tsai <mark-pk.tsai@mediatek.com>
> 
> Before this patch:
> 
>  # ls /sys/kernel/tracing/options
> annotate	   funcgraph-duration  hex		stacktrace
> bin		   funcgraph-irqs      irq-info		sym-addr
> blk_cgname	   funcgraph-overhead  latency-format	sym-offset
> blk_cgroup	   funcgraph-overrun   markers		sym-userobj
> blk_classic	   funcgraph-proc      overwrite	test_nop_accept
> block		   funcgraph-tail      pause-on-trace	test_nop_refuse
> context-info	   func-no-repeats     printk-msg-only	trace_printk
> disable_on_free    func_stack_trace    print-parent	userstacktrace
> display-graph	   function-fork       raw		verbose
> event-fork	   function-trace      record-cmd
> funcgraph-abstime  graph-time	       record-tgid
> funcgraph-cpu	   hash-ptr	       sleep-time
> 
> 
> After this patch:
> 
>  # ls /sys/kernel/tracing/options
> annotate      disable_on_free  irq-info         raw          trace_printk
> bin           display-graph    latency-format   record-cmd   userstacktrace
> blk_cgname    event-fork       markers          record-tgid  verbose
> blk_cgroup    function-fork    overwrite        stacktrace
> blk_classic   function-trace   pause-on-trace   sym-addr
> block         hash-ptr         printk-msg-only  sym-offset
> context-info  hex              print-parent     sym-userobj
> 
> Not good.

Calling __update_tracer_options() when tracer_options_updated=false have no
effect because it return directly in add_tracer_options().
I will fix it in v4 as you suggest in the below comment.

> 
> > ---
> >  kernel/trace/trace.c | 7 +++++++
> >  1 file changed, 7 insertions(+)
> > 
> > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > index eb44418574f9..85ec758c4455 100644
> > --- a/kernel/trace/trace.c
> > +++ b/kernel/trace/trace.c
> > @@ -6317,12 +6317,18 @@ static void tracing_set_nop(struct trace_array *tr)
> >  	tr->current_trace = &nop_trace;
> >  }
> >  
> > +static bool tracer_options_updated;
> > +
> >  static void add_tracer_options(struct trace_array *tr, struct tracer *t)
> >  {
> >  	/* Only enable if the directory has been created already. */
> >  	if (!tr->dir)
> >  		return;
> >  
> > +	/* Only create trace option files after update_tracer_options finish */
> > +	if (!tracer_options_updated)
> > +		return;
> > +
> >  	create_trace_option_files(tr, t);
> >  }
> >  
> > @@ -9133,6 +9139,7 @@ static void update_tracer_options(struct trace_array *tr)
> >  {
> >  	mutex_lock(&trace_types_lock);
> >  	__update_tracer_options(tr);
> > +	tracer_options_updated = true;
> 
> I think you want to set this before the __update, as doing it after just
> makes the update a nop.

You are right.
I will update in v4, thanks!

> 
> -- Steve
> 
> 
> >  	mutex_unlock(&trace_types_lock);
> >  }
> >