Re: ZFS-related panic: "possible" spa->spa_errlog_lock deadlock

[Fabian Keil]

Fabian Keil  wrote:

> Xin Li  wrote:
> 
> > On 9/7/14 11:23 PM, Fabian Keil wrote:  
> > > Xin Li  wrote:
> > > 
> > >> On 9/7/14 9:02 PM, Fabian Keil wrote:
> > >>> Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got
> > >>> the following panic yesterday:
> > >>> 
> > >>> [...] Unread portion of the kernel message buffer: [6880]
> > >>> panic: deadlkres: possible deadlock detected for
> > >>> 0xf80015289490, blocked for 1800503 ticks
> > >> 
> > >> Any chance to get all backtraces (e.g. thread apply all bt full
> > >> 16)? I think a different thread that held the lock have been
> > >> blocked, probably related to your disconnected vdev.
> > > 
> > > Output of "thread apply all bt full 16" is available at: 
> > > http://www.fabiankeil.de/tmp/freebsd/kgdb-output-spa_errlog_lock-deadlock.txt
> > >
> > >  A lot of the backtraces prematurely end with "Cannot access memory
> > > at address", therefore I also added "thread apply all bt" output.
> > > 
> > > Apparently there are at least two additional threads blocking below
> > > spa_get_stats():  
> [...]
> > Yes, thread 1182 owned the lock and is waiting for the zio be done.
> > Other threads that wanted the lock would have to wait.
> > 
> > I don't have much clue why the system entered this state, however, as
> > the operations should have errored out (the GELI device is gone on
> > 21:44:56 based on your log, which suggests all references were closed)
> > instead of waiting.  

> I finally found the time to analyse the problem which seems
> to be that spa_sync() requires at least one writeable vdev to
> complete, but holds the lock(s) required to remove or bring back
> vdevs.
> 
> Letting spa_sync() drop the lock and wait for at least one vdev
> to become writeable again seems to make the problem unreproducible
> for me, but probably merely shrinks the race window and thus is not
> a complete solution.
> 
> For details see:
> https://www.fabiankeil.de/sourcecode/electrobsd/ZFS-Optionally-let-spa_sync-wait-for-writable-vdev.diff

Patch updated to unbreak the userspace build and to note that the
deadlock can still be reproduced with an artifical test case like:

Shell 1:
  mdconfig -u 0 -f /dpool/scratch/test-vdev.img
  zpool create test /dev/md0
  while sleep 1; do
mdconfig -d -u 0 -o force &&
mdconfig -f /dpool/scratch/test-vdev.img &&
zpool clear test;
  done
Shell 2:
  # Cause writes to the pool from another shell, for example
  # by creating datasets.

Log excerpt (from test begin to deadlock):
Oct 29 12:34:28 kendra ZFS: vdev state changed, pool_guid=16039353738236808887 
vdev_guid=3080051161477470469
[...]
Oct 29 12:46:57 kendra ZFS: vdev state changed, pool_guid=16039353738236808887 
vdev_guid=3080051161477470469
Oct 29 12:46:59 kendra ZFS: vdev is removed, pool_guid=16039353738236808887 
vdev_guid=3080051161477470469
Oct 29 12:46:59 kendra ZFS: vdev state changed, pool_guid=16039353738236808887 
vdev_guid=3080051161477470469
Oct 29 12:47:00 kendra kernel: g_dev_taste: make_dev_p() failed (gp->name=md0, 
error=17)

With the deadman enabled, this will also cause:
 panic: I/O to pool 'test' appears to be hung on vdev guid 3080051161477470469 
at '/dev/md0'.
 cpuid = 0
 KDB: stack backtrace:
 db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfe01136af870
 vpanic() at vpanic+0x182/frame 0xfe01136af8f0
 panic() at panic+0x43/frame 0xfe01136af950
 vdev_deadman() at vdev_deadman+0x127/frame 0xfe01136af9a0
 vdev_deadman() at vdev_deadman+0x40/frame 0xfe01136af9f0
 spa_deadman() at spa_deadman+0x86/frame 0xfe01136afa20
 softclock_call_cc() at softclock_call_cc+0x1a3/frame 0xfe01136afaf0
 softclock() at softclock+0x94/frame 0xfe01136afb20
 intr_event_execute_handlers() at intr_event_execute_handlers+0x1b6/frame 
0xfe01136afb60
 ithread_loop() at ithread_loop+0xa6/frame 0xfe01136afbb0
 fork_exit() at fork_exit+0x9c/frame 0xfe01136afbf0
 fork_trampoline() at fork_trampoline+0xe/frame 0xfe01136afbf0

With test's txg_sync_thread being the offender:
 (kgdb) tid 101874
 [Switching to thread 819 (Thread 101874)]#0  sched_switch 
(td=0xf800513649a0, newtd=, flags=) at /usr/src/sys/kern/sched_ule.c:1969
 1969cpuid = PCPU_GET(cpuid);
 (kgdb) where
 #0  sched_switch (td=0xf800513649a0, newtd=, 
flags=) at /usr/src/sys/kern/sched_ule.c:1969
 #1  0x805a3a18 in mi_switch (flags=260, newtd=0x0) at 
