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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Sat, 10 Nov 2018 17:52:17 +0900
From:   Tetsuo Handa <penguin-kernel@...ove.sakura.ne.jp>
To:     Petr Mladek <pmladek@...e.com>
Cc:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>,
        Linus Torvalds <torvalds@...ux-foundation.org>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Dmitriy Vyukov <dvyukov@...gle.com>,
        Steven Rostedt <rostedt@...dmis.org>,
        Alexander Potapenko <glider@...gle.com>,
        Fengguang Wu <fengguang.wu@...el.com>,
        Josh Poimboeuf <jpoimboe@...hat.com>,
        LKML <linux-kernel@...r.kernel.org>,
        Andrew Morton <akpm@...ux-foundation.org>, linux-mm@...ck.org,
        Ingo Molnar <mingo@...hat.com>,
        Peter Zijlstra <peterz@...radead.org>,
        Will Deacon <will.deacon@....com>
Subject: Re: [PATCH 3/3] lockdep: Use line-buffered printk() for lockdep
 messages.

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@mail.gmail.com/ .
> 
> 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 ?