diff mbox series

[-next,v1] x86/apic: Reduce print level of CPU limit announcement

Message ID 20190327090905.5588-1-leon@kernel.org (mailing list archive)
State Changes Requested
Headers show
Series [-next,v1] x86/apic: Reduce print level of CPU limit announcement | expand

Commit Message

Leon Romanovsky March 27, 2019, 9:09 a.m. UTC 
From: Leon Romanovsky <leonro@mellanox.com>

Kernel is booted with less possible CPUs (possible_cpus kernel boot
option) than available CPUs will have prints like this:

[    1.131039] APIC: NR_CPUS/possible_cpus limit of 8 reached. Processor 55/0x1f ignored.
[    1.132228] ACPI: Unable to map lapic to logical cpu number

Those warnings are printed for every not-enabled CPU and on the systems
with large number of such CPUs, we see a lot of those prints for default
print level.

Simple conversion of first line to be in debug level and removal of second line
which is redundant, will remove them while leaving the option to debug system.

Signed-off-by: Leon Romanovsky <leonro@mellanox.com>
---
Changelog v0->v1:
 * Completely removed print from boot.c and updated commit message accordingly.
---
 arch/x86/kernel/acpi/boot.c | 4 +---
 arch/x86/kernel/apic/apic.c | 6 +++---
 2 files changed, 4 insertions(+), 6 deletions(-)

--
2.20.1

Comments

