[PATCH] init/main.c: log initcall level when initcall_debug is used

[PATCH] init/main.c: log initcall level when initcall_debug is used

[Francesco Valla]

When initcall_debug is specified on the command line, the start and
return point for each initcall is printed. However, no information on
the initcall level is reported.

Add to the initcall_debug infrastructure an additional print that
informs when a new initcall level is entered. This is particularly
useful when debugging dependency chains and/or working on boot time
reduction.

Signed-off-by: Francesco Valla <francesco@valla.it>
---
 init/main.c | 18 ++++++++++++++++--
 1 file changed, 16 insertions(+), 2 deletions(-)

diff --git a/init/main.c b/init/main.c
index 2a1757826397..80a07563036d 100644
--- a/init/main.c
+++ b/init/main.c
@@ -1214,6 +1214,12 @@ trace_initcall_finish_cb(void *data, initcall_t fn, int ret)
 		 fn, ret, (unsigned long long)ktime_us_delta(rettime, *calltime));
 }
 
+static __init_or_module void
+trace_initcall_level_cb(void *data, const char *level)
+{
+	printk(KERN_DEBUG "entering initcall level: %s\n", level);
+}
+
 static ktime_t initcall_calltime;
 
 #ifdef TRACEPOINTS_ENABLED
@@ -1225,10 +1231,12 @@ static void __init initcall_debug_enable(void)
 					    &initcall_calltime);
 	ret |= register_trace_initcall_finish(trace_initcall_finish_cb,
 					      &initcall_calltime);
+	ret |= register_trace_initcall_level(trace_initcall_level_cb, NULL);
 	WARN(ret, "Failed to register initcall tracepoints\n");
 }
 # define do_trace_initcall_start	trace_initcall_start
 # define do_trace_initcall_finish	trace_initcall_finish
+# define do_trace_initcall_level	trace_initcall_level
 #else
 static inline void do_trace_initcall_start(initcall_t fn)
 {
@@ -1242,6 +1250,12 @@ static inline void do_trace_initcall_finish(initcall_t fn, int ret)
 		return;
 	trace_initcall_finish_cb(&initcall_calltime, fn, ret);
 }
+static inline void do_trace_initcall_level(const char *level)
+{
+	if (!initcall_debug)
+		return;
+	trace_initcall_level_cb(NULL, level);
+}
 #endif /* !TRACEPOINTS_ENABLED */
 
 int __init_or_module do_one_initcall(initcall_t fn)
@@ -1314,7 +1328,7 @@ static void __init do_initcall_level(int level, char *command_line)
 		   level, level,
 		   NULL, ignore_unknown_bootoption);
 
-	trace_initcall_level(initcall_level_names[level]);
+	do_trace_initcall_level(initcall_level_names[level]);
 	for (fn = initcall_levels[level]; fn < initcall_levels[level+1]; fn++)
 		do_one_initcall(initcall_from_entry(fn));
 }
@@ -1358,7 +1372,7 @@ static void __init do_pre_smp_initcalls(void)
 {
 	initcall_entry_t *fn;
 
-	trace_initcall_level("early");
+	do_trace_initcall_level("early");
 	for (fn = __initcall_start; fn < __initcall0_start; fn++)
 		do_one_initcall(initcall_from_entry(fn));
 }
-- 
2.48.1

RE: [PATCH] init/main.c: log initcall level when initcall_debug is used

[Bird, Tim]

