slowdown of zfs (tx->tx)

[Nicolas Rachinsky]

* Artem Belevich <art at freebsd.org> [2013-01-14 12:41 -0800]:
> txg_wait_open means that ZFS is waiting for ongoing transaction group
> sync. There should've been some write activity in this case.
> 
> Check what zfs kernel threads are doing with procstat -kk on zfskern process.

# sh -c 'for i in `jot 1000`; do procstat -kk 47 ; sleep 0.1; done' | sort | uniq -c
1000    47 100083 zfskern          arc_reclaim_thre mi_switch+0x176 sleepq_timedwait+0x42 _cv_timedwait+0x134 arc_reclaim_thread+0x29d fork_exit+0x11f fork_trampoline+0xe 
1000    47 100084 zfskern          l2arc_feed_threa mi_switch+0x176 sleepq_timedwait+0x42 _cv_timedwait+0x134 l2arc_feed_thread+0x1a8 fork_exit+0x11f fork_trampoline+0xe 
1000    47 100224 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 txg_thread_wait+0x79 txg_quiesce_thread+0xb5 fork_exit+0x11f fork_trampoline+0xe 
 165    47 100225 zfskern          txg_thread_enter <running>                    
   1    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 dbuf_read+0x5e5 dbuf_findbp+0x107 dbuf_prefetch+0x8f dmu_zfetch_dofetch+0x10b dmu_zfetch+0xaf8 dbuf_read+0x675 dnode_hold_impl+0xf2 dmu_buf_hold_array+0x38 dmu_write+0x53 space_map_sync+0x1ff metaslab_sync+0x13e vdev_sync+0x6e spa_sync+0x3ab txg_sync_thread+0x139 
   1    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 dbuf_read+0x5e5 dbuf_will_dirty+0x60 dmu_write+0x82 space_map_sync+0x1ff metaslab_sync+0x13e vdev_sync+0x6e spa_sync+0x3ab txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe 
   1    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 dsl_pool_sync+0x189 spa_sync+0x336 txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe 
  81    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 dsl_pool_sync+0x2c3 spa_sync+0x336 txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe 
 719    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 dsl_pool_sync+0xe0 spa_sync+0x336 txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe 
   4    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 spa_sync+0x286 txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe 
   2    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 spa_sync+0x370 txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe 
  21    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 vdev_config_sync+0xe3 spa_sync+0x49a txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe 
   5    47 100225 zfskern          txg_thread_enter mi_switch+0x176 sleepq_wait+0x42 _cv_wait+0x129 zio_wait+0x61 vdev_uberblock_sync_list+0xd0 vdev_config_sync+0x10f spa_sync+0x49a txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe 
1000   PID    TID COMM             TDNAME           KSTACK               

Thanks
Nicolas
-- 
http://www.rachinsky.de/nicolas