Date: Sat, 4 Jun 2011 08:02:29 +1000 (EST) From: Bruce Evans <brde@optusnet.com.au> To: "Kenneth D. Merry" <ken@freebsd.org> Cc: svn-src-head@freebsd.org, svn-src-all@freebsd.org, src-committers@freebsd.org, Andriy Gapon <avg@freebsd.org>, Bruce Evans <brde@optusnet.com.au> Subject: Re: svn commit: r222537 - in head/sys: kern sys Message-ID: <20110604072808.G1143@besplex.bde.org> In-Reply-To: <20110603211107.GA91421@nargothrond.kdm.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>
next in thread | previous in thread | raw e-mail | index | archive | help
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20110604072808.G1143>