/usr/src/sys/kern/kern_synch.c:470
 #2  0x805ea15a in sleepq_wait (wchan=0x0, pri=0) at 
/usr/src/sys/kern/subr_sleepqueue.c:631
 #3  0x80530509 in _cv_wait (cvp=0xf8002678ea98, 
lock=0xf8002678ea78) at /usr/src/sys/kern/kern_condvar.c:139
 #4  0x81930bbb in zio_wait (zio=) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1535
 #5  0x818e4871 in dsl_pool_sync (dp=0xf80047dfd000, txg=76) at 

Re: ZFS-related panic: "possible" spa->spa_errlog_lock deadlock

[Fabian Keil]

Xin Li  wrote:

> On 9/7/14 11:23 PM, Fabian Keil wrote:
> > Xin Li  wrote:
> >   
> >> On 9/7/14 9:02 PM, Fabian Keil wrote:  
> >>> Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got
> >>> the following panic yesterday:
> >>> 
> >>> [...] Unread portion of the kernel message buffer: [6880]
> >>> panic: deadlkres: possible deadlock detected for
> >>> 0xf80015289490, blocked for 1800503 ticks  
> >> 
> >> Any chance to get all backtraces (e.g. thread apply all bt full
> >> 16)? I think a different thread that held the lock have been
> >> blocked, probably related to your disconnected vdev.  
> > 
> > Output of "thread apply all bt full 16" is available at: 
> > http://www.fabiankeil.de/tmp/freebsd/kgdb-output-spa_errlog_lock-deadlock.txt
> >
> >  A lot of the backtraces prematurely end with "Cannot access memory
> > at address", therefore I also added "thread apply all bt" output.
> > 
> > Apparently there are at least two additional threads blocking below
> > spa_get_stats():
[...]
> Yes, thread 1182 owned the lock and is waiting for the zio be done.
> Other threads that wanted the lock would have to wait.
> 
> I don't have much clue why the system entered this state, however, as
> the operations should have errored out (the GELI device is gone on
> 21:44:56 based on your log, which suggests all references were closed)
> instead of waiting.

Thanks for the responses.

I finally found the time to analyse the problem which seems
to be that spa_sync() requires at least one writeable vdev to
complete, but holds the lock(s) required to remove or bring back
vdevs.

Letting spa_sync() drop the lock and wait for at least one vdev
to become writeable again seems to make the problem unreproducible
for me, but probably merely shrinks the race window and thus is not
a complete solution.

For details see:
https://www.fabiankeil.de/sourcecode/electrobsd/ZFS-Optionally-let-spa_sync-wait-for-writable-vdev.diff
(Experimental, only lightly tested)

Fabian


pgpeu5mIyy5n5.pgp
Description: OpenPGP digital signature

Re: ZFS-related panic: possible spa-spa_errlog_lock deadlock

[Alexander Motin]

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA512

On 07.09.2014 18:56, Xin Li wrote:
 On 9/7/14 11:23 PM, Fabian Keil wrote:
 Xin Li delp...@delphij.net wrote:
 
 On 9/7/14 9:02 PM, Fabian Keil wrote:
 Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got 
 the following panic yesterday:
 
 [...] Unread portion of the kernel message buffer: [6880] 
 panic: deadlkres: possible deadlock detected for 
 0xf80015289490, blocked for 1800503 ticks
 
 Any chance to get all backtraces (e.g. thread apply all bt
 full 16)? I think a different thread that held the lock have
 been blocked, probably related to your disconnected vdev.
 
 Output of thread apply all bt full 16 is available at: 
 http://www.fabiankeil.de/tmp/freebsd/kgdb-output-spa_errlog_lock-deadlock.txt

  A lot of the backtraces prematurely end with Cannot access
 memory at address, therefore I also added thread apply all bt
 output.
 
 Apparently there are at least two additional threads blocking
 below spa_get_stats():
 
 Thread 1182 (Thread 101989): #0  sched_switch 
 (td=0xf800628cc490, newtd=value optimized out,
 flags=value optimized out) at
 /usr/src/sys/kern/sched_ule.c:1932 #1 0x805a23c1 in
 mi_switch (flags=260, newtd=0x0) at 
 /usr/src/sys/kern/kern_synch.c:493 #2  0x805e4bca in 
 sleepq_wait (wchan=0x0, pri=0) at 
 /usr/src/sys/kern/subr_sleepqueue.c:631 #3  0x80539f10
 in _cv_wait (cvp=0xf80025534a50, lock=0xf80025534a30) at 
 /usr/src/sys/kern/kern_condvar.c:139 #4  0x811721db in 
 zio_wait (zio=value optimized out) at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1442
  #5  0x81102111 in dbuf_read (db=value optimized out, 
 zio=value optimized out, flags=value optimized out) at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c:649
  #6  0x81108e6d in dmu_buf_hold (os=value optimized
 out, object=value optimized out, offset=value optimized
 out, tag=0x0, dbp=0xfe00955c6648, flags=value optimized
 out) at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu.c:172
  #7  0x81163986 in zap_lockdir (os=0xf8002b7ab000, 
 obj=92, tx=0x0, lti=RW_READER, fatreader=1, adding=0,
 zapp=value optimized out) at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:467

 
 
 #8  0x811644ad in zap_count (os=0x0, zapobj=0, 
 count=0xfe00955c66d8) at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:712

 
