lkml.org 
[lkml]   [2008]   [Apr]   [15]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH] PRINTK: Decouple input locking from output locking and move render outside lock
On Tue, 08 Apr 2008 19:01:29 +0100
David Howells <dhowells@redhat.com> wrote:

> Decouple the printk input locking from the output locking using a dual-tailed
> ring buffer, and move the render (vscnprintf) and processing (log level token
> inclusion and timestamp inclusion) outside of the input locked section.
>
> +---------+
> | |
> | vprintk |
> | |
> +---------+ +-----------------+
> | | |
> V +--->| Syslog syscall |
> +---------+ | | |
> | | | +-----------------+
> | Render | |
> | | | +-----------------+
> +---------+ +-------------------+ | | |
> | | Ring buffer | +--->| /proc/kmsg |
> V | +---------------+ | | |
> +---------+ | | syslog queue |---+ +-----------------+
> | | | +---------------+
> | Process |----->| |
> | | | +---------------+
> +---------+ | | console queue |---+ +-----------------+
> | +---------------+ | | |
> | | +--->| Console drivers |
> +-------------------+ | |
> +-----------------+
>
>
> New/renamed global variables:
>
> (*) printk_insertion_point is the point in the ring buffer at which data is
> inserted. It may only be moved if printk_insertion_lock is held.
>
> (*) log_extraction_point is the point in the ring buffer from which data is
> read out by do_syslog(). It may only be moved if log_extraction_lock is
> held.
>
> (*) con_extraction_point is the point in the ring buffer from which data is
> read out to be fed to the console drivers. It may only be moved if
> console_sem is held. No spinlock needs to be held whilst writing to the
> console.
>
> (*) console_anytime is the number of registered drivers that have CON_ANYTIME
> flagged. This avoids the need to walk the console list regularly before
> the CPU is officially online.
>
>
> This patch has the following effects:
>
> (1) vprintk() spends much less time within the insertion critical section.
>
> (2) vprintk() can be filling the buffer whilst do_syslog() and
> release_console_sem are emptying it. Memory barriers are employed to
> prevent out-of-order access between the buffers and the pointers.
>
> (3) Instead of a single render buffer, vprintk() has two render buffers per
> CPU. This allows multiple CPUs to be rendering and processing their
> rendered texts at the same time without the need for this to be within a
> spinlock.
>
> (4) vprintk() first prints the string into the first buffer for that CPU, and
> then post-processes it into the CPU's second buffer to make sure metadata
> is present (log level and timestamp)
>
> As the rendering is done into a temporary buffer rather than a ring
> buffer, the printed output is more likely to get truncated as there's less
> room for metadata. This can be alleviated by increasing the size of the
> processing output buffer.
>
> These render buffers amount to 2KB * NR_CPUS in total instead of 1KB.
>
> (5) The timestamp inserted by vprintk() into a line is the time at which the
> rendered line is processed, not the time it hits the buffer. This means:
>
> (a) all those calls to do_div() and snprintf() are done outside the
> critical section (except for recursion messages), and
>
> (b) lines from different CPUs may appear to be out of order (this can be
> solved by throwing a lock around the processing section, a lock that's
> not printk_insertion_lock).
>
> (6) A partial vprintk() on one CPU (ie: not ending in "\n") will have a
> newline inserted after it if another CPU gets a line in first.
>
> (7) release_console_sem() does not need to take any spinlocks; console_sem is
> probably sufficient locking for talking to console drivers. Although the
> function disables IRQs too, this may be unnecessary, provided the IRQ
> handler doesn't try filling up the ring buffer without being able to empty
> it because someone further up the stack holds console_sem.
>
> (8) vprintk() may have to discard messages under high load:
>
> (a) If the console queue can't be emptied fast enough, new messages are
> discarded wholly or in part. Possibly old messages should be
> discarded instead.
>
> (b) If the syslog queue can't be emptied fast enough, then if vprintk()
> can immediately get the appropriate lock, it will advance the
> extraction point by at least 1024 characters, rounded up to the next
> newline, thus discarding some old messages. Failing that, new
> messages will be discarded wholly or in part instead.
>
>
> Why this patch?
> ===============
>
> We're seeing the kernel spit messages out about CPUs getting stuck on the
> console locks. This appears to be due to I/O errors in a just-disconnected
> iSCSI block device causing lots and lots of printks. The system on which this
> is being seen is a ppc64 system with spinlocks that yield to the hypervisor,
> which I suspect is exacerbating the situation.
>
> This patch attempts to alleviate the situation by shortening the amount of time
> spent in the kernel logging critical sections by breaking up the locking and
> moving out stuff that can be done outside of the critical section.
>
>
> Testing
> =======
>
> I've used my FRV test board (32-bit/BE/UP) firstly to step through the code and
> check the various values with GDB under various cases, and secondly to generate
> a sequence of numbered printks, which I've checked have all been correctly
> displayed, and correctly ordered.
>
> I've also run this up on my x86_64 box with 2 CPUs (64-bit/LE/SMP), checking
> that it correctly handles output from FS-Cache and CacheFiles with full
> debugging output turned on, both in printing to tty and serial consoles and in
> extraction via syslog().
>
> ...
>
> kernel/printk.c | 820 +++++++++++++++++++++++++++++++++++--------------------

geeze, that didn't do much to simplify the printk code :(

Wouldn't it be better to teach the offending iscsi code about
printk_ratelimit()? Because I'd expect that even with this change,
undesirable things will still happen with (say) a serial console?



\
 
 \ /
  Last update: 2008-04-16 01:29    [W:0.031 / U:0.572 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site