> -----Original Message-----
> From: Francesco Valla <francesco@valla.it>
> When initcall_debug is specified on the command line, the start and
> return point for each initcall is printed. However, no information on
> the initcall level is reported.
> 
> Add to the initcall_debug infrastructure an additional print that
> informs when a new initcall level is entered. This is particularly
> useful when debugging dependency chains and/or working on boot time
> reduction.
> 
> Signed-off-by: Francesco Valla <francesco@valla.it>
> ---
>  init/main.c | 18 ++++++++++++++++--
>  1 file changed, 16 insertions(+), 2 deletions(-)
> 
> diff --git a/init/main.c b/init/main.c
> index 2a1757826397..80a07563036d 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -1214,6 +1214,12 @@ trace_initcall_finish_cb(void *data, initcall_t fn, int ret)
>  		 fn, ret, (unsigned long long)ktime_us_delta(rettime, *calltime));
>  }
> 
> +static __init_or_module void
> +trace_initcall_level_cb(void *data, const char *level)
> +{
> +	printk(KERN_DEBUG "entering initcall level: %s\n", level);
> +}
> +
>  static ktime_t initcall_calltime;
> 
>  #ifdef TRACEPOINTS_ENABLED
> @@ -1225,10 +1231,12 @@ static void __init initcall_debug_enable(void)
>  					    &initcall_calltime);
>  	ret |= register_trace_initcall_finish(trace_initcall_finish_cb,
>  					      &initcall_calltime);
> +	ret |= register_trace_initcall_level(trace_initcall_level_cb, NULL);
>  	WARN(ret, "Failed to register initcall tracepoints\n");
>  }
>  # define do_trace_initcall_start	trace_initcall_start
>  # define do_trace_initcall_finish	trace_initcall_finish
> +# define do_trace_initcall_level	trace_initcall_level
>  #else
>  static inline void do_trace_initcall_start(initcall_t fn)
>  {
> @@ -1242,6 +1250,12 @@ static inline void do_trace_initcall_finish(initcall_t fn, int ret)
>  		return;
>  	trace_initcall_finish_cb(&initcall_calltime, fn, ret);
>  }
> +static inline void do_trace_initcall_level(const char *level)
> +{
> +	if (!initcall_debug)
> +		return;
> +	trace_initcall_level_cb(NULL, level);
> +}
>  #endif /* !TRACEPOINTS_ENABLED */
> 
>  int __init_or_module do_one_initcall(initcall_t fn)
> @@ -1314,7 +1328,7 @@ static void __init do_initcall_level(int level, char *command_line)
>  		   level, level,
>  		   NULL, ignore_unknown_bootoption);
> 
> -	trace_initcall_level(initcall_level_names[level]);
> +	do_trace_initcall_level(initcall_level_names[level]);
>  	for (fn = initcall_levels[level]; fn < initcall_levels[level+1]; fn++)
>  		do_one_initcall(initcall_from_entry(fn));
>  }
> @@ -1358,7 +1372,7 @@ static void __init do_pre_smp_initcalls(void)
>  {
>  	initcall_entry_t *fn;
> 
> -	trace_initcall_level("early");
> +	do_trace_initcall_level("early");
>  	for (fn = __initcall_start; fn < __initcall0_start; fn++)
>  		do_one_initcall(initcall_from_entry(fn));
>  }
> --
> 2.48.1

This all looks good to me.  Just to clarify, does tracing have to be enabled to get an
the 'entering initcall level...' printk message?  Or will you get a printk message with
tracing disabled, but initcall_debug specified on the command line?

What do we need to do to push this into mainline?  Based on our discussion in the SIG
meeting, there's no official maintainer for init/main.c.  I recommend pushing this
through Andrew Morton's tree, unless we can think of a better tree to push it through.
Since it does affect a tracer, maybe through Steve's tree?

Another option is for you, Francesco, to become the maintainer of init/main.c (!)
Let me know if you're interested in that.  We'll likely have some more boot-time
things to work on in init/main.c, and it would be nice to have someone managing
this stuff as it comes in.

Thanks, Francesco, for proposing this patch.  I think it will obviate the need for a portion of
my Boot Markers patch, that I suggested at Plumbers last year.
 -- Tim

Re: [PATCH] init/main.c: log initcall level when initcall_debug is used

[Francesco Valla]

Hi Tim,