#9  0x8114a6dc in spa_get_errlog_size
 (spa=0xf800062ed000) at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa_errlog.c:149

 
 
 ---Type return to continue, or q return to quit---
 #10 0x8113f549 in spa_get_stats (name=0xfe0044cac000 
 spaceloop, config=0xfe00955c68e8,
 altroot=0xfe0044cac430 , buflen=2048) at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:3287
  #11 0x81189a45 in zfs_ioc_pool_stats 
 (zc=0xfe0044cac000) at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:1656

 
 
 #12 0x81187290 in zfsdev_ioctl (dev=value optimized out, 
 zcmd=value optimized out, arg=value optimized out, flag=value 
 optimized out, td=value optimized out)
 at 
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6136

 
 
 #13 0x80464a55 in devfs_ioctl_f (fp=0xf80038bd00a0, 
 com=3222821381, data=0xf800067b80a0, cred=value optimized
 out, td=0xf800628cc490) at
 /usr/src/sys/fs/devfs/devfs_vnops.c:757
 #14 0x805f3c3d in kern_ioctl (td=0xf800628cc490, 
 fd=value optimized out, com=0) at file.h:311 #15 
 0x805f381c in sys_ioctl (td=0xf800628cc490, 
 uap=0xfe00955c6b80) at /usr/src/sys/kern/sys_generic.c:702
 #16 0x8085c2db in amd64_syscall (td=0xf800628cc490, 
 traced=0) at subr_syscall.c:133 #17 0x8083f90b in 
 Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:390 #18 
 0x0008019fc3da in ?? () Previous frame inner to this frame 
 (corrupt stack?)
 
 Yes, thread 1182 owned the lock and is waiting for the zio be
 done. Other threads that wanted the lock would have to wait.
 
 I don't have much clue why the system entered this state, however,
 as the operations should have errored out (the GELI device is gone
 on 21:44:56 based on your log, which suggests all references were
 closed) instead of waiting.
 
 Adding mav@ as he may have some idea.

Some time ago I experimented with ZFS behavior in situation of
disappearing disks. I fixed several most easily reproducible
scenarios, but finally I've got to conclusion that ZFS in many places
written in a way that simply does not expect errors. In such cases it
just stucks, waiting for disk to reappear and I/O to complete. In some
situations after disk reconnect it can now be recovered with `zpool
clear ...`, but still not all, since sometimes code may stuck holding
some lock required for recovery.

- -- 
Alexander Motin
-BEGIN PGP SIGNATURE-
Version: 

ZFS-related panic: possible spa-spa_errlog_lock deadlock

[Fabian Keil]

Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got the following
panic yesterday:

[...]
Unread portion of the kernel message buffer:
[6880] panic: deadlkres: possible deadlock detected for 0xf80015289490, 
blocked for 1800503 ticks
[6880] 
[6880] cpuid = 1
[6880] KDB: stack backtrace:
[6880] db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 
0xfe009432e9e0
[6880] kdb_backtrace() at kdb_backtrace+0x39/frame 0xfe009432ea90
[6880] panic() at panic+0x1c1/frame 0xfe009432eb50
[6880] deadlkres() at deadlkres+0x588/frame 0xfe009432ebb0
[6880] fork_exit() at fork_exit+0x9a/frame 0xfe009432ebf0
[6880] fork_trampoline() at fork_trampoline+0xe/frame 0xfe009432ebf0
[6880] --- trap 0, rip = 0, rsp = 0xfe009432ecb0, rbp = 0 ---
[6880] KDB: enter: panic
[6880] Uptime: 1h54m40s
[6880] Dumping 354 out of 1973 
MB:..5%..14%..23%..32%..41%..55%..64%..73%..82%..91%

