Lock order reversal errors during boot

Sun May 15 05:43:51 UTC 2016

Greetings,

My first post here so please be gentle.

I am seeing 'lock order reversal' errors during boot on 11-CURRENT - 
r298793.  A sample error:

lock order reversal:
  1st 0xfffff8011280d068 ufs (ufs) @ /usr/src/sys/kern/vfs_subr.c:2498
  2nd 0xfffffe01ca539400 bufwait (bufwait) @ 
/usr/src/sys/ufs/ffs/ffs_vnops.c:263
  3rd 0xfffff80112a23b78 ufs (ufs) @ /usr/src/sys/kern/vfs_subr.c:2498
stack backtrace:
#0 0xffffffff80a94bf0 at witness_debugger+0x70
#1 0xffffffff80a94ae4 at witness_checkorder+0xe54
#2 0xffffffff80a0fdd6 at __lockmgr_args+0x4d6
#3 0xffffffff80ce9626 at ffs_lock+0xa6
[...snip...]

I'm not sure if this is even something I should report, but better safe 
than sorry, yes?

I'm attaching the full dmesg for more information.

Sincerely,

Will Brokenbourgh

-------------- next part --------------
Copyright (c) 1992-2016 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
	The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 11.0-CURRENT #0 r298793: Fri Apr 29 20:48:00 UTC 2016
    root at releng2.nyi.freebsd.org:/usr/obj/usr/src/sys/GENERIC amd64
FreeBSD clang version 3.8.0 (tags/RELEASE_380/final 262564) (based on LLVM 3.8.0)
WARNING: WITNESS option enabled, expect reduced performance.
VT(vga): resolution 640x480
CPU: Intel(R) Core(TM) i5-4590 CPU @ 3.30GHz (3300.06-MHz K8-class CPU)
  Origin="GenuineIntel"  Id=0x306c3  Family=0x6  Model=0x3c  Stepping=3
  Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
  Features2=0x7ffafbff<SSE3,PCLMULQDQ,DTES64,MON,DS_CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,TSCDLT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND>
  AMD Features=0x2c100800<SYSCALL,NX,Page1GB,RDTSCP,LM>
  AMD Features2=0x21<LAHF,ABM>
  Structured Extended Features=0x27ab<FSGSBASE,TSCADJ,BMI1,AVX2,SMEP,BMI2,ERMS,INVPCID,NFPUSG>
  XSAVE Features=0x1<XSAVEOPT>
  VT-x: PAT,HLT,MTF,PAUSE,EPT,UG,VPID
  TSC: P-state invariant, performance statistics
