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.villem...@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
