RE: LOR: sched lock vs. sio + panic in sched_choose() [ULE + SMP panic]

On Fri, 6 Jun 2003, John Baldwin wrote:

> On 06-Jun-2003 David P. Reese Jr. wrote:
> > I've been getting a lot of these for the last two weeks on my SMP box.
> > This panic is on  -CURRENT from earlier today.  Scheduler is ULE.
> >
> > lock order reversal
> >  1st 0xc047f820 sched lock (sched lock) _at_ /usr/src/sys/kern/kern_intr.c:548
> >  2nd 0xc04b83c0 sio (sio) _at_ /usr/src/sys/dev/sio/sio.c:3242
>
> This is a duplicate panic because you are using a serial console.

However, it seems to be another bug that console output trips on a
LOR.  Console output must work in any context, so it must not use
normal locking.  I have used the following related fixes for a year
or two.  Normal locking is still used, but the non-simple-lock parts
are mostly turned off.  The db_active check makes console output stay
further away from normal locking when in ddb.

%%%
Index: sio.c
===================================================================
RCS file: /home/ncvs/src/sys/dev/sio/sio.c,v
retrieving revision 1.399
diff -u -2 -r1.399 sio.c
--- sio.c	31 May 2003 18:39:29 -0000	1.399
+++ sio.c	6 Jun 2003 23:49:09 -0000
_at__at_ -510,7 +510,7 _at__at_
 	while (sio_inited != 2)
 		if (atomic_cmpset_int(&sio_inited, 0, 1)) {
+			/* XXX might still need MTX_QUIET.*/
 			mtx_init(&sio_lock, sio_driver_name, NULL,
-			    (comconsole != -1) ?
-			    MTX_SPIN | MTX_QUIET : MTX_SPIN);
+				 MTX_SPIN | MTX_NOWITNESS);
 			atomic_store_rel_int(&sio_inited, 2);
 		}
_at__at_ -3239,5 +3239,5 _at__at_
 	s = spltty();
 	need_unlock = 0;
-	if (sio_inited == 2 && !mtx_owned(&sio_lock)) {
+	if (!db_active && sio_inited == 2 && !mtx_owned(&sio_lock)) {
 		mtx_lock_spin(&sio_lock);
 		need_unlock = 1;
%%%

>
> > Stack backtrace:
> > backtrace(c0400378,c04b83c0,c0463120,c0463120,c041266b) at backtrace+0x17
> > witness_lock(c04b83c0,8,c041266b,caa,c11efc00) at witness_lock+0x697
> > _mtx_lock_spin_flags(c04b83c0,0,c041266b,caa,0) at _mtx_lock_spin_flags+0xd1
> > siocnputc(c0463280,d,5,d1d62b68,0) at siocnputc+0x81
> > cnputc(a,ffffffff,1,c0415c53,c) at cnputc+0x56
> > putchar(a,d1d62b68,d1d62ab4,c0491d40,0) at putchar+0xcd
> > kvprintf(c0415c52,c025eba0,d1d62b68,a,d1d62b88) at kvprintf+0x7d
> > printf(c0415c52,c,c0415a4d,c03fe55b,c0489b20) at printf+0x57
>
> This is the real panic below:
>
> > trap_fatal(d1d62c14,38,d1d62bf0,c0236c9d,38) at trap_fatal+0x76
> > trap(d1d60018,c0240010,c0470010,c11dcbe0,c0482280) at trap+0x123
> > calltrap() at calltrap+0x5
> > --- trap 0xc, eip = 0xc0253ec7, esp = 0xd1d62c54, ebp = 0xd1d62c68 ---
> > sched_choose(c11dee40,c03fe7a6,28c,0,c11db668) at sched_choose+0x77
> > choosethread(c11dcbe0,2,c03fdb89,1dc,b6e81bd0) at choosethread+0x36
> > mi_switch(c047f820,0,c03fb1fd,224,c11db5ac) at mi_switch+0x200
> > ithread_loop(c11da180,d1d62d48,c03fb0ae,30c,55ff44fd) at ithread_loop+0x256

ithread_loop() just holds sched_lock in a normal way.  So it seems
that sio console output always (?) hits the LOR if it used when
sched_lock is held.  syscons console output is also broken when
sched_lock is held, but I thought that sio console output was less
broken.

> > fork_exit(c022caf0,c11da180,d1d62d48) at fork_exit+0xc0
> > fork_trampoline() at fork_trampoline+0x1a
> > --- trap 0x1, eip = 0, esp = 0xd1d62d7c, ebp = 0 ---
> >
> >
> > Fatal trap 12: page fault while in kernel mode
> > cpuid = 1; lapic.id = 01000000
> > fault virtual address   = 0x38
> > fault code              = supervisor read, page not present
> > instruction pointer     = 0x8:0xc0253ec7
> > stack pointer           = 0x10:0xd1d62c54
> > frame pointer           = 0x10:0xd1d62c68
> > code segment            = base 0x0, limit 0xfffff, type 0x1b
> >                         = DPL 0, pres 1, def32 1, gran 1
> > processor eflags        = interrupt enabled, resume, IOPL = 0
> > current process         = 14 (swi7: tty:sio clock)
> > kernel: type 12 trap, code=0
> > Stopped at      sched_choose+0x77:      movl    0x38(%eax),%eax

It's interesting that any messages get printed at all after a LOR in
the output routine.  Apparently mtx_owned(sio_lock) becomes true before
the LOR is detected.  Then siocnputc() can work if further output is
done in trap context, sinc sio_lock is already held so siocnputc()
doesn''t aquire it again.  If siocnputc() managed to return, then there
would be more LORs for further output.  But it rarely returns, since
traps here are usually fatal.

Bruce