real memory  = 8589934592 (8192 MB)
avail memory = 7625789440 (7272 MB)
Event timer "LAPIC" quality 600
ACPI APIC Table: <ALASKA A M I>
FreeBSD/SMP: Multiprocessor System Detected: 4 CPUs
FreeBSD/SMP: 1 package(s) x 4 core(s)
random: unblocking device.
ioapic0 <Version 2.0> irqs 0-23 on motherboard
random: entropy device external interface
kbd1 at kbdmux0
netmap: loaded module
module_register_init: MOD_LOAD (vesa, 0xffffffff80f10fb0, 0) error 19
random: registering fast source Intel Secure Key RNG
random: fast provider: "Intel Secure Key RNG"
vtvga0: <VT VGA driver> on motherboard
cryptosoft0: <software crypto> on motherboard
acpi0: <ALASKA A M I> on motherboard
acpi0: Power Button (fixed)
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
cpu2: <ACPI CPU> on acpi0
cpu3: <ACPI CPU> on acpi0
hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on acpi0
Timecounter "HPET" frequency 14318180 Hz quality 950
Event timer "HPET" frequency 14318180 Hz quality 550
Event timer "HPET1" frequency 14318180 Hz quality 440
Event timer "HPET2" frequency 14318180 Hz quality 440
Event timer "HPET3" frequency 14318180 Hz quality 440
Event timer "HPET4" frequency 14318180 Hz quality 440
atrtc0: <AT realtime clock> port 0x70-0x77 irq 8 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
attimer0: <AT timer> port 0x40-0x43,0x50-0x53 irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1808-0x180b on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
vgapci0: <VGA-compatible display> port 0xf000-0xf03f mem 0xf7800000-0xf7bfffff,0xe0000000-0xefffffff irq 16 at device 2.0 on pci0
vgapci0: Boot video device
hdac0: <Intel Haswell HDA Controller> mem 0xf7d04000-0xf7d07fff irq 16 at device 3.0 on pci0
pci0: <simple comms> at device 22.0 (no driver attached)
ehci0: <Intel Wildcat Point USB 2.0 controller USB-B> mem 0xf7d0b000-0xf7d0b3ff irq 16 at device 26.0 on pci0
usbus0: EHCI version 1.0
usbus0 on ehci0
hdac1: <Intel Wildcat Point HDA Controller> mem 0xf7d00000-0xf7d03fff irq 22 at device 27.0 on pci0
pcib1: <ACPI PCI-PCI bridge> irq 16 at device 28.0 on pci0
pci1: <ACPI PCI bus> on pcib1
pcib2: <ACPI PCI-PCI bridge> irq 18 at device 28.2 on pci0
pci2: <ACPI PCI bus> on pcib2
re0: <RealTek 8168/8111 B/C/CP/D/DP/E/F/G PCIe Gigabit Ethernet> port 0xe000-0xe0ff mem 0xf7c00000-0xf7c00fff,0xf0000000-0xf0003fff irq 18 at device 0.0 on pci2
re0: Using 1 MSI-X message
re0: ASPM disabled
re0: Chip rev. 0x4c000000
re0: MAC rev. 0x00000000
miibus0: <MII bus> on re0
rgephy0: <RTL8251 1000BASE-T media interface> PHY 1 on miibus0
rgephy0:  none, 10baseT, 10baseT-FDX, 10baseT-FDX-flow, 100baseTX, 100baseTX-FDX, 100baseTX-FDX-flow, 1000baseT-FDX, 1000baseT-FDX-master, 1000baseT-FDX-flow, 1000baseT-FDX-flow-master, auto, auto-flow
re0: Using defaults for TSO: 65518/35/2048
re0: Ethernet address: 40:8d:5c:38:04:9d
re0: netmap queues/slots: TX 1/256, RX 1/256
pcib3: <ACPI PCI-PCI bridge> irq 19 at device 28.3 on pci0
pci3: <ACPI PCI bus> on pcib3
pcib4: <ACPI PCI-PCI bridge> irq 19 at device 0.0 on pci3
pci4: <ACPI PCI bus> on pcib4
ehci1: <Intel Wildcat Point USB 2.0 controller USB-A> mem 0xf7d0a000-0xf7d0a3ff irq 23 at device 29.0 on pci0
usbus1: EHCI version 1.0
usbus1 on ehci1
isab0: <PCI-ISA bridge> at device 31.0 on pci0
isa0: <ISA bus> on isab0
ahci0: <Intel Wildcat Point AHCI SATA controller> port 0xf0b0-0xf0b7,0xf0a0-0xf0a3,0xf090-0xf097,0xf080-0xf083,0xf060-0xf07f mem 0xf7d09000-0xf7d097ff irq 19 at device 31.2 on pci0
ahci0: AHCI v1.30 with 6 6Gbps ports, Port Multiplier not supported
ahcich0: <AHCI channel> at channel 0 on ahci0
ahcich1: <AHCI channel> at channel 1 on ahci0
ahcich2: <AHCI channel> at channel 2 on ahci0
ahciem0: <AHCI enclosure management bridge> on ahci0
acpi_button0: <Power Button> on acpi0
acpi_button1: <Sleep Button> on acpi0
acpi_tz0: <Thermal Zone> on acpi0
acpi_tz1: <Thermal Zone> on acpi0
uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
ppc1: <Parallel port> port 0x378-0x37f irq 5 on acpi0
ppc1: Generic chipset (NIBBLE-only) in COMPATIBLE mode
ppbus0: <Parallel port bus> on ppc1
lpt0: <Printer> on ppbus0
lpt0: Interrupt-driven port
ppi0: <Parallel I/O> on ppbus0
atkbdc0: <Keyboard controller (i8042)> at port 0x60,0x64 on isa0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
ppc0: cannot reserve I/O port range
est0: <Enhanced SpeedStep Frequency Control> on cpu0
est1: <Enhanced SpeedStep Frequency Control> on cpu1
est2: <Enhanced SpeedStep Frequency Control> on cpu2
est3: <Enhanced SpeedStep Frequency Control> on cpu3
fuse-freebsd: version 0.4.4, FUSE ABI 7.8
Timecounters tick every 1.000 msec
hdacc0: <Intel Haswell HDA CODEC> at cad 0 on hdac0
hdaa0: <Intel Haswell Audio Function Group> at nid 1 on hdacc0
pcm0: <Intel Haswell (HDMI/DP 8ch)> at nid 3 on hdaa0
hdacc1: <Realtek ALC892 HDA CODEC> at cad 2 on hdac1
hdaa1: <Realtek ALC892 Audio Function Group> at nid 1 on hdacc1
pcm1: <Realtek ALC892 (Rear Analog 7.1/2.0)> at nid 20,22,21,23 and 24,26 on hdaa1
pcm2: <Realtek ALC892 (Front Analog)> at nid 27 and 25 on hdaa1
pcm3: <Realtek ALC892 (Onboard Digital)> at nid 17 on hdaa1
usbus0: 480Mbps High Speed USB v2.0
usbus1: 480Mbps High Speed USB v2.0
ugen0.1: <Intel> at usbus0
uhub0: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus0
ugen1.1: <Intel> at usbus1
uhub1: <Intel EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus1
ses0 at ahciem0 bus 0 scbus3 target 0 lun 0
ses0: <AHCI SGPIO Enclosure 1.00 0001> SEMB S-E-S 2.00 device
ses0: SEMB SES Device
ada0 at ahcich0 bus 0 scbus0 target 0 lun 0
ada0: <WDC WD10EZEX-00BN5A0 01.01A01> ACS-2 ATA SATA 3.x device
ada0: Serial Number WD-WCC3F4JE4Z03
ada0: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
ada0: Command Queueing enabled
ada0: 953869MB (1953525168 512 byte sectors)
ada1 at ahcich1 bus 0 scbus1 target 0 lun 0
ada1: <ST3000DM001-1CH166 CC29> ACS-2 ATA SATA 3.x device
ada1: Serial Number Z1F5AEVR
ada1: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
ada1: Command Queueing enabled
ada1: 2861588MB (5860533168 512 byte sectors)
ada1: quirks=0x1<4K>
ada2 at ahcich2 bus 0 scbus2 target 0 lun 0
ada2: <WDC WD2003FZEX-00Z4SA0 01.01A01> ACS-2 ATA SATA 3.x device
ada2: Serial Number WD-WMC5C0D31YJ5
ada2: 600.000MB/s transfers (SATA 3.x, UDMA6, PIO 8192bytes)
ada2: Command Queueing enabled
ada2: 1907729MB (3907029168 512 byte sectors)
ada2: quirks=0x1<4K>
SMP: AP CPU #2 Launched!
SMP: AP CPU #3 Launched!
SMP: AP CPU #1 Launched!
Timecounter "TSC-low" frequency 1650032242 Hz quality 1000
WARNING: WITNESS option enabled, expect reduced performance.
Trying to mount root from ufs:/dev/ada2p2 [rw,noatime]...
uhub1: 2 ports with 2 removable, self powered
uhub0: 2 ports with 2 removable, self powered
ugen0.2: <vendor 0x8087> at usbus0
uhub2: <vendor 0x8087 product 0x8009, class 9/0, rev 2.00/0.00, addr 2> on usbus0
ugen1.2: <vendor 0x8087> at usbus1
uhub3: <vendor 0x8087 product 0x8001, class 9/0, rev 2.00/0.00, addr 2> on usbus1
uhub2: 6 ports with 6 removable, self powered
uhub3: 8 ports with 8 removable, self powered
ugen0.3: <Chicony> at usbus0
ukbd0: <Chicony USB Keyboard, class 0/0, rev 2.00/1.44, addr 3> on usbus0
kbd2 at ukbd0
re0: link state changed to DOWN
ugen0.4: <Primax> at usbus0
ugen1.3: <Amazon> at usbus1
umass0: <Mass Storage> on usbus1
umass0:  SCSI over Bulk-Only; quirks = 0x0100
umass0:4:0: Attached to scbus4
da0 at umass-sim0 bus 0 scbus4 target 0 lun 0
da0: <Kindle Internal Storage 0100> Removable Direct Access SCSI-2 device
da0: 40.000MB/s transfers
da0: 1390MB (2846720 512 byte sectors)
da0: quirks=0x2<NO_6_BYTE>
ugen0.5: <vendor 0x05e3> at usbus0
umass1: <vendor 0x05e3 USB Storage, class 0/0, rev 2.00/9.03, addr 5> on usbus0
umass1:  SCSI over Bulk-Only; quirks = 0xc100
umass1:5:1: Attached to scbus5
(probe0:umass-sim1:1:0:0): REPORT LUNS. CDB: a0 00 00 00 00 00 00 00 00 10 00 00 
(probe0:umass-sim1:1:0:0): CAM status: SCSI Status Error
(probe0:umass-sim1:1:0:0): SCSI status: Check Condition
(probe0:umass-sim1:1:0:0): SCSI sense: NOT READY asc:3a,0 (Medium not present)
(probe0:umass-sim1:1:0:0): Error 6, Unretryable error
da1 at umass-sim1 bus 1 scbus5 target 0 lun 0
da1: <Generic STORAGE DEVICE 0903> Removable Direct Access SPC-4 SCSI device
da1: Serial Number 000000000903
da1: 40.000MB/s transfers
da1: Attempt to query device size failed: NOT READY, Medium not present
da1: quirks=0x3<NO_SYNC_CACHE,NO_6_BYTE>
ums0: <Primax Kensington Eagle Trackball, class 0/0, rev 2.00/6.00, addr 4> on usbus0
ums0: 3 buttons and [XYZT] coordinates ID=0
KLD vboxnetflt.ko: depends on kernel - not available or version mismatch
linker_load_file: Unsupported file type
re0: link state changed to UP
info: [drm] Initialized drm 1.1.0 20060810
drmn0: <Intel Haswell (GT2 desktop)> on vgapci0
info: [drm] Memory usable by graphics device = 2048M
info: [drm] MTRR allocation failed.  Graphics performance may suffer.
iicbus0: <Philips I2C bus>error: [drm:pid738:i915_write32] *ERROR* Unknown unclaimed register before writing to c5100
 on iicbb0 addr 0xff
