From patchwork Thu Jun 4 03:52:02 2015 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Wen Congyang X-Patchwork-Id: 480354 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from lists.gnu.org (lists.gnu.org [IPv6:2001:4830:134:3::11]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (No client certificate requested) by ozlabs.org (Postfix) with ESMTPS id C94301401F6 for ; Thu, 4 Jun 2015 13:48:39 +1000 (AEST) Received: from localhost ([::1]:40040 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Z0M8x-0006nx-H2 for incoming@patchwork.ozlabs.org; Wed, 03 Jun 2015 23:48:35 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:38283) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Z0M8i-0006Vb-2w for qemu-devel@nongnu.org; Wed, 03 Jun 2015 23:48:21 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Z0M8e-00053f-Rn for qemu-devel@nongnu.org; Wed, 03 Jun 2015 23:48:20 -0400 Received: from [59.151.112.132] (port=61205 helo=heian.cn.fujitsu.com) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Z0M8Y-000504-OK for qemu-devel@nongnu.org; Wed, 03 Jun 2015 23:48:16 -0400 X-IronPort-AV: E=Sophos;i="5.01,1,1399996800"; d="scan'208";a="96421513" Received: from unknown (HELO edo.cn.fujitsu.com) ([10.167.33.5]) by heian.cn.fujitsu.com with ESMTP; 04 Jun 2015 11:52:16 +0800 Received: from G08CNEXCHPEKD02.g08.fujitsu.local (localhost.localdomain [127.0.0.1]) by edo.cn.fujitsu.com (8.14.3/8.13.1) with ESMTP id t543kNQi002538; Thu, 4 Jun 2015 11:46:24 +0800 Received: from [10.167.226.52] (10.167.226.52) by G08CNEXCHPEKD02.g08.fujitsu.local (10.167.33.89) with Microsoft SMTP Server id 14.3.181.6; Thu, 4 Jun 2015 11:47:53 +0800 Message-ID: <556FCB62.80200@cn.fujitsu.com> Date: Thu, 4 Jun 2015 11:52:02 +0800 From: Wen Congyang User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:31.0) Gecko/20100101 Thunderbird/31.7.0 MIME-Version: 1.0 To: Stefan Hajnoczi , David Weber References: <8145574.73ivEs6Dzv@o3-3> <20150603140607.GC20862@stefanha-thinkpad.redhat.com> In-Reply-To: <20150603140607.GC20862@stefanha-thinkpad.redhat.com> X-Originating-IP: [10.167.226.52] X-detected-operating-system: by eggs.gnu.org: Genre and OS details not recognized. X-Received-From: 59.151.112.132 Cc: linux-ext4@vger.kernel.org, qemu-devel@nongnu.org Subject: Re: [Qemu-devel] Strange problems with lseek in qemu-img map X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org Sender: qemu-devel-bounces+incoming=patchwork.ozlabs.org@nongnu.org Cc: ext4 maillist On 06/03/2015 10:06 PM, Stefan Hajnoczi wrote: > On Tue, Jun 02, 2015 at 02:54:17PM +0200, David Weber wrote: >> Testcase: >> # qemu-img create test 500G >> # time qemu-img map test >> >> Systems: >> O3-3: Kubuntu 15.04 Workstation with stock-kernel 3.19.0-18-generic and stock >> qemu 2.2.0 >> Dinah: Ubuntu Server 15.04 with stock-kernel 3.19.0-18-generic and stock qemu >> 2.2.0 > > These systems have the same kernel but for some reason O3-3 completes > quickly while Dinah takes a long time in lseek(fd, offset, SEEK_DATA). > It looks like the file is empty (the syscall keeps returning ENXIO > because there are no allocated blocks in the file where qemu-img > probes). > >> Result on O3-3: >> root@o3-3:~# qemu-img create test 500G >> Formatting 'test', fmt=raw size=536870912000 >> root@o3-3:~# time qemu-img map test >> Offset Length Mapped to File >> >> real 0m0.049s >> user 0m0.048s >> sys 0m0.000s >> >> Result on dinah: >> root@dinah:~# qemu-img create test 500G >> Formatting 'test', fmt=raw size=536870912000 >> root@dinah:~# time qemu-img map test >> Offset Length Mapped to File >> ^C >> >> real 0m41.862s >> user 0m0.004s >> sys 0m0.068s >> (Stopped with ^C) >> >> Strace on O3-3: >> https://gist.github.com/anonymous/f221035e9176f7c71c74 >> >> Strace on dinah: >> https://gist.github.com/anonymous/40b42888a65478c90b32 >> >> A git bisect between 1.7 and master revealed >> 7c15903789953ead14a417882657d52dc0c19a24 "block/raw-posix: use seek_hole ahead >> of fiemap" as bad but this is not the real problem. >> I also tried to switch from btrfs to ext4 but it didn't change anything. >> >> At this point, I was pretty sure that was just stupit and missing something >> trivial. >> I then startet a fedora 22 live system and I saw the same problem. It happens >> on both the ramdisk and a ext4 filesystem. > > "it" == qemu-img map hangs or takes a very long time? > > Can you post a shell script that reproduces this with a ramdisk? That > seems like the easiest way to get people debugging it. I think it is ext4's problem. I add some printk in ext4_seek_data(): [ 335.579506] ext4_seek_data(): isize: 7d00000000, offset: 0, maxsize: ffffffff000 [ 335.579512] ext4_seek_data(): blkbits: 12, start: 0, end: 7d00000 [ 340.672400] ext4_seek_data(): loop count: 131072001 [ 340.672402] ext4_seek_data() returns -ENXIO [ 340.672447] ext4_seek_data(): isize: 7d00000000, offset: 40000000, maxsize: ffffffff000 [ 340.672449] ext4_seek_data(): blkbits: 12, start: 40000, end: 7d00000 [ 345.701852] ext4_seek_data(): loop count: 130809857 [ 345.701853] ext4_seek_data() returns -ENXIO [ 345.701891] ext4_seek_data(): isize: 7d00000000, offset: 80000000, maxsize: ffffffff000 [ 345.701893] ext4_seek_data(): blkbits: 12, start: 80000, end: 7d00000 [ 350.718479] ext4_seek_data(): loop count: 130547713 [ 350.718480] ext4_seek_data() returns -ENXIO [ 350.718507] ext4_seek_data(): isize: 7d00000000, offset: c0000000, maxsize: ffffffff000 [ 350.718508] ext4_seek_data(): blkbits: 12, start: c0000, end: 7d00000 [ 355.729692] ext4_seek_data(): loop count: 130285569 [ 355.729693] ext4_seek_data() returns -ENXIO [ 355.729732] ext4_seek_data(): isize: 7d00000000, offset: 100000000, maxsize: ffffffff000 [ 355.729734] ext4_seek_data(): blkbits: 12, start: 100000, end: 7d00000 [ 360.728206] ext4_seek_data(): loop count: 130023425 [ 360.728207] ext4_seek_data() returns -ENXIO The diff: We will call the syscall lseek(..., SEEK_DATA) 500 times. Thanks Wen Congyang > > Stefan > diff --git a/fs/ext4/file.c b/fs/ext4/file.c index 0613c25..9b334cc 100644 --- a/fs/ext4/file.c +++ b/fs/ext4/file.c @@ -453,12 +453,16 @@ static loff_t ext4_seek_data(struct file *file, loff_t offset, loff_t maxsize) loff_t dataoff, isize; int blkbits; int ret = 0; + unsigned long count = 0; mutex_lock(&inode->i_mutex); isize = i_size_read(inode); + pr_info("%s(): isize: %llx, offset: %llx, maxsize: %llx\n", + __func__, isize, offset, maxsize); if (offset >= isize) { mutex_unlock(&inode->i_mutex); + pr_info("%s() returns -ENXIO(offset is too large)\n", __func__); return -ENXIO; } @@ -467,8 +471,11 @@ static loff_t ext4_seek_data(struct file *file, loff_t offset, loff_t maxsize) last = start; end = isize >> blkbits; dataoff = offset; + pr_info("%s(): blkbits: %d, start: %x, end: %x\n", + __func__, blkbits, start, end); do { + count++; map.m_lblk = last; map.m_len = end - last + 1; ret = ext4_map_blocks(NULL, inode, &map, 0); @@ -508,8 +515,12 @@ static loff_t ext4_seek_data(struct file *file, loff_t offset, loff_t maxsize) mutex_unlock(&inode->i_mutex); - if (dataoff > isize) + pr_info("%s(): loop count: %ld\n", __func__, count); + + if (dataoff > isize) { + pr_info("%s() returns -ENXIO\n", __func__); return -ENXIO; + } return vfs_setpos(file, dataoff, maxsize); }