WITNESS observes 2 LORs on Boot of Release 10.1

From: Ellis H. Wilson III <ellisw_at_panasas.com>
Date: Tue, 18 Nov 2014 15:19:31 -0500
Hi all,

I'm observing the following two WITNESS LORs being thrown upon boot-up 
of 10.0 and I was tracking current, hoping they would go away by 10.1, 
but it seems they persist as shown below.  I suspect this is because 
current is being built with WITNESS on but also with SKIPSPIN on.  So 
these issues are unlikely to show up for any devs but those who 
specifically enable WITNESS and disable SKIPSPIN like myself.  At my 
work we would greatly like to do our debugging with checking of 
spin-locking order included and panicing upon LOR detection.  That's not 
possible with these in existence.

Specifically:

<snip>
Event timer "RTC" frequency 32768 Hz quality 0
ppc0: cannot reserve I/O port range
Timecounters tick every 10.000 msec
pcm0: measured ac97 link rate at 29212 Hz
lock order reversal:
lock order reversal:
  1st 0xffffffff8177a1a0 entropy harvest mutex (entropy harvest mutex) _at_ 
/usr/src/sys/dev/random/random_harvestq.c:198
  2nd 0xffffffff81475108 scrlock (scrlock) _at_ 
/usr/src/sys/dev/syscons/syscons.c:2694
KDB: stack backtrace:
#0 0xffffffff8092f020 at kdb_backtrace+0x60
#1 0xffffffff80944204 at witness_checkorder+0xc04
#2 0xffffffff808e6d5e at __mtx_lock_spin_flags+0x4e
#3 0xffffffff80738b80 at sc_puts+0xb0
#4 0xffffffff8073c4e5 at sc_cnputc+0xe5
#5 0xffffffff808b6cf0 at cnputc+0x80
#6 0xffffffff808b6fa8 at cnputs+0x58
#7 0xffffffff80934011 at putchar+0x151
#8 0xffffffff80932c36 at kvprintf+0xf6
#9 0xffffffff809344ad at _vprintf+0x8d
#10 0xffffffff809346c3 at printf+0x53
#11 0xffffffff80943fe0 at witness_checkorder+0x9e0
#12 0xffffffff808e6d5e at __mtx_lock_spin_flags+0x4e
#13 0xffffffff8090019b at msleep_spin_sbt+0x5b
#14 0xffffffff80698198 at random_kthread+0x78
#15 0xffffffff808cd941 at fork_exit+0x71
#16 0xffffffff80caee7e at fork_trampoline+0xe
  1st 0xffffffff8177a1a0 entropy harvest mutex (entropy harvest mutex) _at_ 
/usr/src/sys/dev/random/random_harvestq.c:198
  2nd 0xffffffff81568390 sleepq chain (sleepq chain) _at_ 
/usr/src/sys/kern/subr_sleepqueue.c:237
KDB: stack backtrace:
#0 0xffffffff8092f020 at kdb_backtrace+0x60
#1 0xffffffff80944204 at witness_checkorder+0xc04
#2 0xffffffff808e6d5e at __mtx_lock_spin_flags+0x4e
#3 0xffffffff8090019b at msleep_spin_sbt+0x5b
#4 0xffffffff80698198 at random_kthread+0x78
#5 0xffffffff808cd941 at fork_exit+0x71
#6 0xffffffff80caee7e at fork_trampoline+0xe
usbus0: 12Mbps Full Speed USB v1.0
ugen0.1: <Apple> at usbus0
uhub0: <Apple OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0
ada0 at ata0 bus 0 scbus0 target 0 lun 0
ada0: <VBOX HARDDISK 1.0> ATA-6 device
<snip>

This is on a virtual machine via VirtualBox, but we have reproduced it 
on real hardware.  Regarding the latter reversal, I have dug in the code 
and see the calls go about in the following order:

In sys/dev/random/random_harvestq.c:
  198 mtx_lock_spin(&harvest_mtx);
  209 msleep_spin_sbt(&random_kthread_control, &harvest_mtx,
Now in sys/kern/kern_synch.c:
  297 sleepq_lock(ident);
Now in sys/kern/subr_sleepqueue.c
  237 mtx_lock_spin(&sc->sc_lock);

The above line numbers might be a hair off from head since I'm looking 
at code synced last week.

I'm happy to open a bug on this if that's the desirable course of 
action, or to even assist in fixing it, but I wanted to first see if 
anybody knew about these already (they didn't show up on the known LORs 
list on quick perusal) or if this was simply a case of WITNESS being 
overly conservative and throwing false positives.  If this belongs on a 
different list just let me know.

Thanks!

ellis
Received on Tue Nov 18 2014 - 19:35:58 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:54 UTC