svn commit: r222537 - in head/sys: kern sys

[Bruce Evans]

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