iic0: <I2C generic I/O> on iicbus0
iic1: <I2C generic I/O> on iicbus1
iicbus2: <Philips I2C bus> on iicbb1 addr 0x0
iic2: <I2C generic I/O> on iicbus2
iic3: <I2C generic I/O> on iicbus3
iicbus4: <Philips I2C bus> on iicbb2 addr 0x0
iic4: <I2C generic I/O> on iicbus4
iic5: <I2C generic I/O> on iicbus5
iicbus6: <Philips I2C bus> on iicbb3 addr 0x0
iic6: <I2C generic I/O> on iicbus6
iic7: <I2C generic I/O> on iicbus7
iicbus8: <Philips I2C bus> on iicbb4 addr 0x0
iic8: <I2C generic I/O> on iicbus8
iic9: <I2C generic I/O> on iicbus9
iicbus10: <Philips I2C bus> on iicbb5 addr 0x0
iic10: <I2C generic I/O> on iicbus10
iic11: <I2C generic I/O> on iicbus11
info: [drm] MSI enabled 1 message(s)
info: [drm] Supports vblank timestamp caching Rev 1 (10.10.2010).
info: [drm] Driver supports precise vblank timestamp query.
drmn0: taking over the fictitious range 0xe0000000-0xf0000000
info: [drm] Connector VGA-1: get mode from tunables:
info: [drm]   - kern.vt.fb.modes.VGA-1
info: [drm]   - kern.vt.fb.default_mode
info: [drm] Connector HDMI-A-1: get mode from tunables:
info: [drm]   - kern.vt.fb.modes.HDMI-A-1
info: [drm]   - kern.vt.fb.default_mode
info: [drm] Connector DP-1: get mode from tunables:
info: [drm]   - kern.vt.fb.modes.DP-1
info: [drm]   - kern.vt.fb.default_mode
info: [drm] Connector HDMI-A-2: get mode from tunables:
info: [drm]   - kern.vt.fb.modes.HDMI-A-2
info: [drm]   - kern.vt.fb.default_mode
info: [drm] Connector DP-2: get mode from tunables:
info: [drm]   - kern.vt.fb.modes.DP-2
info: [drm]   - kern.vt.fb.default_mode
fbd0 on drmn0
VT: Replacing driver "vga" with new "fb".
drmn0: More than 8 outputs detected
info: [drm] Initialized i915 1.6.0 20080730 for drmn0 on minor 0
info: [drm] Enabling RC6 states: RC6 on, RC6p off, RC6pp off
lock order reversal:
 1st 0xfffffe01ca577980 bufwait (bufwait) @ /usr/src/sys/kern/vfs_bio.c:3512
 2nd 0xfffff80030227200 dirhash (dirhash) @ /usr/src/sys/ufs/ufs/ufs_dirhash.c:281
