From owner-svn-src-head@FreeBSD.ORG Fri Jun 3 22:02:35 2011 Return-Path: Delivered-To: svn-src-head@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 15919106566B; Fri, 3 Jun 2011 22:02:35 +0000 (UTC) (envelope-from brde@optusnet.com.au) Received: from mail03.syd.optusnet.com.au (mail03.syd.optusnet.com.au [211.29.132.184]) by mx1.freebsd.org (Postfix) with ESMTP id A181A8FC0A; Fri, 3 Jun 2011 22:02:34 +0000 (UTC) Received: from c122-106-165-191.carlnfd1.nsw.optusnet.com.au (c122-106-165-191.carlnfd1.nsw.optusnet.com.au [122.106.165.191]) by mail03.syd.optusnet.com.au (8.13.1/8.13.1) with ESMTP id p53M2TW9003207 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Sat, 4 Jun 2011 08:02:32 +1000 Date: Sat, 4 Jun 2011 08:02:29 +1000 (EST) From: Bruce Evans X-X-Sender: bde@besplex.bde.org To: "Kenneth D. Merry" In-Reply-To: <20110603211107.GA91421@nargothrond.kdm.org> Message-ID: <20110604072808.G1143@besplex.bde.org> References: <201105311729.p4VHTwrZ033296@svn.freebsd.org> <4DE5D72A.1020405@FreeBSD.org> <20110601193030.A1275@besplex.bde.org> <20110602213611.GA47880@nargothrond.kdm.org> <20110603204653.B1551@besplex.bde.org> <20110603211107.GA91421@nargothrond.kdm.org> MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed Cc: svn-src-head@freebsd.org, svn-src-all@freebsd.org, src-committers@freebsd.org, Andriy Gapon , Bruce Evans Subject: Re: svn commit: r222537 - in head/sys: kern sys X-BeenThere: svn-src-head@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: SVN commit messages for the src tree for head/-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 03 Jun 2011 22:02:35 -0000 On Fri, 3 Jun 2011, Kenneth D. Merry wrote: > On Fri, Jun 03, 2011 at 20:47:00 +1000, Bruce Evans wrote: >> On Thu, 2 Jun 2011, Kenneth D. Merry wrote: >>> That particular solution doesn't lock the normal kernel printf path, and so >>> won't fix what we're trying to fix. (We've got lots of disks in each >>> system, and when there are various SES events and disks arriving and >>> departing, there are multiple kernel contexts doing printfs simultaneously, >>> and that results in scrambled dmesg output.) >> >> But it does. PRINTF_BUFR_SIZE (at least used to) only be applied to >> vprintf(), but my printf_lock() is applied to all calls to kvprintf() >> that set TOLOG. (If I missed some, this takes 2 lines each to fix.) >> ... > > Ahh. It wasn't 100% clear from looking at the patch which calls had the > lock applied. In this case at least, it's skipping the lock when the > priority is -1. Is this tprintf()? > > % /* > % * Warn that a system table is full. > % @@ -198,5 +221,9 @@ > % pca.flags = flags; > % va_start(ap, fmt); > % + if (pri != -1) > % + printf_lock(); /* To serialize msgbuf. XXX: long-held > lock? */ > % kvprintf(fmt, putchar, &pca, 10, ap); > % + if (pri != -1) > % + printf_unlock(); > % va_end(ap); > % if (sess != NULL) > % Hmm. -1 means `not TOLOG' (see earlier in tprintf()), and I only apply printf_lock() if the output is kernel-only _or_ uses TOLOG (cases that go TOTTY only might need some serialization, but they can probably block and I don't want to apply the low-level printf_lock() to them). Only tprintf() has this magic -1 priority, and this magic never used, at least in the FreeBSD /sys tree and matching '[^a-z]tprintf('. There are just 4 calls to tprintf(), and they are all related to nfs and all use pri = LOG_INFO. So tprintf() always goes TOLOG in practice. uprintf() is relatively popular, and never goes TOLOG. The only obvious difference between uprintf() and tprintf() with pri -1 is that the former users curthread->td_proc while the latter takes a proc pointer. The proc pointer is constructed from a thread pointer passed around by nfs so I can't see what it is, but I bet it is always curthread->td_proc or perhaps NULL. If it is NULL, then tprintf() doesn't print to a tty and reduces to a buggy version of log() if pri != -1 (log() goes TOCONS if !log_open, while the reduced tprintf() always goes TOLOG); if pri == -1, then tprintf() prints nowhere (and hopefully doesn't get confused doing this). >> ... >> Apart from this, I don't know any reason why a printf or even a msgbuf >> write can't wait for a while (a very long while if the output is to a >> slow device -- don't forget to test with a 50 bps serial console) until >> any previous printfs complete. My simple serialization gives this if >> the other printfs are on other CPUs, and possibly if they are on other >> ithreads (the simple serialization doesn't give up control for simplicity, >> since it is hard to tell when it is safe to give up control, but >> preemption while we are spinning might get back to the other printfs). >> And when the printf is recursive, there is no way back to the other >> printfs, so we must proceed. We could proceed immediately, but my >> simple serialization waits in this case too for simplicity. This case >> should be even rarer than waiting too long for another CPU. > > Hopefully the delay won't be too bad for most consumers. It'll take some > testing to see what happens. Certainly the cases of TOLOG only, and TOCONS to a synchronous console, will be very fast. > I'll try to get some time to run some tests with your locking code and see > how it works. It will be good to test on a bigger system that actually needs lots of kernel printfs. Bruce