Re: smpboot: CPU numbers printed as warning

[Paul Menzel <pmenzel@molgen.mpg.de>]

Dear Petr,


Thank you for the quick reply.


Am 16.02.21 um 10:49 schrieb Petr Mladek:
> On Mon 2021-02-15 20:22:34, Paul Menzel wrote:

>> Using Linux 5.10.13 (and before), looking at the Linux kernel warnings, the
>> CPU numbers show up. For example with 12 cpus/threads:
>>
>> ```
>> $ sudo dmesg --level=warn
>> [    0.216103]   #2
>> [    0.220105]   #3
>> [    0.224103]   #4
>> [    0.228104]   #5
>> [    0.232110]   #6
>> [    0.236101]   #7
>> [    0.240102]   #8
>> [    0.244102]   #9
>> [    0.248100]  #10
>> [    0.252098]  #11
>> ```
> 
> Is this the exact output from sudo dmesg --level=warn?

Yes, it is.

> It is strange that each CPU number is printed on its own line.

Should it be put on one line, if `dmesg --level=warn` is executed, even 
with other messages in between?

> Anyway, it might be affected by the new lockless ringbuffer.
> The original code decided whether to connect the lines only by
> "current" task pointer. The lockless ring buffer takes into account
> also CPU number.
> 
> Well, it has never been reliable. For example, I see here:
> 
> <6>[    0.238262][    T1] smp: Bringing up secondary CPUs ...
> <6>[    0.239340][    T1] x86: Booting SMP configuration:
> <6>[    0.239794][    T1] .... node  #0, CPUs:      #1
> <6>[    0.113946][    T0] kvm-clock: cpu 1, msr 6ba01041, secondary cpu clock
> <6>[    0.113946][    T0] smpboot: CPU 1 Converting physical 0 to logical die 1
> <6>[    0.246056][   T16] kvm-guest: stealtime: cpu 1, msr 17f9f2080
> <4>[    0.246679][    T1]  #2
> <6>[    0.113946][    T0] kvm-clock: cpu 2, msr 6ba01081, secondary cpu clock
> <6>[    0.113946][    T0] smpboot: CPU 2 Converting physical 0 to logical die 2
> <6>[    0.250023][   T21] kvm-guest: stealtime: cpu 2, msr 17fbf2080
> <4>[    0.250648][    T1]  #3
> <6>[    0.113946][    T0] kvm-clock: cpu 3, msr 6ba010c1, secondary cpu clock
> <6>[    0.113946][    T0] smpboot: CPU 3 Converting physical 0 to logical die 3
> <6>[    0.254026][   T26] kvm-guest: stealtime: cpu 3, msr 17fdf2080
> <6>[    0.254568][    T1] smp: Brought up 1 node, 4 CPUs
> <6>[    0.254597][    T1] smpboot: Max logical packages: 4
> <6>[    0.255097][    T1] smpboot: Total of 4 processors activated (16896.11 BogoMIPS)
> 
> There are another messages printed in between that obviously break pr_cont().

Yes, that is what I meant.

>> If I am not mistaken, this is from `announce_cpu()` in
>> `arch/x86/kernel/smpboot.c`, and the `pr_cont()` in their “forgets” the log
>> level it belongs to, maybe because of SMP and other messages are printed in
>> between.
>>
>> ```
>>          if (system_state < SYSTEM_RUNNING) {
>>                  if (node != current_node) {
>>                          if (current_node > (-1))
>>                                  pr_cont("\n");
>>                          current_node = node;
>>
>>                          printk(KERN_INFO ".... node %*s#%d, CPUs:  ",
>>                                 node_width - num_digits(node), " ", node);
>>                  }
>>
>>                  /* Add padding for the BSP */
>>                  if (cpu == 1)
>>                          pr_cont("%*s", width + 1, " ");
>>
>>                  pr_cont("%*s#%d", width - num_digits(cpu), " ", cpu);
>>
>>          } else
>>                  pr_info("Booting Node %d Processor %d APIC 0x%x\n",
>>                          node, cpu, apicid);
>> ```
> 
>> Would using `pr_info()` instead be an acceptable fix?
> 
> Makes sense to me.
> 
> Also you should add '\n' into the previous string to make the behavior
> clear. It will always be printed on a new line when pr_info()
> is used.

I am going to reply to Borislav’s response.


Kind regards,

Paul