Reading symbols from /boot/kernel/zfs.ko.symbols...done.
[...]
Loaded symbols for /boot/kernel/profile.ko.symbols
#0  doadump (textdump=1) at pcpu.h:219
219 pcpu.h: No such file or directory.
in pcpu.h
(kgdb) where
#0  doadump (textdump=1) at pcpu.h:219
#1  0x80597bad in kern_reboot (howto=260) at 
/usr/src/sys/kern/kern_shutdown.c:447
#2  0x80598100 in panic (fmt=value optimized out) at 
/usr/src/sys/kern/kern_shutdown.c:746
#3  0x80539b98 in deadlkres () at /usr/src/sys/kern/kern_clock.c:240
#4  0x8055e8da in fork_exit (callout=0x80539610 deadlkres, 
arg=0x0, frame=0xfe009432ec00) at /usr/src/sys/kern/kern_fork.c:977
#5  0x8083fb5e in fork_trampoline () at 
/usr/src/sys/amd64/amd64/exception.S:605
#6  0x in ?? ()
Current language:  auto; currently minimal
(kgdb) set $td=(struct thread *)0xf80015289490
(kgdb) tid $td-td_tid
[Switching to thread 1184 (Thread 101428)]#0  sched_switch 
(td=0xf80015289490, newtd=value optimized out, flags=value optimized 
out) at /usr/src/sys/kern/sched_ule.c:1932
1932cpuid = PCPU_GET(cpuid);
(kgdb) bt
#0  sched_switch (td=0xf80015289490, newtd=value optimized out, 
flags=value optimized out) at /usr/src/sys/kern/sched_ule.c:1932
#1  0x805a23c1 in mi_switch (flags=260, newtd=0x0) at 
/usr/src/sys/kern/kern_synch.c:493
#2  0x805e4bca in sleepq_wait (wchan=0x0, pri=0) at 
/usr/src/sys/kern/subr_sleepqueue.c:631
#3  0x805a12b2 in _sx_xlock_hard (sx=0xf800062ed820, 
tid=18446735277971510416, opts=value optimized out, file=0x0, line=0) at 
/usr/src/sys/kern/kern_sx.c:676
#4  0x805a0add in _sx_xlock (sx=0x0, opts=0, file=value optimized 
out, line=0) at sx.h:154
#5  0x8114a691 in spa_get_errlog_size (spa=0xf800062ed000) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa_errlog.c:142
#6  0x8113f549 in spa_get_stats (name=0xfe0006126000 spaceloop, 
config=0xfe00950e58e8, altroot=0xfe0006126430 , buflen=2048)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:3287
#7  0x81189a45 in zfs_ioc_pool_stats (zc=0xfe0006126000) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:1656
#8  0x81187290 in zfsdev_ioctl (dev=value optimized out, zcmd=value 
optimized out, arg=value optimized out, flag=value optimized out, 
td=value optimized out)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6136
#9  0x80464a55 in devfs_ioctl_f (fp=0xf80017107f50, com=3222821381, 
data=0xf8004fb4b740, cred=value optimized out, td=0xf80015289490) at 
/usr/src/sys/fs/devfs/devfs_vnops.c:757
#10 0x805f3c3d in kern_ioctl (td=0xf80015289490, fd=value 
optimized out, com=0) at file.h:311
#11 0x805f381c in sys_ioctl (td=0xf80015289490, 
uap=0xfe00950e5b80) at /usr/src/sys/kern/sys_generic.c:702
#12 0x8085c2db in amd64_syscall (td=0xf80015289490, traced=0) at 
subr_syscall.c:133
#13 0x8083f90b in Xfast_syscall () at 
/usr/src/sys/amd64/amd64/exception.S:390
#14 0x0008019fc3da in ?? ()
(kgdb) f 3
#3  0x805a12b2 in _sx_xlock_hard (sx=0xf800062ed820, 
tid=18446735277971510416, opts=value optimized out, file=0x0, line=0) at 
/usr/src/sys/kern/kern_sx.c:676
676 sleepq_wait(sx-lock_object, 0);
(kgdb) p sx-lock_object
$14 = {lo_name = 0x81202163 spa-spa_errlog_lock, lo_flags = 
4096, lo_data = 0, lo_witness = 0x0}

This happened several minutes after a couple of zpool processes
stopped responding while accessing information about the following
pool:

fk@r500 ~ $zpool status -v spaceloop
  pool: spaceloop
 state: ONLINE
status: One or more devices has experienced an unrecoverable error.  An
attempt was made to correct the error.  Applications are unaffected.
action: Determine if the device needs to be replaced, and clear the errors
using 'zpool clear' or replace the device with 'zpool replace'.
   see: 

Re: ZFS-related panic: possible spa-spa_errlog_lock deadlock

[Xin Li]

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA512

On 9/7/14 9:02 PM, Fabian Keil wrote:
 Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got the
 following panic yesterday:
 
 [...] Unread portion of the kernel message buffer: [6880] panic:
 deadlkres: possible deadlock detected for 0xf80015289490,
 blocked for 1800503 ticks

Any chance to get all backtraces (e.g. thread apply all bt full 16)?
I think a different thread that held the lock have been blocked,
probably related to your disconnected vdev.

Cheers,

-BEGIN PGP SIGNATURE-

iQIcBAEBCgAGBQJUDGarAAoJEJW2GBstM+nsU+AP/0CjAmk3p/j/HD3lOCRYRiyV
JkajIcSI8FFgAfLuiULclnEziBT+XEgYDisoABd7FVaP890mL/Mp52RSLMYlr8VJ
RP9Qv+KePNGVn52djSOPxnNdUNqgNGHiDEllUIZbBu28k/flV4EcSfm799iA9HES
o84LPUUc1pm+NJTtgoT6QKWZ+kfuztfY3/vlwJEluJqSuoZkN8DII1jT3pE55R6h
f++bqSD/eKOd/3EJ5qZ38glXhmeSPEJ+VJlVumuRMwQoe3II7nIrZZBYVMY1sRZ8
qqmi4mUU1EOGvQWYjZ+J+1TYDTQgO9PP/aEPhz39tyJxP4d/VNDbJqPvAw+ez9ZU
jT7n9xuaFXr3WdJSexSFsDOJts9op6kytqnZScPTgVUi2AbUQwBu3wV9v9XKjqBa
YlcHoGFlpUmlc8I9NXdTks0oyORct0K5E/5x00S9QUGw3EtokDVCBQ63n9L1usmd
mRG7F5xgDoTtl6UQSdW+DLhYF0cS08zG6TBDBx630Bdbtye2j5rRVn/bmonZJpOd
Mx0lUyYGKnJFnMaeJe2BsFkrMyUej1JuI0plLVe/QyZ/GBPKsXCIV1R/EC2+2rUF
xgrJl18H5hnwyNpBxjjrBodz1zgbpntijcH301lxRYlJYDBBwUTk3WBxLs/HISTe
itcqBb/VIO33cjBHn3qJ
=QPRD
-END PGP SIGNATURE-
___
freebsd-current@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-current
To unsubscribe, send any mail to freebsd-current-unsubscr...@freebsd.org

