lkml.org 
[lkml]   [2021]   [Feb]   [16]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: smpboot: CPU numbers printed as warning
From
Date
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

\
 
 \ /
  Last update: 2021-02-17 11:36    [W:0.119 / U:0.144 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site