Why does printf(9) hang network?

[dieterbsd at engineer.com]

Robert writes:
>> Why would doing a printf(9) in a device driver (usb, firewire, 
probably
>> others) cause an obscenely long lockout on
>> /usr/src/sys/kern/uipc_sockbuf.c:148 (sx:so_rcv_sx)  ?
>>
>> Printf(9) alone isn't the problem, adding printfs to chown(2) does 
not
>> cause the problem, but printfs from device drivers do.
>>
>> Grep says that uipc_sockbuf.c is the only file that locks/unlocks 
sb_sx.
>> The device drivers and printf don't even know that sb_sx exists.
>
> I can't speak to the details of your situation, but one possible
> explanation might be: printf runs at the speed of the console, which 
for
> serious consoles can be extremely slowly.

But shouldn't the RS-232 driver just fill up the UART's FIFO and then 
sleep?
Why can't the network code run while the RS-232 driver sleeps?  Actually
this must be happening in the call-printf-from-chown case.  There must 
be
something different when printf is called from a device driver.

> Device driver interrupt threads can preempt other threads,
> possibly while those threads hold locks.  That causes them to hold
> the locks for much longer, as the threads may not get rescheduled for 
some
> period (for example, until the device driver is done doing a printf),

If the CPU is mostly idle, shouldn't the network thread get scheduled 
right
away?

> leading
> other threads waiting for that lock to wait significantly longer.
> Especially the case if the other thread was spinning adaptively, in 
which
> case it will then yield since the holder of the lock effectively 
yielded.

My head is spinning attempting to understand this...

> You might try forcing all the various threads to run on different CPUs
> using cpuset and see if the variance goes down.

Uniprocessor

> You can also use KTR + schedgraph
> to explore the specific scheduling going on, although be aware that 
KTR
> can also noticeably perturb schediling itself.

Scheduling?  The CPU can be mostly idle and the problem still happens.

> In general, things shouldn't call kernel printf in steady state 
operation;
> if  they need to log something, they should use log(9) or similar.  
printf
> is primarily a tool for printing out device probe information, and for
> debugging purposes: it is not intended to be fast.

Sounds fine to me.  Is there a consensus on this?  If so, does this 
need to
go into some developer's handbook?  How do we get developers to fix the
existing code?