Re: ZFS-related panic: possible spa-spa_errlog_lock deadlock

[Fabian Keil]

Xin Li delp...@delphij.net wrote:

 On 9/7/14 9:02 PM, Fabian Keil wrote:
  Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got the
  following panic yesterday:
  
  [...] Unread portion of the kernel message buffer: [6880] panic:
  deadlkres: possible deadlock detected for 0xf80015289490,
  blocked for 1800503 ticks
 
 Any chance to get all backtraces (e.g. thread apply all bt full 16)?
 I think a different thread that held the lock have been blocked,
 probably related to your disconnected vdev.

Output of thread apply all bt full 16 is available at:
http://www.fabiankeil.de/tmp/freebsd/kgdb-output-spa_errlog_lock-deadlock.txt

A lot of the backtraces prematurely end with Cannot access memory at address,
therefore I also added thread apply all bt output.

Apparently there are at least two additional threads blocking below 
spa_get_stats():

Thread 1182 (Thread 101989):
#0  sched_switch (td=0xf800628cc490, newtd=value optimized out, 
flags=value optimized out) at /usr/src/sys/kern/sched_ule.c:1932
#1  0x805a23c1 in mi_switch (flags=260, newtd=0x0) at 
/usr/src/sys/kern/kern_synch.c:493
#2  0x805e4bca in sleepq_wait (wchan=0x0, pri=0) at 
/usr/src/sys/kern/subr_sleepqueue.c:631
#3  0x80539f10 in _cv_wait (cvp=0xf80025534a50, 
lock=0xf80025534a30) at /usr/src/sys/kern/kern_condvar.c:139
#4  0x811721db in zio_wait (zio=value optimized out) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1442
#5  0x81102111 in dbuf_read (db=value optimized out, zio=value 
optimized out, flags=value optimized out) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c:649
#6  0x81108e6d in dmu_buf_hold (os=value optimized out, object=value 
optimized out, offset=value optimized out, tag=0x0, dbp=0xfe00955c6648, 
flags=value optimized out)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu.c:172
#7  0x81163986 in zap_lockdir (os=0xf8002b7ab000, obj=92, tx=0x0, 
lti=RW_READER, fatreader=1, adding=0, zapp=value optimized out)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:467
#8  0x811644ad in zap_count (os=0x0, zapobj=0, 
count=0xfe00955c66d8) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:712
#9  0x8114a6dc in spa_get_errlog_size (spa=0xf800062ed000) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa_errlog.c:149
---Type return to continue, or q return to quit---
#10 0x8113f549 in spa_get_stats (name=0xfe0044cac000 spaceloop, 
config=0xfe00955c68e8, altroot=0xfe0044cac430 , buflen=2048)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:3287
#11 0x81189a45 in zfs_ioc_pool_stats (zc=0xfe0044cac000) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:1656
#12 0x81187290 in zfsdev_ioctl (dev=value optimized out, zcmd=value 
optimized out, arg=value optimized out, flag=value optimized out, 
td=value optimized out)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6136
#13 0x80464a55 in devfs_ioctl_f (fp=0xf80038bd00a0, com=3222821381, 
data=0xf800067b80a0, cred=value optimized out, td=0xf800628cc490) at 
/usr/src/sys/fs/devfs/devfs_vnops.c:757
#14 0x805f3c3d in kern_ioctl (td=0xf800628cc490, fd=value 
optimized out, com=0) at file.h:311
#15 0x805f381c in sys_ioctl (td=0xf800628cc490, 
uap=0xfe00955c6b80) at /usr/src/sys/kern/sys_generic.c:702
#16 0x8085c2db in amd64_syscall (td=0xf800628cc490, traced=0) at 
subr_syscall.c:133
#17 0x8083f90b in Xfast_syscall () at 
/usr/src/sys/amd64/amd64/exception.S:390
#18 0x0008019fc3da in ?? ()
Previous frame inner to this frame (corrupt stack?)

Thread 1188 (Thread 102480):
#0  sched_switch (td=0xf80015a63920, newtd=value optimized out, 
flags=value optimized out) at /usr/src/sys/kern/sched_ule.c:1932
#1  0x805a23c1 in mi_switch (flags=260, newtd=0x0) at 
/usr/src/sys/kern/kern_synch.c:493
#2  0x805e4bca in sleepq_wait (wchan=0x0, pri=0) at 
/usr/src/sys/kern/subr_sleepqueue.c:631
#3  0x805a12b2 in _sx_xlock_hard (sx=0xf800062ed820, 
tid=18446735277979744544, opts=value optimized out, file=0x0, line=0) at 
/usr/src/sys/kern/kern_sx.c:676
#4  0x805a0add in _sx_xlock (sx=0x0, opts=0, file=value optimized 
out, line=0) at sx.h:154
#5  0x8114a691 in spa_get_errlog_size (spa=0xf800062ed000) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa_errlog.c:142
#6  0x8113f549 in spa_get_stats (name=0xfe0005d6c000 spaceloop, 
config=0xfe0095f708e8, altroot=0xfe0005d6c430 , buflen=2048)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:3287
#7  0x81189a45 in zfs_ioc_pool_stats (zc=0xfe0005d6c000) at 
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:1656
#8  0x81187290 in 

