From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753246Ab1G0CLh (ORCPT ); Tue, 26 Jul 2011 22:11:37 -0400 Received: from lemon.ertos.nicta.com.au ([203.143.174.143]:45773 "EHLO lemon.ken.nicta.com.au" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752102Ab1G0CLe (ORCPT ); Tue, 26 Jul 2011 22:11:34 -0400 Date: Wed, 27 Jul 2011 12:11:05 +1000 Message-ID: From: Peter Chubb To: Peter Zijlstra Cc: Peter Chubb , akpm@linux-foundation.org, torvalds@linux-foundation.org, linux-kernel@vger.kernel.org In-Reply-To: <1311696094.24752.98.camel@twins> References: <1311696094.24752.98.camel@twins> User-Agent: Wanderlust/2.15.9 (Almost Unreal) SEMI/1.14.6 (Maruoka) FLIM/1.14.9 (=?UTF-8?B?R29qxY0=?=) APEL/10.8 Emacs/23.3 (x86_64-pc-linux-gnu) MULE/6.0 (HANACHIRUSATO) X-Face: GgFg(Z>fx((4\32hvXq<)|jndSniCH~~$D)Ka:P@e@JR1P%Vr}EwUdfwf-4j\rUs#JR{'h# !]])6%Jh~b$VA|ALhnpPiHu[-x~@<"@Iv&|%R)Fq[[,(&Z'O)Q)xCqe1\M[F8#9l8~}#u$S$Rm`S9% \'T@`:&8>Sb*c5d'=eDYI&GF`+t[LfDH="MP5rwOO]w>ALi7'=QJHz&y&C&TE_3j! Organization: National ICT Australia MIME-Version: 1.0 (generated by SEMI 1.14.6 - "Maruoka") Content-Type: text/plain; charset=US-ASCII X-SA-Exim-Connect-IP: 2402:1800:4000:2:21d:e0ff:fe35:2bed X-SA-Exim-Mail-From: peter.chubb@nicta.com.au Subject: Re: klogd dies, possible emit_log_char() vs do_syslog(..READ..) race. X-SA-Exim-Version: 4.2.1 (built Wed, 25 Jun 2008 17:20:11 +0000) X-SA-Exim-Scanned: Yes (on lemon.ken.nicta.com.au) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org >>>>> "Peter" == Peter Zijlstra writes: Peter> On Tue, 2011-07-26 at 11:08 +1000, Peter Chubb wrote: >> Hi, >> >> Since mid May, my klogd has been turning into a 100% CPU hog at >> regular intervals. Turns out that sometimes reads from /proc/kmsg >> return with zero bytes read --- pointing to a race between >> do_syslog(SYSLOG_ACTION_READ...) and emit_log_char(). (In Debian, >> klogd is invoked with a dd frontend, as dd if=/proc/kmsg >> of=/var/run/klogd bs=1 where /var/run/klogd is a named pipe; this >> dd dies when it reads zero bytes). Peter> Well I suppose that's a bug anyway since if someone managed to Peter> have multiple consumers of the data you'll get into that same Peter> situation, therefore using dd might not be the sanest thing to Peter> do. Indeed -- and this *is* the case on my system (somehow, rsyslogd and klogd were both installed). Peter> Suppose someone does cat /proc/kmsg > /dev/null, just for kicks Peter> ;-) They'd have to be privileged in some way to do that. Peter> Well there is a distinct lack of serialization between the Peter> log_start, log_end usage in wait_event_interruptible() and Peter> emit_log_char(). Peter> From what I can see one has to hold the logbuf_lock to get a Peter> stable reading, so if the code in SYSLOG_ACTION_READ requires Peter> this for proper functioning its buggy. You don't need a stable reading -- you just need to be assured that there's something there to read. And if there are multiple readers all bets are off -- in the (usual) single reader case, the count of things in the buffer should only increase, not decrease, during the race. Peter> That said, this is the very first time I ever looked at that Peter> code ;-) Yes there's no maintainer listed for kernel/printk.c --- I emailed you because you were the last to touch something in that file, so I thought that the code should be in your head at least a little bit :-) Peter> Does something like the (completely untested) patch below also Peter> cure things? Nope. There's still room for something to happen between the wakeup and the test. I'm beginning to think my ugly band-aid is the correct patch! -- Dr Peter Chubb http://www.gelato.unsw.edu.au peterc AT gelato.unsw.edu.au http://www.ertos.nicta.com.au ERTOS within National ICT Australia