Re: Seeing lock order reversal

On Tue, Mar 18, 2008 at 08:16:28PM +0100, Attilio Rao wrote:
> 2008/3/18, pluknet <pluknet_at_gmail.com>:
> > On 18/03/2008, Attilio Rao <attilio_at_freebsd.org> wrote:
> >  > 2008/3/18, pluknet <pluknet_at_gmail.com>:
> >  >  >
> >
> > >  >  Thought taking that into account I could obtain a new one yesterday. I
> >  >  >  didn't see this before.
> >  >  >
> >  >  >  Mar 17 03:17:14 pl sudo:  pluknet : TTY=ttyv1 ; PWD=/usr/home/pluknet
> >  >  >  ; USER=root ; COMMAND=/usr/libexec/getty 3wire.9600 ttyd0
> >  >  >  Mar 17 03:17:14 pl kernel: lock order reversal:
> >  >  >  Mar 17 03:17:14 pl kernel: 1st 0xc07e9274 proctree (proctree) _at_
> >  >  >  /usr/src/sys/kern/kern_exit.c:291
> >  >  >  Mar 17 03:17:14 pl kernel: 2nd 0xc2fc49e8 devfs (devfs) _at_
> >  >  >  /usr/src/sys/kern/vfs_subr.c:2158
> >  >
> >  >
> >  > This one seems interesting.
> >  >  Next time you experience it can you please drop in DDB and print-out
> >  >  the correct order revealed by WITNESS?
> >  >
> >
> >
> > Fortunately I could reproduce it.
> >
> >  lock order reversal:
> >
> >  1st 0xc07e9274 proctree (proctree) _at_ /usr/src/sys/kern/kern_exit.c:291
> >
> >  2nd 0xc3c18278 devfs (devfs) _at_ /usr/src/sys/kern/vfs_subr.c:2158
> >  KDB: stack backtrace:
> >  db_trace_self_wrapper(c07682d0,d6078b24,c0573236,c076a615,c3c18278,...)
> >
> > at db_trace_self_wrapper+0x26
> >
> > kdb_backtrace(c076a615,c3c18278,c075bcfb,c075bcfb,c0770a8c,...) at
> >  kdb_backtrace+0x29
> >  witness_checkorder(c3c18278,9,c0770a8c,86e,c07edcd4,...) at
> >  witness_checkorder+0x6d6
> >  _lockmgr_args(c3c18278,20002,c3c182a8,0,ffffffff,...) at _lockmgr_args+0x519
> >  vop_stdlock(d6078bc4,d6078bbc,c0572a1c,20002,c3c182a8,...) at vop_stdlock+0x51
> >  VOP_LOCK1_APV(c07a07e0,d6078bc4,851,d6078be4,c3c182a8,...) at VOP_LOCK1_APV+0xa5
> >  _vn_lock(c3c18220,20002,c0770a8c,86e,4,...) at _vn_lock+0xf2
> >  vrele(c3c18220,0,c07619a2,14e,ffffffff,...) at vrele+0x142
> >  exit1(c2fdd690,0,d6078d2c,c0729ed3,c2fdd690,...) at exit1+0x8a1
> >  sys_exit(c2fdd690,d6078cfc,4,c07625a5,c07a3d38,...) at sys_exit+0x1d
> >  syscall(d6078d38) at syscall+0x2b3
> >  Xint0x80_syscall() at Xint0x80_syscall+0x20
> >  --- syscall (1, FreeBSD ELF32, sys_exit), eip = 0x2811964f, esp =
> >  0xbfbfeacc, ebp = 0xbfbfead8 ---
> >
> >  Something else?
> 
> This is the "2nd order".
> It would be nice to get where these locks are acquired and what is the
> "1st order".
> In order to get it, it is enough to break in DDB and do: show witness
> at DDB prompt.
> 
> Thanks,
> Attilio

The other order comes from the devfs_close. Look at the handling of the
controlling terminal at the start of the function.