thr3ads.net - freebsd stable - Help debugging stable/10 [Jun 2015]

If this information is useful, please help other people find it:
Share via:

Shane Ambler

2015-Mar-23 15:25 UTC

Help debugging stable/10

On 25/12/2014 23:03, Andriy Gapon wrote:> On 25/12/2014 11:29, Hans Petter Selasky wrote:
>> The cam_sim_free() is stuck, blocking the rest of that controller from
>> enumerating. It might look like a non-USB stack issue.
>>
>> MAV: Do you have some ideas where to start looking, now we have a dump?
Any
>> refcounts to check in particular?
>
> Apparently sim->refcount > 0.
> Not sure how to check who has the reference(s).
>
I am now running
FreeBSD leader.local 10.1-STABLE FreeBSD 10.1-STABLE #4 r279865: Thu
Mar 12 14:25:28 ACDT 2015     root at leader.local:/usr/obj/usr/src/sys
/GENERIC  amd64

I have just tried running with a custom kernel, GENERIC plus DDB GDB
DEADLKRES INVARIANTS INVARIANT_SUPPORT WITNESS WITNESS_SKIPSPIN

When starting Xorg I got a duplicate lock message coming from nvidia,
after running for maybe 20 mins it just reset without warning. I then
decided to go back to the GENERIC kernel and on restarting I got some
lock reversal messages.

nvidia-driver-346.47

nvidia0: <GeForce GT 520> on vgapci0
vgapci0: child nvidia0 requested pci_enable_io
vgapci0: child nvidia0 requested pci_enable_io
vgapci0: Boot video device
hdac0: <NVIDIA GF119 HDA Controller> mem 0xfb080000-0xfb083fff irq 17 at 
device 0.1 on pci1

Full dmesg and other kgdb outputs I have collected are at -
http://shaneware.biz/freebsddebugdata/

Trying to mount root from zfs:zrpleader []...
ums0: <Logitech USB-PS2 Optical Mouse, class 0/0, rev 2.00/11.10, addr 
4> on usbus2
ums0: 3 buttons and [XYZ] coordinates ID=0
ums1: <Wacom Co.,Ltd. CTH-470, class 0/0, rev 2.00/1.00, addr 5> on usbus2
ums1: 6 buttons and [XY] coordinates ID=1
uhid0: <Wacom Co.,Ltd. CTH-470, class 0/0, rev 2.00/1.00, addr 5> on
usbus2
uhid1: <vendor 0x05af USB Keyboard, class 0/0, rev 2.00/1.92, addr 6> on 
usbus2
uhid0: at uhub5, port 2, addr 5 (disconnected)
ums1: at uhub5, port 2, addr 5 (disconnected)
ipfw2 (+ipv6) initialized, divert loadable, nat loadable, default to 
deny, logging disabled
acquiring duplicate lock of same type: "os.lock_sx"
  1st os.lock_sx @ nvidia_os.c:609
  2nd os.lock_sx @ nvidia_os.c:609
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 
0xfffffe0238b8d400
kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe0238b8d4b0
witness_checkorder() at witness_checkorder+0xdc2/frame 0xfffffe0238b8d540
_sx_xlock() at _sx_xlock+0x75/frame 0xfffffe0238b8d580
os_acquire_mutex() at os_acquire_mutex+0x32/frame 0xfffffe0238b8d5a0
_nv010785rm() at _nv010785rm+0x18/frame 0xfffffe000f2fee90
dmapbase() at 0xfffff8001cc40e80/frame 0xfffff8001cc40e18
kernphys() at 0xc1d00001/frame 0xfffff8001cc40e00
(null)() at 0xfffffe0000c5e000/frame 0xc1d0000100000001
acquiring duplicate lock of same type: "os.lock_mtx"
  1st os.lock_mtx @ nvidia_os.c:783
  2nd os.lock_mtx @ nvidia_os.c:783
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 
0xfffffe0238b8d0e0
kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe0238b8d190
witness_checkorder() at witness_checkorder+0xdc2/frame 0xfffffe0238b8d220
__mtx_lock_flags() at __mtx_lock_flags+0xa8/frame 0xfffffe0238b8d270
os_acquire_spinlock() at os_acquire_spinlock+0x1b/frame 0xfffffe0238b8d280
_nv012385rm() at _nv012385rm+0xd75/frame 0xfffffe0000bceef0
pid 3568 (gsettings-data-conv), uid 1001: exited on signal 5