Re: ZFS-related panic: possible spa-spa_errlog_lock deadlock

[Xin Li]

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA512

On 9/7/14 11:23 PM, Fabian Keil wrote:
 Xin Li delp...@delphij.net wrote:
 
 On 9/7/14 9:02 PM, Fabian Keil wrote:
 Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got
 the following panic yesterday:
 
 [...] Unread portion of the kernel message buffer: [6880]
 panic: deadlkres: possible deadlock detected for
 0xf80015289490, blocked for 1800503 ticks
 
 Any chance to get all backtraces (e.g. thread apply all bt full
 16)? I think a different thread that held the lock have been
 blocked, probably related to your disconnected vdev.
 
 Output of thread apply all bt full 16 is available at: 
 http://www.fabiankeil.de/tmp/freebsd/kgdb-output-spa_errlog_lock-deadlock.txt

  A lot of the backtraces prematurely end with Cannot access memory
 at address, therefore I also added thread apply all bt output.
 
 Apparently there are at least two additional threads blocking below
 spa_get_stats():
 
 Thread 1182 (Thread 101989): #0  sched_switch
 (td=0xf800628cc490, newtd=value optimized out, flags=value
 optimized out) at /usr/src/sys/kern/sched_ule.c:1932 #1
 0x805a23c1 in mi_switch (flags=260, newtd=0x0) at
 /usr/src/sys/kern/kern_synch.c:493 #2  0x805e4bca in
 sleepq_wait (wchan=0x0, pri=0) at
 /usr/src/sys/kern/subr_sleepqueue.c:631 #3  0x80539f10 in
 _cv_wait (cvp=0xf80025534a50, lock=0xf80025534a30) at
 /usr/src/sys/kern/kern_condvar.c:139 #4  0x811721db in
 zio_wait (zio=value optimized out) at
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1442 
 #5  0x81102111 in dbuf_read (db=value optimized out,
 zio=value optimized out, flags=value optimized out) at
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c:649 
 #6  0x81108e6d in dmu_buf_hold (os=value optimized out,
 object=value optimized out, offset=value optimized out,
 tag=0x0, dbp=0xfe00955c6648, flags=value optimized out) at
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu.c:172 
 #7  0x81163986 in zap_lockdir (os=0xf8002b7ab000,
 obj=92, tx=0x0, lti=RW_READER, fatreader=1, adding=0, zapp=value
 optimized out) at
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:467

 
#8  0x811644ad in zap_count (os=0x0, zapobj=0,
count=0xfe00955c66d8) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:712
 #9  0x8114a6dc in spa_get_errlog_size
 (spa=0xf800062ed000) at
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa_errlog.c:149

 
- ---Type return to continue, or q return to quit---
 #10 0x8113f549 in spa_get_stats (name=0xfe0044cac000
 spaceloop, config=0xfe00955c68e8, altroot=0xfe0044cac430
 , buflen=2048) at
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:3287 
 #11 0x81189a45 in zfs_ioc_pool_stats
 (zc=0xfe0044cac000) at
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:1656

 
#12 0x81187290 in zfsdev_ioctl (dev=value optimized out,
zcmd=value optimized out, arg=value optimized out, flag=value
optimized out, td=value optimized out)
 at
 /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6136

 
#13 0x80464a55 in devfs_ioctl_f (fp=0xf80038bd00a0,
com=3222821381, data=0xf800067b80a0, cred=value optimized out,
td=0xf800628cc490) at /usr/src/sys/fs/devfs/devfs_vnops.c:757
 #14 0x805f3c3d in kern_ioctl (td=0xf800628cc490,
 fd=value optimized out, com=0) at file.h:311 #15
 0x805f381c in sys_ioctl (td=0xf800628cc490,
 uap=0xfe00955c6b80) at /usr/src/sys/kern/sys_generic.c:702 #16
 0x8085c2db in amd64_syscall (td=0xf800628cc490,
 traced=0) at subr_syscall.c:133 #17 0x8083f90b in
 Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:390 #18
 0x0008019fc3da in ?? () Previous frame inner to this frame
 (corrupt stack?)

Yes, thread 1182 owned the lock and is waiting for the zio be done.
Other threads that wanted the lock would have to wait.

I don't have much clue why the system entered this state, however, as
the operations should have errored out (the GELI device is gone on
21:44:56 based on your log, which suggests all references were closed)
instead of waiting.

Adding mav@ as he may have some idea.

Cheers,
-BEGIN PGP SIGNATURE-

