Re: 8.1R ZFS almost locking up system
Hello list! Thu, Jan 01, 1970 at 12:00:00AM + Dan Nelson wrote: In the last episode (Aug 31), Tim Bishop said: On Sat, Aug 21, 2010 at 05:24:29PM -0500, Dan Nelson wrote: In the last episode (Aug 21), Tim Bishop said: A few items from top, including zfskern: PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 5 root4 -8- 0K60K zio-i 0 54:38 3.47% zfskern 91775 70 1 440 53040K 31144K tx-tx 1 2:11 0.00% postgres 39661 tdb 1 440 55776K 32968K tx-tx 0 0:39 0.00% mutt 14828 root1 470 14636K 1572K tx-tx 1 0:03 0.00% zfs 11188 root1 510 14636K 1572K tx-tx 0 0:03 0.00% zfs I'm seeing a similar problem on a remote server (unpatched 8.1-RELEASE, amd64, quad-core, raidz pool on 8 drives). However, it's also different in what seems to be important. Please advise. Portions of top: CPU: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle Mem: 75M Active, 31M Inact, 1352M Wired, 136K Cache, 812M Buf, 6458M Free 35769 root 1 520 2740K 744K zilog- 1 0:00 0.00% sync 35625 df 1 440 14636K 1856K zio-i 2 0:00 0.00% zfs 35920 root 1 440 15668K 1836K scl-s 0 0:00 0.00% zpool 35607 root 1 440 8260K 2284K zio-i 0 0:00 0.00% csh 0 100084 kernel zfs_vn_rele_task mi_switch+0x16f sleepq_wait+0x42 _sleep+0x31c taskqueue_thread_loop+0xb7 fork_exit+0x118 fork_trampoline+0xe 5 100031 zfskern arc_reclaim_thre mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 arc_reclaim_thread+0x2d1 fork_exit+0x118 fork_trampoline+0xe 5 100032 zfskern l2arc_feed_threa mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 l2arc_feed_thread+0x1be fork_exit+0x118 fork_trampoline+0xe 5 100085 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_thread_wait+0x79 txg_quiesce_thread+0xb5 fork_exit+0x118 fork_trampoline+0xe 5 100086 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 zio_wait+0x61 dsl_pool_sync+0xea spa_sync+0x355 txg_sync_thread+0x195 fork_exit+0x118 fork_trampoline+0xe procstat -kk -a: 0 100114 kernel zfs_vn_rele_task mi_switch+0x16f sleepq_wait+0x42 _sleep+0x31c taskqueue_thread_loop+0xb7 fork_exit+0x118 fork_trampoline+0xe 0 100123 kernel zil_cleanmi_switch+0x16f sleepq_wait+0x42 _sleep+0x31c taskqueue_thread_loop+0xb7 fork_exit+0x118 fork_trampoline+0xe 16 100065 syncer -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 zio_wait+0x61 zil_commit+0x3e1 zfs_sync+0xa6 sync_fsync+0x184 sync_vnode+0x16b sched_sync+0x1c9 fork_exit+0x118 fork_trampoline+0xe 39 100079 zfskern arc_reclaim_thre mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 arc_reclaim_thread+0x2d1 fork_exit+0x118 fork_trampoline+0xe 39 100086 zfskern l2arc_feed_threa mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 l2arc_feed_thread+0x1be fork_exit+0x118 fork_trampoline+0xe 39 100115 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_thread_wait+0x79 txg_quiesce_thread+0xb5 fork_exit+0x118 fork_trampoline+0xe 39 100116 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 zio_wait+0x61 dsl_pool_sync+0xea spa_sync+0x355 txg_sync_thread+0x195 35625 100151 zfs -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 zio_wait+0x61 dbuf_read+0x39a dmu_buf_hold+0xcc zap_lockdir+0x52 zap_cursor_retrieve+0x194 dsl_prop_get_all+0x187 zfs_ioc_objset_stats+0x7b zfsdev_ioctl+0x8d devfs_ioctl_f+0x77 kern_ioctl+0xf6 ioctl+0xfd syscall+0x1e7 35769 100212 sync -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 zil_commit+0x7a zfs_sync+0xa6 sync+0x20e syscall+0x1e7 Xfast_syscall+0xe1 etc. etc... Seems pretty identical... But gstat seems different: dT: 1.008s w: 1.000s L(q) ops/sr/s kBps ms/rw/s kBps ms/w %busy Name ... 3 0 0 00.0 0 00.00.0 da0 3 0 0 00.0 0 00.00.0 da1 3 0 0 00.0 0 00.00.0 da2 35 0 0 00.0 0 00.00.0 da3 3 0 0 00.0 0 00.00.0 da4 2 0 0 00.0 0 00.00.0 da5 3 0 0 00.0 0 00.00.0 da6 35 0 0 00.0 0 00.00.0 da7 Note the huge wait queues... I've tried reading from the disks (dd), camcontrol inquiry'ing them, but all of these methods fail: %dd if=/dev/da3 of=/dev/null bs=1024k load: 0.00 cmd: dd 37770 [physrd] 2.67r 0.00u 0.00s 0% 1168k [and
Re: 8.1R ZFS almost locking up system
In the last episode (Sep 01), Tim Bishop said: On Tue, Aug 31, 2010 at 10:58:29AM -0500, Dan Nelson wrote: In the last episode (Aug 31), Tim Bishop said: It happened again this Saturday (clearly something in the weekly periodic run is triggering the issue). procstat -kk shows the following for processes doing something zfs related (where zfs related means the string 'zfs' in the procstat -kk output): 0 100084 kernel zfs_vn_rele_task mi_switch+0x16f sleepq_wait+0x42 _sleep+0x31c taskqueue_thread_loop+0xb7 fork_exit+0x118 fork_trampoline+0xe 5 100031 zfskern arc_reclaim_thre mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 arc_reclaim_thread+0x2d1 fork_exit+0x118 fork_trampoline+0xe 5 100032 zfskern l2arc_feed_threa mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 l2arc_feed_thread+0x1be fork_exit+0x118 fork_trampoline+0xe 5 100085 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_thread_wait+0x79 txg_quiesce_thread+0xb5 fork_exit+0x118 fork_trampoline+0xe 5 100086 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 zio_wait+0x61 dsl_pool_sync+0xea spa_sync+0x355 txg_sync_thread+0x195 fork_exit+0x118 fork_trampoline+0xe 17 100040 syncer -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_synced+0x7c zil_commit+0x416 zfs_sync+0xa6 sync_fsync+0x184 sync_vnode+0x16b sched_sync+0x1c9 fork_exit+0x118 fork_trampoline+0xe 2210 100156 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 3500 100177 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 3783 100056 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 4064 100165 mysqld initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 closef+0x3b kern_close+0x14d syscall+0x1e7 Xfast_syscall+0xe1 4441 100224 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 100227 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 4445 100228 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 4446 100229 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 4447 100089 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 5352 100270 mutt -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_synced+0x7c zil_commit+0x416 zfs_freebsd_fsync+0xd7 null_bypass+0xd3 fsync+0x161 syscall+0x1e7 Xfast_syscall+0xe1 52686 100200 tarsnap -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc
Re: 8.1R ZFS almost locking up system
On Tue, Aug 31, 2010 at 10:58:29AM -0500, Dan Nelson wrote:
In the last episode (Aug 31), Tim Bishop said:
On Sat, Aug 21, 2010 at 05:24:29PM -0500, Dan Nelson wrote:
In the last episode (Aug 21), Tim Bishop said:
A few items from top, including zfskern:
PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU
COMMAND
5 root4 -8- 0K60K zio-i 0 54:38 3.47%
zfskern
91775 70 1 440 53040K 31144K tx-tx 1 2:11 0.00%
postgres
39661 tdb 1 440 55776K 32968K tx-tx 0 0:39 0.00% mutt
14828 root1 470 14636K 1572K tx-tx 1 0:03 0.00% zfs
11188 root1 510 14636K 1572K tx-tx 0 0:03 0.00% zfs
At some point during this process my zfs snapshots have been failing to
complete:
root5 0.8 0.0 060 ?? DL7Aug10 54:43.83
[zfskern]
root 8265 0.0 0.0 14636 1528 ?? D10:00AM 0:03.12 zfs
snapshot -r po...@2010-08-21_10:00:01--1d
root11188 0.0 0.1 14636 1572 ?? D11:00AM 0:02.93 zfs
snapshot -r po...@2010-08-21_11:00:01--1d
root14828 0.0 0.1 14636 1572 ?? D12:00PM 0:03.04 zfs
snapshot -r po...@2010-08-21_12:00:00--1d
root17862 0.0 0.1 14636 1572 ?? D 1:00PM 0:01.96 zfs
snapshot -r po...@2010-08-21_13:00:01--1d
root20986 0.0 0.1 14636 1572 ?? D 2:00PM 0:02.07 zfs
snapshot -r po...@2010-08-21_14:00:01--1d
procstat -k on some of these processes might help to pinpoint what part of
the zfs code they're all waiting in.
It happened again this Saturday (clearly something in the weekly
periodic run is triggering the issue). procstat -kk shows the following
for processes doing something zfs related (where zfs related means the
string 'zfs' in the procstat -kk output):
0 100084 kernel zfs_vn_rele_task mi_switch+0x16f
sleepq_wait+0x42 _sleep+0x31c taskqueue_thread_loop+0xb7 fork_exit+0x118
fork_trampoline+0xe
5 100031 zfskern arc_reclaim_thre mi_switch+0x16f
sleepq_timedwait+0x42 _cv_timedwait+0x129 arc_reclaim_thread+0x2d1
fork_exit+0x118 fork_trampoline+0xe
5 100032 zfskern l2arc_feed_threa mi_switch+0x16f
sleepq_timedwait+0x42 _cv_timedwait+0x129 l2arc_feed_thread+0x1be
fork_exit+0x118 fork_trampoline+0xe
5 100085 zfskern txg_thread_enter mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 txg_thread_wait+0x79
txg_quiesce_thread+0xb5 fork_exit+0x118 fork_trampoline+0xe
5 100086 zfskern txg_thread_enter mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 zio_wait+0x61 dsl_pool_sync+0xea
spa_sync+0x355 txg_sync_thread+0x195 fork_exit+0x118 fork_trampoline+0xe
17 100040 syncer -mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 txg_wait_synced+0x7c zil_commit+0x416
zfs_sync+0xa6 sync_fsync+0x184 sync_vnode+0x16b sched_sync+0x1c9
fork_exit+0x118 fork_trampoline+0xe
2210 100156 syslogd -mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378
VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60
writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1
3500 100177 syslogd -mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378
VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60
writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1
3783 100056 syslogd -mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378
VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60
writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1
4064 100165 mysqld initial thread mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c
zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc
vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 closef+0x3b kern_close+0x14d
syscall+0x1e7 Xfast_syscall+0xe1
4441 100224 python2.6initial thread mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c
zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc
null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f
vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23
100227 python2.6initial thread mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c
zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc
null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f
vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23
4445 100228 python2.6initial thread mi_switch+0x16f
sleepq_wait+0x42 _cv_wait+0x111
Re: 8.1R ZFS almost locking up system
On Sat, Aug 21, 2010 at 05:24:29PM -0500, Dan Nelson wrote: In the last episode (Aug 21), Tim Bishop said: A few items from top, including zfskern: PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 5 root4 -8- 0K60K zio-i 0 54:38 3.47% zfskern 91775 70 1 440 53040K 31144K tx-tx 1 2:11 0.00% postgres 39661 tdb 1 440 55776K 32968K tx-tx 0 0:39 0.00% mutt 14828 root1 470 14636K 1572K tx-tx 1 0:03 0.00% zfs 11188 root1 510 14636K 1572K tx-tx 0 0:03 0.00% zfs At some point during this process my zfs snapshots have been failing to complete: root5 0.8 0.0 060 ?? DL7Aug10 54:43.83 [zfskern] root 8265 0.0 0.0 14636 1528 ?? D10:00AM 0:03.12 zfs snapshot -r po...@2010-08-21_10:00:01--1d root11188 0.0 0.1 14636 1572 ?? D11:00AM 0:02.93 zfs snapshot -r po...@2010-08-21_11:00:01--1d root14828 0.0 0.1 14636 1572 ?? D12:00PM 0:03.04 zfs snapshot -r po...@2010-08-21_12:00:00--1d root17862 0.0 0.1 14636 1572 ?? D 1:00PM 0:01.96 zfs snapshot -r po...@2010-08-21_13:00:01--1d root20986 0.0 0.1 14636 1572 ?? D 2:00PM 0:02.07 zfs snapshot -r po...@2010-08-21_14:00:01--1d procstat -k on some of these processes might help to pinpoint what part of the zfs code they're all waiting in. It happened again this Saturday (clearly something in the weekly periodic run is triggering the issue). procstat -kk shows the following for processes doing something zfs related (where zfs related means the string 'zfs' in the procstat -kk output): 0 100084 kernel zfs_vn_rele_task mi_switch+0x16f sleepq_wait+0x42 _sleep+0x31c taskqueue_thread_loop+0xb7 fork_exit+0x118 fork_trampoline+0xe 5 100031 zfskern arc_reclaim_thre mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 arc_reclaim_thread+0x2d1 fork_exit+0x118 fork_trampoline+0xe 5 100032 zfskern l2arc_feed_threa mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 l2arc_feed_thread+0x1be fork_exit+0x118 fork_trampoline+0xe 5 100085 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_thread_wait+0x79 txg_quiesce_thread+0xb5 fork_exit+0x118 fork_trampoline+0xe 5 100086 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 zio_wait+0x61 dsl_pool_sync+0xea spa_sync+0x355 txg_sync_thread+0x195 fork_exit+0x118 fork_trampoline+0xe 17 100040 syncer -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_synced+0x7c zil_commit+0x416 zfs_sync+0xa6 sync_fsync+0x184 sync_vnode+0x16b sched_sync+0x1c9 fork_exit+0x118 fork_trampoline+0xe 2210 100156 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 3500 100177 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 3783 100056 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 4064 100165 mysqld initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 closef+0x3b kern_close+0x14d syscall+0x1e7 Xfast_syscall+0xe1 4441 100224 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 100227 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 4445 100228 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 4446 100229 python2.6initial thread
Re: 8.1R ZFS almost locking up system
In the last episode (Aug 31), Tim Bishop said: On Sat, Aug 21, 2010 at 05:24:29PM -0500, Dan Nelson wrote: In the last episode (Aug 21), Tim Bishop said: A few items from top, including zfskern: PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 5 root4 -8- 0K60K zio-i 0 54:38 3.47% zfskern 91775 70 1 440 53040K 31144K tx-tx 1 2:11 0.00% postgres 39661 tdb 1 440 55776K 32968K tx-tx 0 0:39 0.00% mutt 14828 root1 470 14636K 1572K tx-tx 1 0:03 0.00% zfs 11188 root1 510 14636K 1572K tx-tx 0 0:03 0.00% zfs At some point during this process my zfs snapshots have been failing to complete: root5 0.8 0.0 060 ?? DL7Aug10 54:43.83 [zfskern] root 8265 0.0 0.0 14636 1528 ?? D10:00AM 0:03.12 zfs snapshot -r po...@2010-08-21_10:00:01--1d root11188 0.0 0.1 14636 1572 ?? D11:00AM 0:02.93 zfs snapshot -r po...@2010-08-21_11:00:01--1d root14828 0.0 0.1 14636 1572 ?? D12:00PM 0:03.04 zfs snapshot -r po...@2010-08-21_12:00:00--1d root17862 0.0 0.1 14636 1572 ?? D 1:00PM 0:01.96 zfs snapshot -r po...@2010-08-21_13:00:01--1d root20986 0.0 0.1 14636 1572 ?? D 2:00PM 0:02.07 zfs snapshot -r po...@2010-08-21_14:00:01--1d procstat -k on some of these processes might help to pinpoint what part of the zfs code they're all waiting in. It happened again this Saturday (clearly something in the weekly periodic run is triggering the issue). procstat -kk shows the following for processes doing something zfs related (where zfs related means the string 'zfs' in the procstat -kk output): 0 100084 kernel zfs_vn_rele_task mi_switch+0x16f sleepq_wait+0x42 _sleep+0x31c taskqueue_thread_loop+0xb7 fork_exit+0x118 fork_trampoline+0xe 5 100031 zfskern arc_reclaim_thre mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 arc_reclaim_thread+0x2d1 fork_exit+0x118 fork_trampoline+0xe 5 100032 zfskern l2arc_feed_threa mi_switch+0x16f sleepq_timedwait+0x42 _cv_timedwait+0x129 l2arc_feed_thread+0x1be fork_exit+0x118 fork_trampoline+0xe 5 100085 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_thread_wait+0x79 txg_quiesce_thread+0xb5 fork_exit+0x118 fork_trampoline+0xe 5 100086 zfskern txg_thread_enter mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 zio_wait+0x61 dsl_pool_sync+0xea spa_sync+0x355 txg_sync_thread+0x195 fork_exit+0x118 fork_trampoline+0xe 17 100040 syncer -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_synced+0x7c zil_commit+0x416 zfs_sync+0xa6 sync_fsync+0x184 sync_vnode+0x16b sched_sync+0x1c9 fork_exit+0x118 fork_trampoline+0xe 2210 100156 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 3500 100177 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 3783 100056 syslogd -mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 zfs_freebsd_write+0x378 VOP_WRITE_APV+0xb2 vn_write+0x2d7 dofilewrite+0x85 kern_writev+0x60 writev+0x41 syscall+0x1e7 Xfast_syscall+0xe1 4064 100165 mysqld initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 closef+0x3b kern_close+0x14d syscall+0x1e7 Xfast_syscall+0xe1 4441 100224 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 100227 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d null_inactive+0x1f vinactive+0x6a vputx+0x1cc vn_close+0xa1 vn_closefile+0x5a _fdrop+0x23 4445 100228 python2.6initial thread mi_switch+0x16f sleepq_wait+0x42 _cv_wait+0x111 txg_wait_open+0x85 dmu_tx_assign+0x16c zfs_inactive+0xd9 zfs_freebsd_inactive+0x1a vinactive+0x6a vputx+0x1cc null_reclaim+0xbc vgonel+0x12e vrecycle+0x7d
Re: 8.1R ZFS almost locking up system
On 2010-Aug-21 23:04:35 +0100, Tim Bishop t...@bishnet.net wrote: I've had a problem on a FreeBSD 8.1R system for a few weeks. It seems that ZFS gets in to an almost unresponsive state. Last time it did it (two weeks ago) I couldn't even log in, although the system was up, this time I could manage a reboot but couldn't stop any applications (they were likely hanging on I/O). Unless you have a ZFS-only system, it's possible you are running out of free memory (see the free entry in top(1) or 'systat -v') - in which case r211581 (and r211599 which fixes a mismerge) should help. Your very high kstat.zfs.misc.arcstats.memory_throttle_count suggests this is your problem. I have a more extensive patch in http://www.freebsd.org/cgi/query-pr.cgi?pr=146410 -- Peter Jeremy pgpVn6Q2Ml3YY.pgp Description: PGP signature
Re: 8.1R ZFS almost locking up system
On Sat, Aug 21, 2010 at 05:24:29PM -0500, Dan Nelson wrote: In the last episode (Aug 21), Tim Bishop said: I've had a problem on a FreeBSD 8.1R system for a few weeks. It seems that ZFS gets in to an almost unresponsive state. Last time it did it (two weeks ago) I couldn't even log in, although the system was up, this time I could manage a reboot but couldn't stop any applications (they were likely hanging on I/O). Could your pool be very close to full? Zfs will throttle itself when it's almost out of disk space. I know it's saved me from filling up my filesystems a couple times :) It's not close to full, so I don't think that's the issue. A few items from top, including zfskern: PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 5 root4 -8- 0K60K zio-i 0 54:38 3.47% zfskern 91775 70 1 440 53040K 31144K tx-tx 1 2:11 0.00% postgres 39661 tdb 1 440 55776K 32968K tx-tx 0 0:39 0.00% mutt 14828 root1 470 14636K 1572K tx-tx 1 0:03 0.00% zfs 11188 root1 510 14636K 1572K tx-tx 0 0:03 0.00% zfs At some point during this process my zfs snapshots have been failing to complete: root5 0.8 0.0 060 ?? DL7Aug10 54:43.83 [zfskern] root 8265 0.0 0.0 14636 1528 ?? D10:00AM 0:03.12 zfs snapshot -r po...@2010-08-21_10:00:01--1d root11188 0.0 0.1 14636 1572 ?? D11:00AM 0:02.93 zfs snapshot -r po...@2010-08-21_11:00:01--1d root14828 0.0 0.1 14636 1572 ?? D12:00PM 0:03.04 zfs snapshot -r po...@2010-08-21_12:00:00--1d root17862 0.0 0.1 14636 1572 ?? D 1:00PM 0:01.96 zfs snapshot -r po...@2010-08-21_13:00:01--1d root20986 0.0 0.1 14636 1572 ?? D 2:00PM 0:02.07 zfs snapshot -r po...@2010-08-21_14:00:01--1d procstat -k on some of these processes might help to pinpoint what part of the zfs code they're all waiting in. I'll do that. Thanks for the pointer :-) Tim. -- Tim Bishop http://www.bishnet.net/tim/ PGP Key: 0x5AE7D984 ___ freebsd-stable@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-stable To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org
Re: 8.1R ZFS almost locking up system
On Tue, Aug 24, 2010 at 06:49:23AM +1000, Peter Jeremy wrote: On 2010-Aug-21 23:04:35 +0100, Tim Bishop t...@bishnet.net wrote: I've had a problem on a FreeBSD 8.1R system for a few weeks. It seems that ZFS gets in to an almost unresponsive state. Last time it did it (two weeks ago) I couldn't even log in, although the system was up, this time I could manage a reboot but couldn't stop any applications (they were likely hanging on I/O). Unless you have a ZFS-only system, it's possible you are running out of free memory (see the free entry in top(1) or 'systat -v') - in which case r211581 (and r211599 which fixes a mismerge) should help. Your very high kstat.zfs.misc.arcstats.memory_throttle_count suggests this is your problem. Thanks. At the time I had a reasonable amount free (~450MB from 3GB), but it had dropped lower than that at some points previously. I'll take a closer look at that next time, and look at that patch (or upgrade to 8-STABLE). And the system has a UFS root, but all the apps/data are stored in ZFS. Tim. -- Tim Bishop http://www.bishnet.net/tim/ PGP Key: 0x5AE7D984 ___ freebsd-stable@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-stable To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org
8.1R ZFS almost locking up system
I've had a problem on a FreeBSD 8.1R system for a few weeks. It seems that ZFS gets in to an almost unresponsive state. Last time it did it (two weeks ago) I couldn't even log in, although the system was up, this time I could manage a reboot but couldn't stop any applications (they were likely hanging on I/O). Here's some details I collected prior to reboot. The zpool output, including iostat and gstat for the disks: # zpool status pool: pool0 state: ONLINE scrub: none requested config: NAMESTATE READ WRITE CKSUM pool0 ONLINE 0 0 0 mirrorONLINE 0 0 0 ad4s3 ONLINE 0 0 0 ad6s3 ONLINE 0 0 0 errors: No known data errors # zpool iostat -v 5 ... capacity operationsbandwidth pool used avail read write read write -- - - - - - - pool0117G 16.7G248114 865K 269K mirror 117G 16.7G248114 865K 269K ad4s3 - - 43 56 2.47M 269K ad6s3 - - 39 56 2.41M 269K -- - - - - - - # gstat ... L(q) ops/sr/s kBps ms/rw/s kBps ms/w %busy Name 1 48 48 30429.8 0 00.0 47.6| ad4 0 38 38 2406 10.5 0 00.0 39.5| ad6 0 0 0 00.0 0 00.00.0| ad4s1 0 0 0 00.0 0 00.00.0| ad4s2 1 48 48 30429.8 0 00.0 47.6| ad4s3 0 0 0 00.0 0 00.00.0| ad6s1 0 0 0 00.0 0 00.00.0| ad6s2 0 38 38 2406 11.8 0 00.0 44.4| ad6s3 I've seen this before when I've had poor ZFS performance. There's more I/O on the disks than on the pool itself. It's not particularly busy though. A few items from top, including zfskern: PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 5 root4 -8- 0K60K zio-i 0 54:38 3.47% zfskern 91775 70 1 440 53040K 31144K tx-tx 1 2:11 0.00% postgres 39661 tdb 1 440 55776K 32968K tx-tx 0 0:39 0.00% mutt 14828 root1 470 14636K 1572K tx-tx 1 0:03 0.00% zfs 11188 root1 510 14636K 1572K tx-tx 0 0:03 0.00% zfs At some point during this process my zfs snapshots have been failing to complete: root5 0.8 0.0 060 ?? DL7Aug10 54:43.83 [zfskern] root 8265 0.0 0.0 14636 1528 ?? D10:00AM 0:03.12 zfs snapshot -r po...@2010-08-21_10:00:01--1d root11188 0.0 0.1 14636 1572 ?? D11:00AM 0:02.93 zfs snapshot -r po...@2010-08-21_11:00:01--1d root14828 0.0 0.1 14636 1572 ?? D12:00PM 0:03.04 zfs snapshot -r po...@2010-08-21_12:00:00--1d root17862 0.0 0.1 14636 1572 ?? D 1:00PM 0:01.96 zfs snapshot -r po...@2010-08-21_13:00:01--1d root20986 0.0 0.1 14636 1572 ?? D 2:00PM 0:02.07 zfs snapshot -r po...@2010-08-21_14:00:01--1d It all seems to point at ZFS getting to the point of being almost unresponsive. It's been exactly two weeks since the last time this happened and therefore the last reboot, so it'll be interesting to see if the same happens again after the same period of time. I noticed this given in a few other ZFS related messages: vfs.worklist_len: 15 I have attached all (hopefully) ZFS-related sysctl output. Finally, the reboot log: Aug 21 22:13:06 server kernel: Aug 21 22:13:06 server reboot: rebooted by tdb Aug 21 22:19:47 server kernel: Waiting (max 60 seconds) for system process `vnlru' to stop...done Aug 21 22:19:47 server kernel: Waiting (max 60 seconds) for system process `bufdaemon' to stop... Aug 21 22:19:48 server kernel: done Aug 21 22:19:48 server kernel: Waiting (max 60 seconds) for system process `syncer' to stop... Aug 21 22:20:03 server kernel: Aug 21 22:20:03 server kernel: Syncing disks, vnodes remaining...14 Aug 21 22:20:48 server kernel: timed out Aug 21 22:21:55 server kernel: Waiting (max 60 seconds) for system process `vnlru' to stop... Aug 21 22:22:39 server kernel: 1 Aug 21 22:22:55 server kernel: timed out Aug 21 22:22:55 server kernel: Waiting (max 60 seconds) for system process `bufdaemon' to stop... I've undoubtedly missed some important information, so please let me know if there's anything more useful I can collect next time (I'm quite sure it'll happen again). Thanks, Tim. -- Tim Bishop http://www.bishnet.net/tim/ PGP Key: 0x5AE7D984 vfs.zfs.l2c_only_size: 0 vfs.zfs.mfu_ghost_data_lsize: 40245248 vfs.zfs.mfu_ghost_metadata_lsize: 87331328 vfs.zfs.mfu_ghost_size: 127576576 vfs.zfs.mfu_data_lsize: 99885056 vfs.zfs.mfu_metadata_lsize: 146944 vfs.zfs.mfu_size: 101330432 vfs.zfs.mru_ghost_data_lsize: 181200896 vfs.zfs.mru_ghost_metadata_lsize: 25819648
Re: 8.1R ZFS almost locking up system
In the last episode (Aug 21), Tim Bishop said: I've had a problem on a FreeBSD 8.1R system for a few weeks. It seems that ZFS gets in to an almost unresponsive state. Last time it did it (two weeks ago) I couldn't even log in, although the system was up, this time I could manage a reboot but couldn't stop any applications (they were likely hanging on I/O). Could your pool be very close to full? Zfs will throttle itself when it's almost out of disk space. I know it's saved me from filling up my filesystems a couple times :) A few items from top, including zfskern: PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 5 root4 -8- 0K60K zio-i 0 54:38 3.47% zfskern 91775 70 1 440 53040K 31144K tx-tx 1 2:11 0.00% postgres 39661 tdb 1 440 55776K 32968K tx-tx 0 0:39 0.00% mutt 14828 root1 470 14636K 1572K tx-tx 1 0:03 0.00% zfs 11188 root1 510 14636K 1572K tx-tx 0 0:03 0.00% zfs At some point during this process my zfs snapshots have been failing to complete: root5 0.8 0.0 060 ?? DL7Aug10 54:43.83 [zfskern] root 8265 0.0 0.0 14636 1528 ?? D10:00AM 0:03.12 zfs snapshot -r po...@2010-08-21_10:00:01--1d root11188 0.0 0.1 14636 1572 ?? D11:00AM 0:02.93 zfs snapshot -r po...@2010-08-21_11:00:01--1d root14828 0.0 0.1 14636 1572 ?? D12:00PM 0:03.04 zfs snapshot -r po...@2010-08-21_12:00:00--1d root17862 0.0 0.1 14636 1572 ?? D 1:00PM 0:01.96 zfs snapshot -r po...@2010-08-21_13:00:01--1d root20986 0.0 0.1 14636 1572 ?? D 2:00PM 0:02.07 zfs snapshot -r po...@2010-08-21_14:00:01--1d procstat -k on some of these processes might help to pinpoint what part of the zfs code they're all waiting in. -- Dan Nelson dnel...@allantgroup.com ___ freebsd-stable@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-stable To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org
