From owner-freebsd-fs@FreeBSD.ORG Mon Jan 14 20:41:03 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 73244162 for ; Mon, 14 Jan 2013 20:41:03 +0000 (UTC) (envelope-from artemb@gmail.com) Received: from mail-vb0-f51.google.com (mail-vb0-f51.google.com [209.85.212.51]) by mx1.freebsd.org (Postfix) with ESMTP id 1772D92F for ; Mon, 14 Jan 2013 20:41:02 +0000 (UTC) Received: by mail-vb0-f51.google.com with SMTP id fq11so4047416vbb.10 for ; Mon, 14 Jan 2013 12:41:02 -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=XQIM1nDAEmRY7MDfEhauYCWiozqZHx65EbRdswFhdJE=; b=wK7sZLleTAtTH9cg7amqFyKXAFSxIbuYUvjARznHHQ81hypaT8UfmmToSCsNi4BqXr r14C9VrhOJLPqjpc34CnRo0e1ujXP1lxgHF2R9oQvLP4wBDFOFgdYV1+hyRedEmp4DV9 5vPVIIesiLyhe3DySZnUP2uS5oMAF5M5YdfjM0hLiMxoBCufSATVDbSD2V3u+geBz4iT 8FvEaohBpAyaAvQGQec2PDi+hsovSb3uRLsdhqno9xMTx7jxVIDIwzI9GL1Dg0PWM0jI 2dWi8k/juPcZx9jBfhOSTzsH7U5sfznghfIHtrYzAqCSKXuMM40h0QfKiwWPf2fiMgYe r/ig== MIME-Version: 1.0 Received: by 10.52.156.40 with SMTP id wb8mr90499872vdb.39.1358196062075; Mon, 14 Jan 2013 12:41:02 -0800 (PST) Sender: artemb@gmail.com Received: by 10.220.122.196 with HTTP; Mon, 14 Jan 2013 12:41:01 -0800 (PST) In-Reply-To: <20130114195148.GA20540@mid.pc5.i.0x5.de> References: <20130108174225.GA17260@mid.pc5.i.0x5.de> <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> Date: Mon, 14 Jan 2013 12:41:01 -0800 X-Google-Sender-Auth: g2rKpwHkwJdoYdnres2GBFw2hCM 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: Mon, 14 Jan 2013 20:41:03 -0000 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 proces= s. --Artem On Mon, Jan 14, 2013 at 11:51 AM, Nicolas Rachinsky wrote: > * Artem Belevich [2013-01-14 11:13 -0800]: >> On Mon, Jan 14, 2013 at 1:40 AM, Nicolas Rachinsky >> wrote: >> > 5 Reallocated_Sector_Ct 0x0033 094 094 010 Pre-fail Alwa= ys - 166 >> > 195 Hardware_ECC_Recovered 0x001a 100 100 000 Old_age Alwa= ys - 1259614646 >> > 196 Reallocated_Event_Count 0x0032 096 096 000 Old_age Alwa= ys - 166 >> >> > Reallocated_Sector_Ct did not increase during the last days. >> >> It does not matter IMHO. That hard drive already got quite a few bad >> sectors that ECC could not deal with. There are apparently more >> marginally bad sectors, but ECC deals with it for now. Once enough >> bits rot, you'll get more bad sectors. I personally would replace the >> drive. > > Yes, I'll do that. > >> >> Cound you do gstat with 1-second interval. Some of the 5-second >> >> samples show that ada8 is the bottleneck -- it has its request queue >> >> full (L(q)=3D10) when all other drives were done with their jobs. And >> >> that's a 5-sec average. Its write service time also seems to be a lot >> >> higher than for other drives. >> > >> > Attached. I have replace ada8 by ada9, which is a Western Digital >> > Caviar Black. >> > >> > Now ada0 and ada4 seem to be the bottleneck. >> > >> > But I don't understand the intervalls without any disk activity. >> >> It is puzzling. Is rsync still sleeping in tx->tx state? Try running >> "procstat -kk " periodically. It will print in-kernel stack >> trace and may help giving a clue where/why rsync is stuck. > > # sh -c 'for i in `jot 100`; do procstat -kk 36639 ; sleep 1; done' | sor= t | uniq -c > 100 PID TID COMM TDNAME KSTACK > 1 36639 100574 rsync - > 99 36639 100574 rsync - mi_switch+0x176 sleep= q_wait+0x42 _cv_wait+0x129 txg_wait_open+0x85 zfs_freebsd_write+0x3a6 VOP_W= RITE_APV+0xb2 vn_write+0x373 dofilewrite+0x8b kern_writev+0x60 write+0x55 a= md64_syscall+0x1f4 Xfast_syscall+0xfc > > # sh -c 'for i in `jot 100`; do procstat -kk 36639 ; sleep 0.36; done' | = sort | uniq -c > 100 PID TID COMM TDNAME KSTACK > 1 36639 100574 rsync - mi_switch+0x176 sleep= q_timedwait+0x42 _cv_timedwait+0x134 txg_delay+0x137 dsl_pool_tempreserve_s= pace+0xd5 dsl_dir_tempreserve_space+0x154 dmu_tx_assign+0x370 zfs_freebsd_w= rite+0x38a VOP_WRITE_APV+0xb2 vn_write+0x373 dofilewrite+0x8b kern_writev+0= x60 write+0x55 amd64_syscall+0x1f4 Xfast_syscall+0xfc > 99 36639 100574 rsync - mi_switch+0x176 sleep= q_wait+0x42 _cv_wait+0x129 txg_wait_open+0x85 zfs_freebsd_write+0x3a6 VOP_W= RITE_APV+0xb2 vn_write+0x373 dofilewrite+0x8b kern_writev+0x60 write+0x55 a= md64_syscall+0x1f4 Xfast_syscall+0xfc > > # sh -c 'for i in `jot 100`; do procstat -kk 36639 ; sleep 0.1; done' | s= ort | uniq -c > 100 PID TID COMM TDNAME KSTACK > 100 36639 100574 rsync - mi_switch+0x176 sleep= q_wait+0x42 _cv_wait+0x129 txg_wait_open+0x85 zfs_freebsd_write+0x3a6 VOP_W= RITE_APV+0xb2 vn_write+0x373 dofilewrite+0x8b kern_writev+0x60 write+0x55 a= md64_syscall+0x1f4 Xfast_syscall+0xfc > > > Thanks in advance > > Nicolas > > -- > http://www.rachinsky.de/nicolas