Date: Mon, 14 Jan 2013 17:37:25 -0800 From: Artem Belevich <art@freebsd.org> To: Nicolas Rachinsky <fbsd-mas-0@ml.turing-complete.org> Cc: freebsd-fs <freebsd-fs@freebsd.org> Subject: Re: slowdown of zfs (tx->tx) Message-ID: <CAFqOu6jKX-Ks6C1RK5GwZ51ZVUSnGSe7S99_EfK%2BfwLPjAFFYw@mail.gmail.com> In-Reply-To: <20130114214652.GA76779@mid.pc5.i.0x5.de> References: <CAFqOu6jgA8RWV5d%2BrOBk8D=3Vu3yWSnDkAi1cFJ0esj4OpBy2Q@mail.gmail.com> <20130109162613.GA34276@mid.pc5.i.0x5.de> <CAFqOu6jrng=v8eVyhqV-PBqJM_dYy%2BU7X4%2B=ahBeoxvK4mxcSA@mail.gmail.com> <20130110193949.GA10023@mid.pc5.i.0x5.de> <20130111073417.GA95100@mid.pc5.i.0x5.de> <CAFqOu6gWpMsWN0pTBiv10WfwyGWMfO9GzMLWTtcVxHixr-_i3Q@mail.gmail.com> <20130114094010.GA75529@mid.pc5.i.0x5.de> <CAFqOu6hxfGt_M6Jo9qWeifDz9YnNc_Bd9H-GEe4RYtutaPvH5w@mail.gmail.com> <20130114195148.GA20540@mid.pc5.i.0x5.de> <CAFqOu6jwJ4qhbOovN_NhzusdQJvrbvUC3g93sziR=Uw99SGenw@mail.gmail.com> <20130114214652.GA76779@mid.pc5.i.0x5.de>
next in thread | previous in thread | raw e-mail | index | archive | help
On Mon, Jan 14, 2013 at 1:46 PM, Nicolas Rachinsky <fbsd-mas-0@ml.turing-complete.org> wrote: > * Artem Belevich <art@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 pro= cess. > > # sh -c 'for i in `jot 1000`; do procstat -kk 47 ; sleep 0.1; done' | sor= t | uniq -c > 1000 47 100083 zfskern arc_reclaim_thre mi_switch+0x176 sleep= q_timedwait+0x42 _cv_timedwait+0x134 arc_reclaim_thread+0x29d fork_exit+0x1= 1f fork_trampoline+0xe > 1000 47 100084 zfskern l2arc_feed_threa mi_switch+0x176 sleep= q_timedwait+0x42 _cv_timedwait+0x134 l2arc_feed_thread+0x1a8 fork_exit+0x11= f fork_trampoline+0xe > 1000 47 100224 zfskern txg_thread_enter mi_switch+0x176 sleep= q_wait+0x42 _cv_wait+0x129 txg_thread_wait+0x79 txg_quiesce_thread+0xb5 for= k_exit+0x11f fork_trampoline+0xe > 165 47 100225 zfskern txg_thread_enter <running> > 1 47 100225 zfskern txg_thread_enter mi_switch+0x176 sleep= q_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+0x67= 5 dnode_hold_impl+0xf2 dmu_buf_hold_array+0x38 dmu_write+0x53 space_map_syn= c+0x1ff metaslab_sync+0x13e vdev_sync+0x6e spa_sync+0x3ab txg_sync_thread+0= x139 > 1 47 100225 zfskern txg_thread_enter mi_switch+0x176 sleep= q_wait+0x42 _cv_wait+0x129 zio_wait+0x61 dbuf_read+0x5e5 dbuf_will_dirty+0x= 60 dmu_write+0x82 space_map_sync+0x1ff metaslab_sync+0x13e vdev_sync+0x6e s= pa_sync+0x3ab txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe > 1 47 100225 zfskern txg_thread_enter mi_switch+0x176 sleep= q_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 sleep= q_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 sleep= q_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 sleep= q_wait+0x42 _cv_wait+0x129 zio_wait+0x61 spa_sync+0x286 txg_sync_thread+0x1= 39 fork_exit+0x11f fork_trampoline+0xe > 2 47 100225 zfskern txg_thread_enter mi_switch+0x176 sleep= q_wait+0x42 _cv_wait+0x129 zio_wait+0x61 spa_sync+0x370 txg_sync_thread+0x1= 39 fork_exit+0x11f fork_trampoline+0xe > 21 47 100225 zfskern txg_thread_enter mi_switch+0x176 sleep= q_wait+0x42 _cv_wait+0x129 zio_wait+0x61 vdev_config_sync+0xe3 spa_sync+0x4= 9a txg_sync_thread+0x139 fork_exit+0x11f fork_trampoline+0xe > 5 47 100225 zfskern txg_thread_enter mi_switch+0x176 sleep= q_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 for= k_trampoline+0xe > 1000 PID TID COMM TDNAME KSTACK OK. threads responsible for transaction sync seem to be stuck in zio_wait. zio_wait is in turn waiting for some task thread to be done with its work. Now you need to figure out what are those task threads doing. 'procstat -kk 0' will dump few hundreds of taskq threads. Most of them would be zfs related. On an idle box (8.3/amd64 in my case) most of them would have the same stack trace looking like this (modulo offsets): mi_switch+0x196 sleepq_wait+0x42 _sleep+0x3c0 taskqueue_thread_loop+0xbe fork_exit+0x11f fork_trampoline+0xe Look for stack traces that don't match that pattern. --Artem
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAFqOu6jKX-Ks6C1RK5GwZ51ZVUSnGSe7S99_EfK%2BfwLPjAFFYw>