From owner-freebsd-fs@FreeBSD.ORG Thu Apr 11 16:59:11 2013 Return-Path: Delivered-To: freebsd-fs@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by hub.freebsd.org (Postfix) with ESMTP id C28E7DFC for ; Thu, 11 Apr 2013 16:59:11 +0000 (UTC) (envelope-from nowakpl@platinum.linux.pl) Received: from platinum.linux.pl (platinum.edu.pl [81.161.192.4]) by mx1.freebsd.org (Postfix) with ESMTP id 6A738A0C for ; Thu, 11 Apr 2013 16:59:10 +0000 (UTC) Received: by platinum.linux.pl (Postfix, from userid 87) id 2CB5C47E29; Thu, 11 Apr 2013 18:52:37 +0200 (CEST) X-Spam-Checker-Version: SpamAssassin 3.3.2 (2011-06-06) on platinum.linux.pl X-Spam-Level: X-Spam-Status: No, score=-1.3 required=3.0 tests=ALL_TRUSTED,AWL autolearn=disabled version=3.3.2 Received: from [10.255.1.2] (unknown [83.151.38.73]) by platinum.linux.pl (Postfix) with ESMTPA id 9D78F47E24 for ; Thu, 11 Apr 2013 18:52:37 +0200 (CEST) Message-ID: <5166EA43.7050700@platinum.linux.pl> Date: Thu, 11 Apr 2013 18:52:19 +0200 From: Adam Nowacki User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:17.0) Gecko/20130328 Thunderbird/17.0.5 MIME-Version: 1.0 To: freebsd-fs@freebsd.org Subject: ZFS slow reads for unallocated blocks Content-Type: text/plain; charset=ISO-8859-2; format=flowed Content-Transfer-Encoding: 7bit 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: Thu, 11 Apr 2013 16:59:11 -0000 This one is quite weird - reads from files that were created and resized with ftruncate (so no actual data on disk) are considerably slower and use more CPU time than files with data. If compression is enabled this will also affect files with long runs of zeroes as ZFS won't write any data to disk in this case. There is no I/O on the pool during the read tests - all fits into 10GB ARC. FreeBSD storage 9.1-RELEASE FreeBSD 9.1-RELEASE #0: Sat Feb 23 15:51:26 UTC 2013 root@storage:/usr/obj/usr/src/sys/GENERIC amd64 Mem: 264M Active, 82M Inact, 12G Wired, 100M Cache, 13M Buf, 3279M Free Swap: 5120M Total, 5120M Free # zfs create -o atime=off -o recordsize=128k -o compression=off -o mountpoint=/home/testfs home/testfs --- truncated file: # time truncate -s 1G /home/testfs/trunc1g 0.000u 0.000s 0:00.00 0.0% 0+0k 0+0io 0pf+0w # time dd if=/home/testfs/trunc1g of=/dev/null bs=1024k 1024+0 records in 1024+0 records out 1073741824 bytes transferred in 0.434817 secs (2469410435 bytes/sec) 0.000u 0.435s 0:00.43 100.0% 26+2813k 0+0io 0pf+0w # time dd if=/home/testfs/trunc1g of=/dev/null bs=16k 65536+0 records in 65536+0 records out 1073741824 bytes transferred in 3.809560 secs (281854564 bytes/sec) 0.000u 3.779s 0:03.81 98.9% 25+2755k 0+0io 0pf+0w # time cat /home/testfs/trunc1g > /dev/null 0.070u 14.031s 0:14.19 99.3% 15+2755k 0+0io 0pf+0w ^^^^^^^ 14 seconds compared to 1 second for random data --- file filled with zeroes: # time dd if=/dev/zero of=/home/testfs/zero1g bs=1024k count=1024 1024+0 records in 1024+0 records out 1073741824 bytes transferred in 2.375426 secs (452020732 bytes/sec) 0.000u 0.525s 0:02.37 21.9% 23+2533k 1+1io 0pf+0w # time dd if=/home/testfs/zero1g of=/dev/null bs=1024k 1024+0 records in 1024+0 records out 1073741824 bytes transferred in 0.199078 secs (5393571244 bytes/sec) 0.000u 0.200s 0:00.20 100.0% 26+2808k 0+0io 0pf+0w # time dd if=/home/testfs/zero1g of=/dev/null bs=16k 65536+0 records in 65536+0 records out 1073741824 bytes transferred in 0.436472 secs (2460046434 bytes/sec) 0.015u 0.421s 0:00.43 100.0% 26+2813k 0+0io 0pf+0w # time cat /home/testfs/zero1g > /dev/null 0.023u 1.156s 0:01.18 99.1% 15+2779k 0+0io 0pf+0w --- file filled with random bytes: # time dd if=/dev/random of=/home/testfs/random1g bs=1024k count=1024 1024+0 records in 1024+0 records out 1073741824 bytes transferred in 16.116569 secs (66623474 bytes/sec) 0.000u 13.214s 0:16.11 81.9% 25+2750k 0+1io 0pf+0w # time dd if=/home/testfs/random1g of=/dev/null bs=1024k 1024+0 records in 1024+0 records out 1073741824 bytes transferred in 0.207115 secs (5184280044 bytes/sec) 0.000u 0.208s 0:00.20 100.0% 26+2808k 0+0io 0pf+0w # time dd if=/home/testfs/random1g of=/dev/null bs=16k 65536+0 records in 65536+0 records out 1073741824 bytes transferred in 0.432518 secs (2482536705 bytes/sec) 0.023u 0.409s 0:00.43 97.6% 26+2828k 0+0io 0pf+0w # time cat /home/testfs/random1g > /dev/null 0.031u 1.053s 0:01.08 100.0% 15+2770k 0+0io 0pf+0w --- compression on: # zfs create -o atime=off -o recordsize=128k -o compression=lzjb -o mountpoint=/home/testfs home/testfs --- file filled with zeroes: # time dd if=/dev/zero of=/home/testfs/zero1g bs=1024k count=1024 1024+0 records in 1024+0 records out 1073741824 bytes transferred in 1.007765 secs (1065468404 bytes/sec) 0.000u 0.458s 0:01.01 44.5% 26+2880k 1+1io 0pf+0w # time dd if=/home/testfs/zero1g of=/dev/null bs=1024k 1024+0 records in 1024+0 records out 1073741824 bytes transferred in 0.630737 secs (1702360431 bytes/sec) 0.000u 0.630s 0:00.63 100.0% 25+2742k 0+0io 0pf+0w # time dd if=/home/testfs/zero1g of=/dev/null bs=16k 65536+0 records in 65536+0 records out 1073741824 bytes transferred in 4.089175 secs (262581530 bytes/sec) 0.015u 4.036s 0:04.09 98.7% 25+2758k 0+0io 0pf+0w # time cat /home/testfs/zero1g > /dev/null 0.031u 15.863s 0:15.95 99.6% 15+2754k 0+0io 0pf+0w ^^^^^^^ --- it appears recordsize has a huge effect on this (recordsize=32k): # zfs create -o atime=off -o recordsize=32k -o compression=off -o mountpoint=/home/testfs home/testfs # time truncate -s 1G testfs/trunc1g 0.000u 0.000s 0:00.01 0.0% 0+0k 1+0io 0pf+0w # time cat /home/testfs/trunc1g > /dev/null 0.047u 5.842s 0:05.93 99.1% 15+2761k 0+0io 0pf+0w ^^^^^^ --- recordsize=4k: # zfs create -o atime=off -o recordsize=4k -o compression=off -o mountpoint=/home/testfs home/testfs # time truncate -s 1G testfs/trunc1g 0.000u 0.000s 0:00.00 0.0% 0+0k 0+0io 0pf+0w # time cat /home/testfs/trunc1g > /dev/null 0.047u 1.441s 0:01.52 97.3% 15+2768k 0+0io 0pf+0w ^^^^^^