stack backtrace:
#0 0xffffffff80a94bf0 at witness_debugger+0x70
#1 0xffffffff80a94ae4 at witness_checkorder+0xe54
#2 0xffffffff80a3fc22 at _sx_xlock+0x72
#3 0xffffffff80cee9bd at ufsdirhash_add+0x3d
#4 0xffffffff80cf1785 at ufs_direnter+0x4c5
#5 0xffffffff80cfac29 at ufs_makeinode+0x5e9
#6 0xffffffff80cf67c3 at ufs_create+0x33
#7 0xffffffff80feeb71 at VOP_CREATE_APV+0xf1
#8 0xffffffff80b04748 at vn_open_cred+0x2f8
#9 0xffffffff80afdafc at kern_openat+0x25c
#10 0xffffffff80e98f5b at amd64_syscall+0x2db
#11 0xffffffff80e7823b at Xfast_syscall+0xfb
lock order reversal:
 1st 0xfffff80007c5a8e0 filedesc structure (filedesc structure) @ /usr/src/sys/kern/kern_descrip.c:1231
 2nd 0xfffff80090cfc068 ufs (ufs) @ /usr/src/sys/kern/vfs_subr.c:4829
stack backtrace:
#0 0xffffffff80a94bf0 at witness_debugger+0x70
#1 0xffffffff80a94ae4 at witness_checkorder+0xe54
#2 0xffffffff80a0fdd6 at __lockmgr_args+0x4d6
#3 0xffffffff80ce9626 at ffs_lock+0xa6
#4 0xffffffff80ff1110 at VOP_LOCK1_APV+0x100
#5 0xffffffff80b04efa at _vn_lock+0x9a
#6 0xffffffff809f0c6e at knlist_remove_kq+0x7e
#7 0xffffffff80afbbe8 at filt_vfsdetach+0x28
#8 0xffffffff809f1537 at knote_fdclose+0xc7
#9 0xffffffff809e5225 at closefp+0x65
#10 0xffffffff80e98f5b at amd64_syscall+0x2db
#11 0xffffffff80e7823b at Xfast_syscall+0xfb
lock order reversal:
 1st 0xfffff8011280d068 ufs (ufs) @ /usr/src/sys/kern/vfs_subr.c:2498
 2nd 0xfffffe01ca539400 bufwait (bufwait) @ /usr/src/sys/ufs/ffs/ffs_vnops.c:263
 3rd 0xfffff80112a23b78 ufs (ufs) @ /usr/src/sys/kern/vfs_subr.c:2498
