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
_______________________________________________
svn-src-all@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/svn-src-all
To unsubscribe, send any mail to "svn-src-all-unsubscr...@freebsd.org"
