linux-kernel - Re: [PATCH printk 3/5] printk: use buffer pool for sprint buffers

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]

Message-ID: <de1b6e44-bbd7-6264-d354-4f9d76bd2870@prevas.dk>
Date:   Thu, 1 Oct 2020 09:15:39 +0200
From:   Rasmus Villemoes <rasmus.villemoes@...vas.dk>
To:     Steven Rostedt <rostedt@...dmis.org>
Cc:     Petr Mladek <pmladek@...e.com>,
        John Ogness <john.ogness@...utronix.de>,
        Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Linus Torvalds <torvalds@...ux-foundation.org>,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        Thomas Gleixner <tglx@...utronix.de>,
        linux-kernel@...r.kernel.org
Subject: Re: [PATCH printk 3/5] printk: use buffer pool for sprint buffers

On 30/09/2020 15.35, Steven Rostedt wrote:
> On Wed, 30 Sep 2020 10:06:24 +0200
> Rasmus Villemoes <rasmus.villemoes@...vas.dk> wrote:
> 
>> True. But remember that printk is called from _everywhere_, with all
>> sorts of locks held and/or preemption disabled or whatnot, and every
>> cycle spent in printk makes those windows wider. Doubling the cost of
>> every single printk by unconditionally doing vsnprintf() twice is a bad
>> idea.
> 
> But the console output is usually magnitudes more expensive than the
> vsnprintf(), would doing it twice really make a difference?

AFAIU, not every message gets printed to the console directly - syslog(2):

   /proc/sys/kernel/printk
       /proc/sys/kernel/printk is a writable file containing four
integer val‐
       ues that influence kernel printk() behavior when  printing  or
logging
       error messages.  The four values are:

       console_loglevel
              Only  messages  with  a  log level lower than this value
will be
              printed to the console.  The default value  for  this
field  is
              DEFAULT_CONSOLE_LOGLEVEL  (7),  but it is set to 4 if the
kernel
              command line contains the word "quiet",

So the normal state of things is that you don't pay the cost of printing
to the console for all the pr_debug (ok, they may be compiled out or
run-time disabled depending on DYNAMIC_DEBUG etc.), nor info, notice,
warn. For those messages that are not directly written to the console,
the vsnprintf() is a large part of the cost (not exactly half, of
course, so doubling is an exaggeration, but whether it's 70% or 100%
doesn't really matter).

I'm not at all concerned about pr_err and above becoming more expensive,
they are rare. But random drivers are filled with random pr_info in
random contexts - just a small selection from dmesg -x shows these
really important things:

kern  :info  : [ 4631.338105] ax88179_178a 3-13.2.3.3:1.0 eth0: ax88179
- Link status is: 1
kern  :info  : [ 4642.218100] ax88179_178a 3-13.2.3.3:1.0 eth0: ax88179
- Link status is: 0
kern  :info  : [ 4643.882038] ax88179_178a 3-13.2.3.3:1.0 eth0: ax88179
- Link status is: 1
kern  :info  : [ 4667.562011] ax88179_178a 3-13.2.3.3:1.0 eth0: ax88179
- Link status is: 0
...
kern  :info  : [ 9149.215456] [drm] ring test on 1 succeeded in 1 usecs
kern  :info  : [ 9149.215459] [drm] ring test on 2 succeeded in 1 usecs
kern  :info  : [ 9149.215466] [drm] ring test on 3 succeeded in 4 usecs

and if I'm reading the code correctly, the former is even an example of
something that happens in irq context.

Rasmus