Joe Perches March 27, 2019, 9:17 a.m. UTC | #1 
On Wed, 2019-03-27 at 11:09 +0200, Leon Romanovsky wrote:
> Kernel is booted with less possible CPUs (possible_cpus kernel boot
> option) than available CPUs will have prints like this:
[]
> diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
[]
> @@ -2305,9 +2305,9 @@ int generic_processor_info(int apicid, int version)
>  	if (num_processors >= nr_cpu_ids) {
>  		int thiscpu = max + disabled_cpus;
> 
> -		pr_warning("APIC: NR_CPUS/possible_cpus limit of %i "
> -			   "reached. Processor %d/0x%x ignored.\n",
> -			   max, thiscpu, apicid);
> +		pr_debug(
> +			"APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> +			max, thiscpu, apicid);

2 lines please

		pr_debug("APIC: etc...",
			 max, thiscpu, ...);

And this would probably be better as

		printk(KERN_DEBUG "APIC: etc...",
		 ...)

to avoid the need to compile with DEBUG or enable
with CONFIG_DYNAMIC_DEBUG
Leon Romanovsky March 27, 2019, 9:38 a.m. UTC | #2 
On Wed, Mar 27, 2019 at 02:17:40AM -0700, Joe Perches wrote:
> On Wed, 2019-03-27 at 11:09 +0200, Leon Romanovsky wrote:
> > Kernel is booted with less possible CPUs (possible_cpus kernel boot
> > option) than available CPUs will have prints like this:
> []
> > diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> []
> > @@ -2305,9 +2305,9 @@ int generic_processor_info(int apicid, int version)
> >  	if (num_processors >= nr_cpu_ids) {
> >  		int thiscpu = max + disabled_cpus;
> >
> > -		pr_warning("APIC: NR_CPUS/possible_cpus limit of %i "
> > -			   "reached. Processor %d/0x%x ignored.\n",
> > -			   max, thiscpu, apicid);
> > +		pr_debug(
> > +			"APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > +			max, thiscpu, apicid);
>
> 2 lines please
>
> 		pr_debug("APIC: etc...",
> 			 max, thiscpu, ...);

It was two lines before, but I changed for two reasons:
 * It helped me to grep the source code to find the origin of dmesg warning.
 * i got checkpatch warning about spitted string, can you please fix checkpatch do not complain?

>
> And this would probably be better as
>
> 		printk(KERN_DEBUG "APIC: etc...",
> 		 ...)
>
> to avoid the need to compile with DEBUG or enable
> with CONFIG_DYNAMIC_DEBUG

You don't need anything like this, just provide dyndbg parameters
through kernel command line.

Thanks

>
>
>
Joe Perches March 27, 2019, 9:49 a.m. UTC | #3 
On Wed, 2019-03-27 at 11:38 +0200, Leon Romanovsky wrote:
> On Wed, Mar 27, 2019 at 02:17:40AM -0700, Joe Perches wrote:
> > On Wed, 2019-03-27 at 11:09 +0200, Leon Romanovsky wrote:
> > > Kernel is booted with less possible CPUs (possible_cpus kernel boot
> > > option) than available CPUs will have prints like this:
> > []
> > > diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> > []
> > > @@ -2305,9 +2305,9 @@ int generic_processor_info(int apicid, int version)
> > >  	if (num_processors >= nr_cpu_ids) {
> > >  		int thiscpu = max + disabled_cpus;
> > > 
> > > -		pr_warning("APIC: NR_CPUS/possible_cpus limit of %i "
> > > -			   "reached. Processor %d/0x%x ignored.\n",
> > > -			   max, thiscpu, apicid);
> > > +		pr_debug(
> > > +			"APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > > +			max, thiscpu, apicid);
> > 
> > 2 lines please
> > 
> > 		pr_debug("APIC: etc...",
> > 			 max, thiscpu, ...);
> 
> It was two lines before, but I changed for two reasons:
>  * It helped me to grep the source code to find the origin of dmesg warning.
>  * i got checkpatch warning about spitted string, can you please fix checkpatch do not complain?

Yes, use

	pr_debug("APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
		 max, thiscpu, apicid);

or better

	printk(KERN_DEBUG "APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
	       max, thiscpu, apicid);

> > And this would probably be better as
> > 
> > 		printk(KERN_DEBUG "APIC: etc...",
> > 		 ...)
> > 
> > to avoid the need to compile with DEBUG or enable
> > with CONFIG_DYNAMIC_DEBUG
> 
> You don't need anything like this, just provide dyndbg parameters
> through kernel command line.

That assumes CONFIG_DYNAMIC_DEBUG is always enabled,
and it is not enabled in many .config files.
Leon Romanovsky March 27, 2019, 9:53 a.m. UTC | #4 
On Wed, Mar 27, 2019 at 02:49:02AM -0700, Joe Perches wrote:
> On Wed, 2019-03-27 at 11:38 +0200, Leon Romanovsky wrote:
> > On Wed, Mar 27, 2019 at 02:17:40AM -0700, Joe Perches wrote:
> > > On Wed, 2019-03-27 at 11:09 +0200, Leon Romanovsky wrote:
> > > > Kernel is booted with less possible CPUs (possible_cpus kernel boot
> > > > option) than available CPUs will have prints like this:
> > > []
> > > > diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> > > []
> > > > @@ -2305,9 +2305,9 @@ int generic_processor_info(int apicid, int version)
> > > >  	if (num_processors >= nr_cpu_ids) {
> > > >  		int thiscpu = max + disabled_cpus;
> > > >
> > > > -		pr_warning("APIC: NR_CPUS/possible_cpus limit of %i "
> > > > -			   "reached. Processor %d/0x%x ignored.\n",
> > > > -			   max, thiscpu, apicid);
> > > > +		pr_debug(
> > > > +			"APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > > > +			max, thiscpu, apicid);
> > >
> > > 2 lines please
> > >
> > > 		pr_debug("APIC: etc...",
> > > 			 max, thiscpu, ...);
> >
> > It was two lines before, but I changed for two reasons:
> >  * It helped me to grep the source code to find the origin of dmesg warning.
> >  * i got checkpatch warning about spitted string, can you please fix checkpatch do not complain?
>
> Yes, use
>
> 	pr_debug("APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> 		 max, thiscpu, apicid);

Ahh, I see, I got such change from clang formatter.

>
> or better
>
> 	printk(KERN_DEBUG "APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> 	       max, thiscpu, apicid);
>
> > > And this would probably be better as
> > >
> > > 		printk(KERN_DEBUG "APIC: etc...",
> > > 		 ...)
> > >
> > > to avoid the need to compile with DEBUG or enable
> > > with CONFIG_DYNAMIC_DEBUG
> >
> > You don't need anything like this, just provide dyndbg parameters
> > through kernel command line.
>
> That assumes CONFIG_DYNAMIC_DEBUG is always enabled,
> and it is not enabled in many .config files.

No problem.

Thanks

>
>
Leon Romanovsky March 27, 2019, 10:11 a.m. UTC | #5 
On Wed, Mar 27, 2019 at 11:53:37AM +0200, Leon Romanovsky wrote:
> On Wed, Mar 27, 2019 at 02:49:02AM -0700, Joe Perches wrote:
> > On Wed, 2019-03-27 at 11:38 +0200, Leon Romanovsky wrote:
> > > On Wed, Mar 27, 2019 at 02:17:40AM -0700, Joe Perches wrote:
> > > > On Wed, 2019-03-27 at 11:09 +0200, Leon Romanovsky wrote:
> > > > > Kernel is booted with less possible CPUs (possible_cpus kernel boot
> > > > > option) than available CPUs will have prints like this:
> > > > []
> > > > > diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> > > > []
> > > > > @@ -2305,9 +2305,9 @@ int generic_processor_info(int apicid, int version)
> > > > >  	if (num_processors >= nr_cpu_ids) {
> > > > >  		int thiscpu = max + disabled_cpus;
> > > > >
> > > > > -		pr_warning("APIC: NR_CPUS/possible_cpus limit of %i "
> > > > > -			   "reached. Processor %d/0x%x ignored.\n",
> > > > > -			   max, thiscpu, apicid);
> > > > > +		pr_debug(
> > > > > +			"APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > > > > +			max, thiscpu, apicid);
> > > >
> > > > 2 lines please
> > > >
> > > > 		pr_debug("APIC: etc...",
> > > > 			 max, thiscpu, ...);
> > >
> > > It was two lines before, but I changed for two reasons:
> > >  * It helped me to grep the source code to find the origin of dmesg warning.
> > >  * i got checkpatch warning about spitted string, can you please fix checkpatch do not complain?
> >
> > Yes, use
> >
> > 	pr_debug("APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > 		 max, thiscpu, apicid);
>
> Ahh, I see, I got such change from clang formatter.
>
> >
> > or better
> >
> > 	printk(KERN_DEBUG "APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > 	       max, thiscpu, apicid);
> >
> > > > And this would probably be better as
> > > >
> > > > 		printk(KERN_DEBUG "APIC: etc...",
> > > > 		 ...)
> > > >
> > > > to avoid the need to compile with DEBUG or enable
> > > > with CONFIG_DYNAMIC_DEBUG
> > >
> > > You don't need anything like this, just provide dyndbg parameters
> > > through kernel command line.
> >
> > That assumes CONFIG_DYNAMIC_DEBUG is always enabled,
> > and it is not enabled in many .config files.
>
> No problem.

ok, I tested your variant and it still prints a t least on my systems,
so it won't solve my problem. I'll keep this patch as is.

Thanks for the review.

>
> Thanks
>
> >
> >
Joe Perches March 27, 2019, 10:17 a.m. UTC | #6 
On Wed, 2019-03-27 at 12:11 +0200, Leon Romanovsky wrote:
> On Wed, Mar 27, 2019 at 11:53:37AM +0200, Leon Romanovsky wrote:
> > On Wed, Mar 27, 2019 at 02:49:02AM -0700, Joe Perches wrote:
> > > On Wed, 2019-03-27 at 11:38 +0200, Leon Romanovsky wrote:
> > > > On Wed, Mar 27, 2019 at 02:17:40AM -0700, Joe Perches wrote:
> > > > > On Wed, 2019-03-27 at 11:09 +0200, Leon Romanovsky wrote:
> > > > > > Kernel is booted with less possible CPUs (possible_cpus kernel boot
> > > > > > option) than available CPUs will have prints like this:
> > > > > []
> > > > > > diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
> > > > > []
> > > > > > @@ -2305,9 +2305,9 @@ int generic_processor_info(int apicid, int version)
> > > > > >  	if (num_processors >= nr_cpu_ids) {
> > > > > >  		int thiscpu = max + disabled_cpus;
> > > > > > 
> > > > > > -		pr_warning("APIC: NR_CPUS/possible_cpus limit of %i "
> > > > > > -			   "reached. Processor %d/0x%x ignored.\n",
> > > > > > -			   max, thiscpu, apicid);
> > > > > > +		pr_debug(
> > > > > > +			"APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > > > > > +			max, thiscpu, apicid);
> > > > > 
> > > > > 2 lines please
> > > > > 
> > > > > 		pr_debug("APIC: etc...",
> > > > > 			 max, thiscpu, ...);
> > > > 
> > > > It was two lines before, but I changed for two reasons:
> > > >  * It helped me to grep the source code to find the origin of dmesg warning.
> > > >  * i got checkpatch warning about spitted string, can you please fix checkpatch do not complain?
> > > 
> > > Yes, use
> > > 
> > > 	pr_debug("APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > > 		 max, thiscpu, apicid);
> > 
> > Ahh, I see, I got such change from clang formatter.
> > 
> > > or better
> > > 
> > > 	printk(KERN_DEBUG "APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
> > > 	       max, thiscpu, apicid);
> > > 
> > > > > And this would probably be better as
> > > > > 
> > > > > 		printk(KERN_DEBUG "APIC: etc...",
> > > > > 		 ...)
> > > > > 
> > > > > to avoid the need to compile with DEBUG or enable
> > > > > with CONFIG_DYNAMIC_DEBUG
> > > > 
> > > > You don't need anything like this, just provide dyndbg parameters
> > > > through kernel command line.
> > > 
> > > That assumes CONFIG_DYNAMIC_DEBUG is always enabled,
> > > and it is not enabled in many .config files.
> > 
> > No problem.
> 
> ok, I tested your variant and it still prints a t least on my systems,
> so it won't solve my problem. I'll keep this patch as is.

I believe it's more common to set the console logging level
to exclude the KERN_DEBUG level when appropriate.

https://linuxconfig.org/introduction-to-the-linux-kernel-log-levels
Borislav Petkov March 27, 2019, 10:18 a.m. UTC | #7 
On Wed, Mar 27, 2019 at 12:11:33PM +0200, Leon Romanovsky wrote:
> ok, I tested your variant and it still prints a t least on my systems,

Probably because your loglevel is set to debug. And no, we don't want to
have to enable some config option in order to see this.

Also, the ugly linebreak needs to go.
Leon Romanovsky March 27, 2019, 10:50 a.m. UTC | #8 
On Wed, Mar 27, 2019 at 11:18:15AM +0100, Borislav Petkov wrote:
> On Wed, Mar 27, 2019 at 12:11:33PM +0200, Leon Romanovsky wrote:
> > ok, I tested your variant and it still prints a t least on my systems,
>
> Probably because your loglevel is set to debug. And no, we don't want to
> have to enable some config option in order to see this.

It is how we are internally running verification and development,
with KERN_DEBUG level, we need it to catch bugs.

This "some config option" is dynamic debug prints and most probably it
is enabled in your or any kernel developer in the world.

Please let me know, If you insist on changing pr_debug to printk(KERN_DEBUG ...).

>
> Also, the ugly linebreak needs to go.
>
> --
> Regards/Gruss,
>     Boris.
>
> Good mailing practices for 400: avoid top-posting and trim the reply.
Borislav Petkov March 27, 2019, 11:14 a.m. UTC | #9 
On Wed, Mar 27, 2019 at 12:50:24PM +0200, Leon Romanovsky wrote:
> It is how we are internally running verification and development,
> with KERN_DEBUG level, we need it to catch bugs.

And what is the big deal with seeing those messages? Why are *exactly*
those two such a big problem and the gazillion other debug messages are
fine?

> This "some config option" is dynamic debug prints and most probably it
> is enabled in your or any kernel developer in the world.

I personally don't use it because it only gets in the way.
Leon Romanovsky March 27, 2019, 11:36 a.m. UTC | #10 
On Wed, Mar 27, 2019 at 12:14:52PM +0100, Borislav Petkov wrote:
> On Wed, Mar 27, 2019 at 12:50:24PM +0200, Leon Romanovsky wrote:
> > It is how we are internally running verification and development,
> > with KERN_DEBUG level, we need it to catch bugs.
>
> And what is the big deal with seeing those messages? Why are *exactly*
> those two such a big problem and the gazillion other debug messages are
> fine?

At the end, it is reduced to our usage, we are running QEMU inside
docker to test kernel changes with limitation on number of CPUs to use.
The systems are optimized to boot kernel as soon as possible in order
to run tests and on my machine (64 CPUs) reduce is visible: from ~2.6
sec to ~2.3 sec from execution to kernel boot.

>
> > This "some config option" is dynamic debug prints and most probably it
> > is enabled in your or any kernel developer in the world.
>
> I personally don't use it because it only gets in the way.
>
> --
> Regards/Gruss,
>     Boris.
>
> Good mailing practices for 400: avoid top-posting and trim the reply.
Borislav Petkov March 27, 2019, 11:49 a.m. UTC | #11 
On Wed, Mar 27, 2019 at 01:36:28PM +0200, Leon Romanovsky wrote:
> At the end, it is reduced to our usage, we are running QEMU inside
> docker to test kernel changes with limitation on number of CPUs to use.
> The systems are optimized to boot kernel as soon as possible in order
> to run tests and on my machine (64 CPUs) reduce is visible: from ~2.6
> sec to ~2.3 sec from execution to kernel boot.

You're kidding, right?

0.3 sec boot time "improvement" for a kernel on which you run tests
which take orders of magnitude longer (I assume). And you want to hide
this message in the upstream kernel because you want to minimally speed
up *your* *specific* usage ?

And we still are wasting time talking about this?!

Oh boy.
Leon Romanovsky March 27, 2019, 11:58 a.m. UTC | #12 
On Wed, Mar 27, 2019 at 12:49:17PM +0100, Borislav Petkov wrote:
> On Wed, Mar 27, 2019 at 01:36:28PM +0200, Leon Romanovsky wrote:
> > At the end, it is reduced to our usage, we are running QEMU inside
> > docker to test kernel changes with limitation on number of CPUs to use.
> > The systems are optimized to boot kernel as soon as possible in order
> > to run tests and on my machine (64 CPUs) reduce is visible: from ~2.6
> > sec to ~2.3 sec from execution to kernel boot.
>
> You're kidding, right?
>
> 0.3 sec boot time "improvement" for a kernel on which you run tests
> which take orders of magnitude longer (I assume). And you want to hide
> this message in the upstream kernel because you want to minimally speed
> up *your* *specific* usage ?
>
> And we still are wasting time talking about this?!

I understand your point, we will keep it internally.
Sorry for wasting your time.

Thanks

>
> Oh boy.
>
> --
> Regards/Gruss,
>     Boris.
>
> Good mailing practices for 400: avoid top-posting and trim the reply.
diff mbox series

Patch

diff --git a/arch/x86/kernel/acpi/boot.c b/arch/x86/kernel/acpi/boot.c
index 8dcbf6890714..baac0a40bc44 100644
--- a/arch/x86/kernel/acpi/boot.c
+++ b/arch/x86/kernel/acpi/boot.c
@@ -769,10 +769,8 @@  int acpi_map_cpu(acpi_handle handle, phys_cpuid_t physid, u32 acpi_id,
 	int cpu;

 	cpu = acpi_register_lapic(physid, acpi_id, ACPI_MADT_ENABLED);
-	if (cpu < 0) {
-		pr_info(PREFIX "Unable to map lapic to logical cpu number\n");
+	if (cpu < 0)
 		return cpu;
-	}

 	acpi_processor_set_pdc(handle);
 	acpi_map_cpu2node(handle, cpu, physid);
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index b7bcdd781651..8c2a487b5216 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -2305,9 +2305,9 @@  int generic_processor_info(int apicid, int version)
 	if (num_processors >= nr_cpu_ids) {
 		int thiscpu = max + disabled_cpus;

-		pr_warning("APIC: NR_CPUS/possible_cpus limit of %i "
-			   "reached. Processor %d/0x%x ignored.\n",
-			   max, thiscpu, apicid);
+		pr_debug(
+			"APIC: NR_CPUS/possible_cpus limit of %i reached. Processor %d/0x%x ignored.\n",
+			max, thiscpu, apicid);

 		disabled_cpus++;
 		return -EINVAL;