On Tuesday, 1 April 2025 at 19:57:22 Bird, Tim <Tim.Bird@sony.com> wrote:
> > -----Original Message-----
> > From: Francesco Valla <francesco@valla.it>
> > When initcall_debug is specified on the command line, the start and
> > return point for each initcall is printed. However, no information on
> > the initcall level is reported.
> > 
> > Add to the initcall_debug infrastructure an additional print that
> > informs when a new initcall level is entered. This is particularly
> > useful when debugging dependency chains and/or working on boot time
> > reduction.
> > 
> > Signed-off-by: Francesco Valla <francesco@valla.it>
> > ---
> >  init/main.c | 18 ++++++++++++++++--
> >  1 file changed, 16 insertions(+), 2 deletions(-)
> > 
> > diff --git a/init/main.c b/init/main.c
> > index 2a1757826397..80a07563036d 100644
> > --- a/init/main.c
> > +++ b/init/main.c
> > @@ -1214,6 +1214,12 @@ trace_initcall_finish_cb(void *data, initcall_t fn, int ret)
> >  		 fn, ret, (unsigned long long)ktime_us_delta(rettime, *calltime));
> >  }
> > 
> > +static __init_or_module void
> > +trace_initcall_level_cb(void *data, const char *level)
> > +{
> > +	printk(KERN_DEBUG "entering initcall level: %s\n", level);
> > +}
> > +
> >  static ktime_t initcall_calltime;
> > 
> >  #ifdef TRACEPOINTS_ENABLED
> > @@ -1225,10 +1231,12 @@ static void __init initcall_debug_enable(void)
> >  					    &initcall_calltime);
> >  	ret |= register_trace_initcall_finish(trace_initcall_finish_cb,
> >  					      &initcall_calltime);
> > +	ret |= register_trace_initcall_level(trace_initcall_level_cb, NULL);
> >  	WARN(ret, "Failed to register initcall tracepoints\n");
> >  }
> >  # define do_trace_initcall_start	trace_initcall_start
> >  # define do_trace_initcall_finish	trace_initcall_finish
> > +# define do_trace_initcall_level	trace_initcall_level
> >  #else
> >  static inline void do_trace_initcall_start(initcall_t fn)
> >  {
> > @@ -1242,6 +1250,12 @@ static inline void do_trace_initcall_finish(initcall_t fn, int ret)
> >  		return;
> >  	trace_initcall_finish_cb(&initcall_calltime, fn, ret);
> >  }
> > +static inline void do_trace_initcall_level(const char *level)
> > +{
> > +	if (!initcall_debug)
> > +		return;
> > +	trace_initcall_level_cb(NULL, level);
> > +}
> >  #endif /* !TRACEPOINTS_ENABLED */
> > 
> >  int __init_or_module do_one_initcall(initcall_t fn)
> > @@ -1314,7 +1328,7 @@ static void __init do_initcall_level(int level, char *command_line)
> >  		   level, level,
> >  		   NULL, ignore_unknown_bootoption);
> > 
> > -	trace_initcall_level(initcall_level_names[level]);
> > +	do_trace_initcall_level(initcall_level_names[level]);
> >  	for (fn = initcall_levels[level]; fn < initcall_levels[level+1]; fn++)
> >  		do_one_initcall(initcall_from_entry(fn));
> >  }
> > @@ -1358,7 +1372,7 @@ static void __init do_pre_smp_initcalls(void)
> >  {
> >  	initcall_entry_t *fn;
> > 
> > -	trace_initcall_level("early");
> > +	do_trace_initcall_level("early");
> >  	for (fn = __initcall_start; fn < __initcall0_start; fn++)
> >  		do_one_initcall(initcall_from_entry(fn));
> >  }
> > --
> > 2.48.1
> 
> This all looks good to me.  Just to clarify, does tracing have to be enabled to get an
> the 'entering initcall level...' printk message?  Or will you get a printk message with
> tracing disabled, but initcall_debug specified on the command line?
> 

No, tracing doesn't have to be enabled. We are just attaching to the tracing subsystem
if it's there, just like it is done for the "calling" / "initcall returned" messages.

> What do we need to do to push this into mainline?  Based on our discussion in the SIG
> meeting, there's no official maintainer for init/main.c.  I recommend pushing this
> through Andrew Morton's tree, unless we can think of a better tree to push it through.
> Since it does affect a tracer, maybe through Steve's tree?
> 
> Another option is for you, Francesco, to become the maintainer of init/main.c (!)
> Let me know if you're interested in that.  We'll likely have some more boot-time
> things to work on in init/main.c, and it would be nice to have someone managing
> this stuff as it comes in.
> 

I fear I don't have the knowledge to maintain init/main.c, unfortunately. I can
for sure take a look at other MRs related to it, but that's it - I don't wan't to
take a commitment I cannot / am not able to honor.

> Thanks, Francesco, for proposing this patch.  I think it will obviate the need for a portion of
> my Boot Markers patch, that I suggested at Plumbers last year.
>  -- Tim
> 

Thank you for the review!

Francesco

Re: [PATCH] init/main.c: log initcall level when initcall_debug is used

[Andrew Morton]

On Sun, 16 Mar 2025 21:50:15 +0100 Francesco Valla <francesco@valla.it> wrote:

> When initcall_debug is specified on the command line, the start and
> return point for each initcall is printed. However, no information on
> the initcall level is reported.
> 
> Add to the initcall_debug infrastructure an additional print that
> informs when a new initcall level is entered. This is particularly
> useful when debugging dependency chains and/or working on boot time
> reduction.
> 
> ...
>
> --- a/init/main.c
> +++ b/init/main.c
> @@ -1214,6 +1214,12 @@ trace_initcall_finish_cb(void *data, initcall_t fn, int ret)
>  		 fn, ret, (unsigned long long)ktime_us_delta(rettime, *calltime));
>  }
>  
> +static __init_or_module void
> +trace_initcall_level_cb(void *data, const char *level)
> +{
> +	printk(KERN_DEBUG "entering initcall level: %s\n", level);
> +}

Please review and test this fixlet:

--- a/init/main.c~init-mainc-log-initcall-level-when-initcall_debug-is-used-fix
+++ a/init/main.c
@@ -1217,7 +1217,7 @@ trace_initcall_finish_cb(void *data, ini
 static __init_or_module void
 trace_initcall_level_cb(void *data, const char *level)
 {
-	printk(KERN_DEBUG "entering initcall level: %s\n", level);
+	pr_debug("entering initcall level: %s\n", level);
 }
 
 static ktime_t initcall_calltime;

Re: [PATCH] init/main.c: log initcall level when initcall_debug is used

[Rob Landley]

On 4/2/25 21:55, Andrew Morton wrote:
> Please review and test this fixlet:
> 
> --- a/init/main.c~init-mainc-log-initcall-level-when-initcall_debug-is-used-fix
> +++ a/init/main.c
> @@ -1217,7 +1217,7 @@ trace_initcall_finish_cb(void *data, ini
>   static __init_or_module void
>   trace_initcall_level_cb(void *data, const char *level)
>   {
> -	printk(KERN_DEBUG "entering initcall level: %s\n", level);
> +	pr_debug("entering initcall level: %s\n", level);
>   }

How do I tell kconfig to remove all pr_blah() below loglevel X so they 
aren't compiled into the kernel taking up space? I thought that was the 
reason for switching to the pr_thingy() macros (it was in the old -tiny 
tree Mackall walked away from) but last time I tried to do it in vanilla 
I couldn't find the knob or trace the relevant plumbing...

Rob

Re: [PATCH] init/main.c: log initcall level when initcall_debug is used

[Andrew Morton]

On Thu, 3 Apr 2025 01:42:46 -0500 Rob Landley <rob@landley.net> wrote:

> On 4/2/25 21:55, Andrew Morton wrote:
> > Please review and test this fixlet:
> > 
> > --- a/init/main.c~init-mainc-log-initcall-level-when-initcall_debug-is-used-fix
> > +++ a/init/main.c
> > @@ -1217,7 +1217,7 @@ trace_initcall_finish_cb(void *data, ini
> >   static __init_or_module void
> >   trace_initcall_level_cb(void *data, const char *level)
> >   {
> > -	printk(KERN_DEBUG "entering initcall level: %s\n", level);
> > +	pr_debug("entering initcall level: %s\n", level);
> >   }
> 
> How do I tell kconfig to remove all pr_blah() below loglevel X so they 
> aren't compiled into the kernel taking up space? I thought that was the 
> reason for switching to the pr_thingy() macros (it was in the old -tiny 
> tree Mackall walked away from) but last time I tried to do it in vanilla 
> I couldn't find the knob or trace the relevant plumbing...

Ask the maintainer :)

I can't see a way.  Maybe it was never merged.

Re: [PATCH] init/main.c: log initcall level when initcall_debug is used

[Petr Mladek]

On Thu 2025-04-03 00:09:35, Andrew Morton wrote:
> On Thu, 3 Apr 2025 01:42:46 -0500 Rob Landley <rob@landley.net> wrote:
> 
> > On 4/2/25 21:55, Andrew Morton wrote:
> > > Please review and test this fixlet:
> > > 
> > > --- a/init/main.c~init-mainc-log-initcall-level-when-initcall_debug-is-used-fix
> > > +++ a/init/main.c
> > > @@ -1217,7 +1217,7 @@ trace_initcall_finish_cb(void *data, ini
> > >   static __init_or_module void
> > >   trace_initcall_level_cb(void *data, const char *level)
> > >   {
> > > -	printk(KERN_DEBUG "entering initcall level: %s\n", level);
> > > +	pr_debug("entering initcall level: %s\n", level);
> > >   }
> > 
> > How do I tell kconfig to remove all pr_blah() below loglevel X so they 
> > aren't compiled into the kernel taking up space? I thought that was the 
> > reason for switching to the pr_thingy() macros (it was in the old -tiny 
> > tree Mackall walked away from) but last time I tried to do it in vanilla 
> > I couldn't find the knob or trace the relevant plumbing...
> 
> Ask the maintainer :)
> 
> I can't see a way.  Maybe it was never merged.

If I read the definition of pr_debug() correctly then it should
become nop when CONFIG_DYNAMIC_DEBUG is not defined, look
for "pr_debug" and "no_printk" in include/linux/printk.h.

That said, I have never checked this. Another condition is
that DEBUG must not be defined. But I guess that it is
the default.

Best Regards,
Petr

Re: [PATCH] init/main.c: log initcall level when initcall_debug is used

[Geert Uytterhoeven]

Hi Andrew,

On Thu, 3 Apr 2025 at 04:56, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Sun, 16 Mar 2025 21:50:15 +0100 Francesco Valla <francesco@valla.it> wrote:
> > When initcall_debug is specified on the command line, the start and
> > return point for each initcall is printed. However, no information on
> > the initcall level is reported.
> >
> > Add to the initcall_debug infrastructure an additional print that
> > informs when a new initcall level is entered. This is particularly
> > useful when debugging dependency chains and/or working on boot time
> > reduction.
> >
> > ...
> >
> > --- a/init/main.c
> > +++ b/init/main.c
> > @@ -1214,6 +1214,12 @@ trace_initcall_finish_cb(void *data, initcall_t fn, int ret)
> >                fn, ret, (unsigned long long)ktime_us_delta(rettime, *calltime));
> >  }
> >
> > +static __init_or_module void
> > +trace_initcall_level_cb(void *data, const char *level)
> > +{
> > +     printk(KERN_DEBUG "entering initcall level: %s\n", level);
> > +}
>
> Please review and test this fixlet:
>
> --- a/init/main.c~init-mainc-log-initcall-level-when-initcall_debug-is-used-fix
> +++ a/init/main.c
> @@ -1217,7 +1217,7 @@ trace_initcall_finish_cb(void *data, ini
>  static __init_or_module void
>  trace_initcall_level_cb(void *data, const char *level)
>  {
> -       printk(KERN_DEBUG "entering initcall level: %s\n", level);
> +       pr_debug("entering initcall level: %s\n", level);
>  }
>
>  static ktime_t initcall_calltime;

I think the "printk(KERN_DEBUG ...)" construct is intentional.
The message should be logged when "initcall_debug" is passed on
the kernel command line, while pr_debug() is a no-op unless DEBUG is
defined inside the source file.

See also the two existing users in init/main.c near
https://elixir.bootlin.com/linux/v6.13.7/source/init/main.c#L1207.

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: [PATCH] init/main.c: log initcall level when initcall_debug is used

[Francesco Valla]

On Thursday, 3 April 2025 at 10:27:14 Geert Uytterhoeven <geert@linux-m68k.org> wrote:
> Hi Andrew,
> 
> On Thu, 3 Apr 2025 at 04:56, Andrew Morton <akpm@linux-foundation.org> wrote:
> > On Sun, 16 Mar 2025 21:50:15 +0100 Francesco Valla <francesco@valla.it> wrote:
> > > When initcall_debug is specified on the command line, the start and
> > > return point for each initcall is printed. However, no information on
> > > the initcall level is reported.
> > >
> > > Add to the initcall_debug infrastructure an additional print that
> > > informs when a new initcall level is entered. This is particularly
> > > useful when debugging dependency chains and/or working on boot time
> > > reduction.
> > >
> > > ...
> > >
> > > --- a/init/main.c
> > > +++ b/init/main.c
> > > @@ -1214,6 +1214,12 @@ trace_initcall_finish_cb(void *data, initcall_t fn, int ret)
> > >                fn, ret, (unsigned long long)ktime_us_delta(rettime, *calltime));
> > >  }
> > >
> > > +static __init_or_module void
> > > +trace_initcall_level_cb(void *data, const char *level)
> > > +{
> > > +     printk(KERN_DEBUG "entering initcall level: %s\n", level);
> > > +}
> >
> > Please review and test this fixlet:
> >
> > --- a/init/main.c~init-mainc-log-initcall-level-when-initcall_debug-is-used-fix
> > +++ a/init/main.c
> > @@ -1217,7 +1217,7 @@ trace_initcall_finish_cb(void *data, ini
> >  static __init_or_module void
> >  trace_initcall_level_cb(void *data, const char *level)
> >  {
> > -       printk(KERN_DEBUG "entering initcall level: %s\n", level);
> > +       pr_debug("entering initcall level: %s\n", level);
> >  }
> >
> >  static ktime_t initcall_calltime;
> 
> I think the "printk(KERN_DEBUG ...)" construct is intentional.
> The message should be logged when "initcall_debug" is passed on
> the kernel command line, while pr_debug() is a no-op unless DEBUG is
> defined inside the source file.
> 
> See also the two existing users in init/main.c near
> https://elixir.bootlin.com/linux/v6.13.7/source/init/main.c#L1207.
> 

Yes, printk(KERN_DEBUG ...) here is intentional, or it would be removed,
as Geert is correctly saying.

We have another occurrence of this for the "probe" messages also related
to initcall_debug, with a nice explanatory comment:

https://elixir.bootlin.com/linux/v6.14-rc6/source/drivers/base/dd.c#L741


Thank you!

Francesco