From owner-freebsd-fs@FreeBSD.ORG Tue Jan 15 01:37:31 2013 Return-Path: Delivered-To: freebsd-fs@freebsd.org Received: from mx1.freebsd.org (mx1.FreeBSD.org [8.8.178.115]) by hub.freebsd.org (Postfix) with ESMTP id E113CA3E for ; Tue, 15 Jan 2013 01:37:31 +0000 (UTC) (envelope-from artemb@gmail.com) Received: from mail-vc0-f172.google.com (mail-vc0-f172.google.com [209.85.220.172]) by mx1.freebsd.org (Postfix) with ESMTP id 902F7A54 for ; Tue, 15 Jan 2013 01:37:31 +0000 (UTC) Received: by mail-vc0-f172.google.com with SMTP id fw7so4210442vcb.31 for ; Mon, 14 Jan 2013 17:37:25 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:sender:in-reply-to:references:date :x-google-sender-auth:message-id:subject:from:to:cc:content-type :content-transfer-encoding; bh=ERJqw0lCTNCaIJYj1D/i06oFPviy76eK8ykVyi7zL5g=; b=pCgjNYjD/Kek39O97JLEWbnDnHpxYik7sZXMyZYI7YqzZ0nZGOdFDvMZsTseoeYSKR mftYEdOeGZKTSTltO9nXsXhP5VlOVis02sFju7NttLm+Kmg3mdjWwhf233+GCiuMEjRk fgB5TGr9JBMcXj9Z++EJxpjKu+NjjuV/xdzOU9a7pxODIwqz/nIbfAi3SRPl1OfEQNuQ Dx6Nx6yUtmQCPxyCh8XnB3dRTnhWNiokp/MJoyIEAp5UD7OEbxFx6UPHvuauH41E+XZz BCG9e0941iRSaQ+7QTuu/kRn5+oAi0Qk6ovlUwvUnSRCdN5HIiOt9STnbeVf3M7ikrPG Otng== MIME-Version: 1.0 Received: by 10.52.180.200 with SMTP id dq8mr90147517vdc.71.1358213845191; Mon, 14 Jan 2013 17:37:25 -0800 (PST) Sender: artemb@gmail.com Received: by 10.220.122.196 with HTTP; Mon, 14 Jan 2013 17:37:25 -0800 (PST) In-Reply-To: <20130114214652.GA76779@mid.pc5.i.0x5.de> References: <20130109162613.GA34276@mid.pc5.i.0x5.de> <20130110193949.GA10023@mid.pc5.i.0x5.de> <20130111073417.GA95100@mid.pc5.i.0x5.de> <20130114094010.GA75529@mid.pc5.i.0x5.de> <20130114195148.GA20540@mid.pc5.i.0x5.de> <20130114214652.GA76779@mid.pc5.i.0x5.de> Date: Mon, 14 Jan 2013 17:37:25 -0800 X-Google-Sender-Auth: ooDSOCBbgBRv9mcQWqd_AE-gd9U Message-ID: Subject: Re: slowdown of zfs (tx->tx) From: Artem Belevich To: Nicolas Rachinsky Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Cc: freebsd-fs X-BeenThere: freebsd-fs@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: Filesystems List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 15 Jan 2013 01:37:31 -0000 On Mon, Jan 14, 2013 at 1:46 PM, Nicolas Rachinsky wrote: > * Artem Belevich [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 > 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