iQIcBAEBCgAGBQJUDIA5AAoJEJW2GBstM+nsdsgP/RT4nBT4mvOtpF2IEL7VFexJ
OjipGsWIDmG9kc8CEEN+qh3Q4+prJO3IwHGTUPa0Vu13jRZ3T/uoZj/ncVAqnCyW
s+SeEBjVVhZs/B08LqT2A8fZI9jVdqvFVWEL02z3ibWggoCnP60oag1OyvkNGqQU
apWtXkjTnrFmOEcbB95viD8QEhfUzlQgBbeRuK8ADtK/jQNEl6A8xdE5HCT2DIN4
icIwoj9eXqyLB0/aGVIFycRID4hWAZaqPehXVtGhCdnlGut7itdufuXtfmTCEDWs
z3vkGjTCJ3qsyKSxl/2ABGRgAH/lpR6J/N2yZOSNMRTt9PbjN1iLppu2IfD33OdY
QlQrI2HhbwvoZmYe4f4B/1/8qzKag77hzYG2J2aN0OGn45zkThOwoQt854zm7OHq
f3O3pysxUInTnIJrdBa53cT0arhQRtYn1xL5CYyvK4Nto74ht6g/AuBJbBWzWM/B
t2fKuZmpGt32lf+vHjWS0O2VWdkc6I6s5rVZJsSLzAMfc1rWePIcokPdUk9RucyX

Re: ZFS-related panic: possible spa-spa_errlog_lock deadlock

[Steven Hartland]

- Original Message - 
From: Xin Li delp...@delphij.net

To: Fabian Keil freebsd-lis...@fabiankeil.de; freebsd-current@freebsd.org
Cc: Alexander Motin m...@ixsystems.com
Sent: Sunday, September 07, 2014 4:56 PM
Subject: Re: ZFS-related panic: possible spa-spa_errlog_lock deadlock



-BEGIN PGP SIGNED MESSAGE-
Hash: SHA512

On 9/7/14 11:23 PM, Fabian Keil wrote:

Xin Li delp...@delphij.net wrote:


On 9/7/14 9:02 PM, Fabian Keil wrote:

Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got
the following panic yesterday:

[...] Unread portion of the kernel message buffer: [6880]
panic: deadlkres: possible deadlock detected for
0xf80015289490, blocked for 1800503 ticks


Any chance to get all backtraces (e.g. thread apply all bt full
16)? I think a different thread that held the lock have been
blocked, probably related to your disconnected vdev.


Output of thread apply all bt full 16 is available at: 
http://www.fabiankeil.de/tmp/freebsd/kgdb-output-spa_errlog_lock-deadlock.txt


 A lot of the backtraces prematurely end with Cannot access memory
at address, therefore I also added thread apply all bt output.

Apparently there are at least two additional threads blocking below
spa_get_stats():

Thread 1182 (Thread 101989): #0  sched_switch
(td=0xf800628cc490, newtd=value optimized out, flags=value
optimized out) at /usr/src/sys/kern/sched_ule.c:1932 #1
0x805a23c1 in mi_switch (flags=260, newtd=0x0) at
/usr/src/sys/kern/kern_synch.c:493 #2  0x805e4bca in
sleepq_wait (wchan=0x0, pri=0) at
/usr/src/sys/kern/subr_sleepqueue.c:631 #3  0x80539f10 in
_cv_wait (cvp=0xf80025534a50, lock=0xf80025534a30) at
/usr/src/sys/kern/kern_condvar.c:139 #4  0x811721db in
zio_wait (zio=value optimized out) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1442 
#5  0x81102111 in dbuf_read (db=value optimized out,

zio=value optimized out, flags=value optimized out) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c:649 
#6  0x81108e6d in dmu_buf_hold (os=value optimized out,

object=value optimized out, offset=value optimized out,
tag=0x0, dbp=0xfe00955c6648, flags=value optimized out) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu.c:172 
#7  0x81163986 in zap_lockdir (os=0xf8002b7ab000,

obj=92, tx=0x0, lti=RW_READER, fatreader=1, adding=0, zapp=value
optimized out) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:467



#8  0x811644ad in zap_count (os=0x0, zapobj=0,
count=0xfe00955c66d8) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zap_micro.c:712

#9  0x8114a6dc in spa_get_errlog_size
(spa=0xf800062ed000) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa_errlog.c:149



- ---Type return to continue, or q return to quit---

#10 0x8113f549 in spa_get_stats (name=0xfe0044cac000
spaceloop, config=0xfe00955c68e8, altroot=0xfe0044cac430
, buflen=2048) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:3287 
#11 0x81189a45 in zfs_ioc_pool_stats

(zc=0xfe0044cac000) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:1656



#12 0x81187290 in zfsdev_ioctl (dev=value optimized out,
zcmd=value optimized out, arg=value optimized out, flag=value
optimized out, td=value optimized out)

at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6136



#13 0x80464a55 in devfs_ioctl_f (fp=0xf80038bd00a0,
com=3222821381, data=0xf800067b80a0, cred=value optimized out,
td=0xf800628cc490) at /usr/src/sys/fs/devfs/devfs_vnops.c:757

#14 0x805f3c3d in kern_ioctl (td=0xf800628cc490,
fd=value optimized out, com=0) at file.h:311 #15
0x805f381c in sys_ioctl (td=0xf800628cc490,
uap=0xfe00955c6b80) at /usr/src/sys/kern/sys_generic.c:702 #16
0x8085c2db in amd64_syscall (td=0xf800628cc490,
traced=0) at subr_syscall.c:133 #17 0x8083f90b in
Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:390 #18
0x0008019fc3da in ?? () Previous frame inner to this frame
(corrupt stack?)


