lkml.org 
[lkml]   [2020]   [Oct]   [1]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: [PATCH printk 3/5] printk: use buffer pool for sprint buffers
    On Thu 2020-10-01 09:15:39, Rasmus Villemoes wrote:
    > On 30/09/2020 15.35, Steven Rostedt wrote:
    > > On Wed, 30 Sep 2020 10:06:24 +0200
    > > Rasmus Villemoes <rasmus.villemoes@prevas.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.

    As I already wrote. We might optimize this when it causes real
    life problems. And trace_printk() is a better choice for performance
    sensitive debugging.

    Best Regards,
    Petr

    \
     
     \ /
      Last update: 2020-10-01 09:59    [W:3.845 / U:0.020 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site