stack backtrace:
#0 0xffffffff80a94bf0 at witness_debugger+0x70
#1 0xffffffff80a94ae4 at witness_checkorder+0xe54
#2 0xffffffff80a0fdd6 at __lockmgr_args+0x4d6
#3 0xffffffff80ce9626 at ffs_lock+0xa6
#4 0xffffffff80ff1110 at VOP_LOCK1_APV+0x100
#5 0xffffffff80b04efa at _vn_lock+0x9a
#6 0xffffffff80af5533 at vget+0x63
#7 0xffffffff80ae7efc at vfs_hash_get+0xcc
#8 0xffffffff80ce4cb0 at ffs_vgetf+0x40
#9 0xffffffff80cdc5a1 at softdep_sync_buf+0xb51
#10 0xffffffff80cea216 at ffs_syncvnode+0x256
#11 0xffffffff80cc0915 at ffs_truncate+0x8f5
#12 0xffffffff80cf190f at ufs_direnter+0x64f
#13 0xffffffff80cfac29 at ufs_makeinode+0x5e9
#14 0xffffffff80cf67c3 at ufs_create+0x33
#15 0xffffffff80feeb71 at VOP_CREATE_APV+0xf1
#16 0xffffffff80b04748 at vn_open_cred+0x2f8
#17 0xffffffff80afdafc at kern_openat+0x25c