Yes, thread 1182 owned the lock and is waiting for the zio be done.
Other threads that wanted the lock would have to wait.

I don't have much clue why the system entered this state, however, as
the operations should have errored out (the GELI device is gone on
21:44:56 based on your log, which suggests all references were closed)
instead of waiting.

Adding mav@ as he may have some idea.


We're seen a disk drop invalidating a pool before, which should fail
all reads / writes but process have instead just wedged in the kernel.


From experience I'd say it happens ~5% of time, so its quite hard to

catch.

Unfortunately never managed to get a dump of it.

   Regards
   Steve
___
freebsd-current@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo

Re: ZFS-related panic: possible spa-spa_errlog_lock deadlock

[Fabian Keil]

Xin Li delp...@delphij.net wrote:

 On 9/7/14 11:23 PM, Fabian Keil wrote:
  Xin Li delp...@delphij.net wrote:
  
  On 9/7/14 9:02 PM, Fabian Keil wrote:
  Using a kernel built from FreeBSD 11.0-CURRENT r271182 I got
  the following panic yesterday:
  
  [...] Unread portion of the kernel message buffer: [6880]
  panic: deadlkres: possible deadlock detected for
  0xf80015289490, blocked for 1800503 ticks
  
  Any chance to get all backtraces (e.g. thread apply all bt full
  16)? I think a different thread that held the lock have been
  blocked, probably related to your disconnected vdev.
  
  Output of thread apply all bt full 16 is available at: 
  http://www.fabiankeil.de/tmp/freebsd/kgdb-output-spa_errlog_lock-deadlock.txt
 
   A lot of the backtraces prematurely end with Cannot access memory
  at address, therefore I also added thread apply all bt output.
  
  Apparently there are at least two additional threads blocking below
  spa_get_stats():
[...]
 Yes, thread 1182 owned the lock and is waiting for the zio be done.
 Other threads that wanted the lock would have to wait.
 
 I don't have much clue why the system entered this state, however, as
 the operations should have errored out (the GELI device is gone on
 21:44:56 based on your log, which suggests all references were closed)
 instead of waiting.

It occurred to me that I have relevant auth.log entries as well:

Sep  6 20:54:31 r500 sudo:   fk : TTY=pts/5 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/geli attach -j - /dev/label/spaceloop
Sep  6 20:54:44 r500 sudo:   fk : TTY=pts/5 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/geli attach -j - /dev/label/takems
Sep  6 20:54:51 r500 sudo:   fk : TTY=pts/5 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/zpool import -d /dev/label takems
Sep  6 20:55:30 r500 sudo:   fk : TTY=pts/5 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/zfs send -i @2014-08-13_23:10 tank/home/fk@2014-09-06_19:56
Sep  6 20:55:30 r500 sudo:   fk : TTY=pts/5 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/zfs receive -v -u -F spaceloop/backup/r500/tank/home/fk
Sep  6 20:55:46 r500 sudo:   fk : TTY=pts/5 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/zfs send -i @2014-08-13_23:10 tank/home/fk@2014-09-06_19:56
Sep  6 20:55:46 r500 sudo:   fk : TTY=pts/5 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/zfs receive -v -u -F spaceloop/backup/r500/tank/home/fk
[...]
Sep  6 21:28:47 r500 sudo:   fk : TTY=pts/6 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/zpool status spaceloop
Sep  6 21:29:43 r500 sudo:   fk : TTY=pts/9 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/zpool export takems
Sep  6 21:29:46 r500 sudo:   fk : TTY=pts/9 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/geli detach label/takems.eli
Sep  6 21:30:08 r500 sudo:   fk : TTY=pts/10 ; PWD=/home/fk ; USER=root ; 
COMMAND=/sbin/zpool clear spaceloop
Sep  6 21:44:16 r500 sudo:   fk : TTY=pts/11 ; PWD=/home/fk ; USER=root ; 
COMMAND=/usr/sbin/usbconfig
Sep  6 21:44:56 r500 sudo:   fk : TTY=pts/11 ; PWD=/home/fk ; USER=root ; 
COMMAND=/usr/sbin/usbconfig -d 1.3 reset
Sep  6 21:46:26 r500 sudo:   fk : TTY=pts/1 ; PWD=/home/fk ; USER=root ; 
COMMAND=/usr/sbin/usbconfig
Sep  6 22:03:33 r500 login: login on ttyv0 as fk

IIRC, I tried the USB reset because the zfs receive ... spaceloop/*,
zpool status spaceloop and zpool clear spaceloop processes (and some
that weren't called with sudo and thus weren't logged) got stuck and while
it caused the kernel to close label/spaceloop.eli as intended, it did not
noticeable affect the deadlocked processes.

I don't remember exactly why the same ZFS stream was sent twice, but the most
likely explanation seems to be that I aborted the operation before it was done
and it's conceivable that this left the system in a state that caused the second
attempt to get stuck.

Fabian


signature.asc
Description: PGP signature