Mar 24 00:24:25 leader kernel: Waiting (max 60 seconds) for system 
process `vnlru' to stop...done
Mar 24 00:24:25 leader kernel: Waiting (max 60 seconds) for system 
process `bufdaemon' to stop...done
Mar 24 00:24:25 leader kernel: Waiting (max 60 seconds) for system 
process `syncer' to stop...
Mar 24 00:24:25 leader kernel: Syncing disks, vnodes remaining...0 0 0 0 
0 0 0 0 done
Mar 24 00:24:25 leader kernel: All buffers synced.
Mar 24 00:24:25 leader kernel: lock order reversal:
Mar 24 00:24:25 leader kernel: 1st 0xfffff800224555f0 zfs (zfs) @ 
/usr/src/sys/kern/vfs_mount.c:1229
Mar 24 00:24:25 leader kernel: 2nd 0xfffff800222d67c8 syncer (syncer) @ 
/usr/src/sys/kern/vfs_subr.c:2268
Mar 24 00:24:25 leader kernel: KDB: stack backtrace:
Mar 24 00:24:25 leader kernel: db_trace_self_wrapper() at 
db_trace_self_wrapper+0x2b/frame 0xfffffe022df6e4c0
Mar 24 00:24:25 leader kernel: kdb_backtrace() at 
kdb_backtrace+0x39/frame 0xfffffe022df6e570
Mar 24 00:24:25 leader kernel: witness_checkorder() at 
witness_checkorder+0xdc2/frame 0xfffffe022df6e600
Mar 24 00:24:25 leader kernel: __lockmgr_args() at 
__lockmgr_args+0x9ea/frame 0xfffffe022df6e740
Mar 24 00:24:25 leader kernel: vop_stdlock() at vop_stdlock+0x3c/frame 
0xfffffe022df6e760
Mar 24 00:24:25 leader kernel: VOP_LOCK1_APV() at 
VOP_LOCK1_APV+0xfc/frame 0xfffffe022df6e790
Mar 24 00:24:25 leader kernel: _vn_lock() at _vn_lock+0xaa/frame 
0xfffffe022df6e800
Mar 24 00:24:25 leader kernel: vputx() at vputx+0x232/frame 
0xfffffe022df6e860
Mar 24 00:24:25 leader kernel: dounmount() at dounmount+0x301/frame 
0xfffffe022df6e8e0
Mar 24 00:24:25 leader kernel: vfs_unmountall() at 
vfs_unmountall+0x61/frame 0xfffffe022df6e910
Mar 24 00:24:25 leader kernel: kern_reboot() at kern_reboot+0x540/frame 
0xfffffe022df6e980
Mar 24 00:24:25 leader kernel: sys_reboot() at sys_reboot+0x5a/frame 
0xfffffe022df6e9a0
Mar 24 00:24:25 leader kernel: amd64_syscall() at 
amd64_syscall+0x25a/frame 0xfffffe022df6eab0
Mar 24 00:24:25 leader kernel: Xfast_syscall() at 
Xfast_syscall+0xfb/frame 0xfffffe022df6eab0
Mar 24 00:24:25 leader kernel: --- syscall (55, FreeBSD ELF64, 
sys_reboot), rip = 0x40f1bc, rsp = 0x7fffffffe6d8, rbp = 0x7fffffffe7d0 ---
Mar 24 00:24:25 leader kernel: lock order reversal:
Mar 24 00:24:25 leader kernel: 1st 0xfffff800222d6b78 zfs (zfs) @ 
/usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1814
Mar 24 00:24:25 leader kernel: 2nd 0xffffffff818514a8 allproc (allproc) 
@ /usr/src/sys/kern/kern_descrip.c:2872
Mar 24 00:24:25 leader kernel: KDB: stack backtrace:
Mar 24 00:24:25 leader kernel: db_trace_self_wrapper() at 
db_trace_self_wrapper+0x2b/frame 0xfffffe022df6e690
Mar 24 00:24:25 leader kernel: kdb_backtrace() at 
kdb_backtrace+0x39/frame 0xfffffe022df6e740
Mar 24 00:24:25 leader kernel: witness_checkorder() at 
witness_checkorder+0xdc2/frame 0xfffffe022df6e7d0
Mar 24 00:24:25 leader kernel: _sx_slock() at _sx_slock+0x76/frame 
0xfffffe022df6e810
Mar 24 00:24:25 leader kernel: mountcheckdirs() at 
mountcheckdirs+0x47/frame 0xfffffe022df6e860
Mar 24 00:24:25 leader kernel: dounmount() at dounmount+0x36f/frame 
0xfffffe022df6e8e0
Mar 24 00:24:25 leader kernel: vfs_unmountall() at 
vfs_unmountall+0x61/frame 0xfffffe022df6e910
Mar 24 00:24:25 leader kernel: kern_reboot() at kern_reboot+0x540/frame 
0xfffffe022df6e980
Mar 24 00:24:25 leader kernel: sys_reboot() at sys_reboot+0x5a/frame 
0xfffffe022df6e9a0
Mar 24 00:24:25 leader kernel: amd64_syscall() at 
amd64_syscall+0x25a/frame 0xfffffe022df6eab0
Mar 24 00:24:25 leader kernel: Xfast_syscall() at 
Xfast_syscall+0xfb/frame 0xfffffe022df6eab0
Mar 24 00:24:25 leader kernel: --- syscall (55, FreeBSD ELF64, 
sys_reboot), rip = 0x40f1bc, rsp = 0x7fffffffe6d8, rbp = 0x7fffffffe7d0 ---
Mar 24 00:24:25 leader kernel: lock order reversal:
Mar 24 00:24:25 leader kernel: 1st 0xfffff8001ca8e240 zfs (zfs) @ 
/usr/src/sys/kern/vfs_mount.c:1229
Mar 24 00:24:25 leader kernel: 2nd 0xfffff8001ca8e5f0 devfs (devfs) @ 
/usr/src/sys/kern/vfs_subr.c:2157
Mar 24 00:24:25 leader kernel: KDB: stack backtrace:
Mar 24 00:24:25 leader kernel: db_trace_self_wrapper() at 
db_trace_self_wrapper+0x2b/frame 0xfffffe022df6e460
Mar 24 00:24:25 leader kernel: kdb_backtrace() at 
kdb_backtrace+0x39/frame 0xfffffe022df6e510
Mar 24 00:24:25 leader kernel: witness_checkorder() at 
witness_checkorder+0xdc2/frame 0xfffffe022df6e5a0
Mar 24 00:24:25 leader kernel: __lockmgr_args() at 
__lockmgr_args+0x9ea/frame 0xfffffe022df6e6e0
Mar 24 00:24:25 leader kernel: vop_stdlock() at vop_stdlock+0x3c/frame 
0xfffffe022df6e700
Mar 24 00:24:25 leader kernel: VOP_LOCK1_APV() at 
VOP_LOCK1_APV+0xfc/frame 0xfffffe022df6e730
Mar 24 00:24:25 leader kernel: _vn_lock() at _vn_lock+0xaa/frame 
0xfffffe022df6e7a0
Mar 24 00:24:25 leader kernel: vget() at vget+0x67/frame 0xfffffe022df6e7e0
Mar 24 00:24:25 leader kernel: devfs_allocv() at devfs_allocv+0xfd/frame 
0xfffffe022df6e830
Mar 24 00:24:25 leader kernel: devfs_root() at devfs_root+0x43/frame 
0xfffffe022df6e860
Mar 24 00:24:25 leader kernel: dounmount() at dounmount+0x345/frame 
0xfffffe022df6e8e0
Mar 24 00:24:25 leader kernel: vfs_unmountall() at 
vfs_unmountall+0x61/frame 0xfffffe022df6e910
Mar 24 00:24:25 leader kernel: kern_reboot() at kern_reboot+0x540/frame 
0xfffffe022df6e980
Mar 24 00:24:25 leader kernel: sys_reboot() at sys_reboot+0x5a/frame 
0xfffffe022df6e9a0
Mar 24 00:24:25 leader kernel: amd64_syscall() at 
amd64_syscall+0x25a/frame 0xfffffe022df6eab0
Mar 24 00:24:25 leader kernel: Xfast_syscall() at 
Xfast_syscall+0xfb/frame 0xfffffe022df6eab0
Mar 24 00:24:25 leader kernel: --- syscall (55, FreeBSD ELF64, 
sys_reboot), rip = 0x40f1bc, rsp = 0x7fffffffe6d8, rbp = 0x7fffffffe7d0 ---
Mar 24 00:24:25 leader kernel: Uptime: 12m42s

-- 
FreeBSD - the place to B...Software Developing

Shane Ambler

Shane Ambler

2015-Jun-17 07:24 UTC

head link

Help debugging stable/10

On 24/03/2015 01:55, Shane Ambler wrote:> On 25/12/2014 23:03, Andriy Gapon wrote:
>> On 25/12/2014 11:29, Hans Petter Selasky wrote:
>>> The cam_sim_free() is stuck, blocking the rest of that controller
from
>>> enumerating. It might look like a non-USB stack issue.
>>>
>>> MAV: Do you have some ideas where to start looking, now we have a
>>> dump? Any
>>> refcounts to check in particular?
>>
>> Apparently sim->refcount > 0.
>> Not sure how to check who has the reference(s).
>>
Can anyone think of something I can try?

To recap to save you going back through history -
After running 9.0 - 9.2 for 3 years I upgraded to 10.1RC3 and started
getting a locking issue, most new processes fail to start, top and ps
failing being indicators, the most info I have got is a back trace
using kgdb, there are 4 instances I got output from procstat -kk -a

On several occasions I have found that after inserting a usb memstick
the device failed to be created, leaving me unable to mount the
filesystem without a restart.

I then switched to stable/10 in hopes of a fix finding it's way in.

The back traces I have been able to collect (and a dmesg) are listed at
http://shaneware.biz/freebsddebugdata/

This is my everyday desktop machine. I am now running

FreeBSD leader.local 10.1-STABLE FreeBSD 10.1-STABLE #11 r283839: Thu
Jun  4 17:41:28 ACST 2015     root at leader.local:/usr/obj/usr/src/sys
/GENERIC  amd64

I can only say it appears to be getting worse, though I may just be
getting sick of having to restart nearly every day. Lately it seems that
the less I do the quicker it locks up. I have restarted twice this week
and then let it sit while I have gone out, after returning I get maybe
10-15 mins then have to restart, one of them was less than an hour uptime.

While running poudriere I have got past 1 day uptime but it locks up
harder and I don't usually get a chance to record any data.

-- 
FreeBSD - the place to B...Software Developing

Shane Ambler

freebsd stable - Jun 2015 - Help debugging stable/10

Help debugging stable/10

Help debugging stable/10