[Qemu-devel] Strange problems with lseek in qemu-img map

[Qemu-devel] Strange problems with lseek in qemu-img map

[David Weber]

Hello,

I'm currently evaluating to switch our virtualization servers to a newer OS. 
This includes a switch from qemu 1.7 to 2.2 or 2.3. 
Our system heavily relies on big sparse images and drive_mirror. While 
testing, I experienced some problems with that combination.
The strange thing is, that everything works flawlessly on my workstation but 
fails on my servers.

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

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.

Any ideas on this? I'm pretty much stuck at this point. Please ask if you need 
more information.

Cheers,
David

Re: [Qemu-devel] Strange problems with lseek in qemu-img map

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 2052 bytes --]

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.

Stefan

[-- Attachment #2: Type: application/pgp-signature, Size: 473 bytes --]

Re: [Qemu-devel] Strange problems with lseek in qemu-img map

[Wen Congyang]

On 06/02/2015 08:54 PM, David Weber wrote:
> Hello,
> 
> I'm currently evaluating to switch our virtualization servers to a newer OS. 
> This includes a switch from qemu 1.7 to 2.2 or 2.3. 
> Our system heavily relies on big sparse images and drive_mirror. While 
> testing, I experienced some problems with that combination.
> The strange thing is, that everything works flawlessly on my workstation but 
> fails on my servers.
> 
> 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
> 
> 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)

Do you use the same filesystem?

Thanks
Wen Congyang

> 
> 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.
> 
> Any ideas on this? I'm pretty much stuck at this point. Please ask if you need 
> more information.
> 
> Cheers,
> David
> 
> 
> 

Re: [Qemu-devel] Strange problems with lseek in qemu-img map

[Wen Congyang]

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:
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);
 }

We will call the syscall lseek(..., SEEK_DATA) 500 times.

Thanks
Wen Congyang

> 
> Stefan
>