Re: [PATCH 3/3] lockdep: Use line-buffered printk() for lockdep messages.

[Petr Mladek]

On Sat 2018-11-10 17:52:17, Tetsuo Handa wrote:
> On 2018/11/10 0:43, Petr Mladek wrote:
> > On Fri 2018-11-09 18:55:26, Tetsuo Handa wrote:
> >> How early_printk requirement affects line buffered printk() API?
> >>
> >> I don't think it is impossible to convert from
> >>
> >>      printk("Testing feature XYZ..");
> >>      this_may_blow_up_because_of_hw_bugs();
> >>      printk(KERN_CONT " ... ok\n");
> >>
> >> to
> >>
> >>      printk("Testing feature XYZ:\n");
> >>      this_may_blow_up_because_of_hw_bugs();
> >>      printk("Testing feature XYZ.. ... ok\n");
> >>
> >> in https://lore.kernel.org/lkml/CA+55aFwmwdY_mMqdEyFPpRhCKRyeqj=+aCqe5nN108v8ELFvPw@xxxxxxxxxxxxxx/ .
> > 
> > I just wonder how this pattern is common. I have tried but I failed
> > to find any instance.
> > 
> > This problem looks like a big argument against explicit buffers.
> > But I wonder if it is real.
> 
> An example of boot up messages where buffering makes difference.
> 
> Vanilla:
> 
> [    0.260459] smp: Bringing up secondary CPUs ...
> [    0.269595] x86: Booting SMP configuration:
> [    0.270461] .... node  #0, CPUs:      #1
> [    0.066578] Disabled fast string operations
> [    0.066578] mce: CPU supports 0 MCE banks
> [    0.066578] smpboot: CPU 1 Converting physical 2 to logical package 1
> [    0.342569]  #2
> [    0.066578] Disabled fast string operations
> [    0.066578] mce: CPU supports 0 MCE banks
> [    0.066578] smpboot: CPU 2 Converting physical 4 to logical package 2
> [    0.413442]  #3
> [    0.066578] Disabled fast string operations
> [    0.066578] mce: CPU supports 0 MCE banks
> [    0.066578] smpboot: CPU 3 Converting physical 6 to logical package 3
> [    0.476562] smp: Brought up 1 node, 4 CPUs
> [    0.477477] smpboot: Max logical packages: 8
> [    0.477514] smpboot: Total of 4 processors activated (22691.70 BogoMIPS)
> 
> With try_buffered_printk() patch:
> 
> [    0.279768] smp: Bringing up secondary CPUs ...
> [    0.288825] x86: Booting SMP configuration:
> [    0.066748] Disabled fast string operations
> [    0.066748] mce: CPU supports 0 MCE banks
> [    0.066748] smpboot: CPU 1 Converting physical 2 to logical package 1
> [    0.066748] Disabled fast string operations
> [    0.066748] mce: CPU supports 0 MCE banks
> [    0.066748] smpboot: CPU 2 Converting physical 4 to logical package 2
> [    0.066748] Disabled fast string operations
> [    0.066748] mce: CPU supports 0 MCE banks
> [    0.066748] smpboot: CPU 3 Converting physical 6 to logical package 3
> [    0.495862] .... node  #0, CPUs:      #1 #2 #3
6smp: Brought up 1 node, 4 CPUs
> [    0.496833] smpboot: Max logical packages: 8
> [    0.497609] smpboot: Total of 4 processors activated (22665.22 BogoMIPS)
> 
> 
> 
> Hmm, arch/x86/kernel/smpboot.c is not emitting '\n' after #num
> 
>         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);
> 
> and causing
> 
>         pr_info("Brought up %d node%s, %d CPU%s\n",
>                 num_nodes, (num_nodes > 1 ? "s" : ""),
>                 num_cpus,  (num_cpus  > 1 ? "s" : ""));
> 
> line to be concatenated to previous line.
> Maybe disable try_buffered_printk() if system_state !=
> SYSTEM_RUNNING ?

We need to solve continuous lines also during boot. Also similar
problems might be in the code that is called in SYSTEM_RUNNING state.

This is yet another clue that try_buffered_printk() approach is not
that good idea.

Best Regards,
Petr