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

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

[David Weber]

Thanks a lot for your reply and sorry for my double post out of impatientness.

> > 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?
I never waited for it to complete but I guess it just takes very long.

> 
> Can you post a shell script that reproduces this with a ramdisk?  That
> seems like the easiest way to get people debugging it.

You can use the following commands.

mkfs.ext4 /dev/ram0
mkdir -p /mnt/tmp
mount /dev/ram0 /mnt/tmp
cd /mnt/tmp
qemu-img create test 500G
time qemu-img map test

This takes foreover on all my systems.

Running everything on tmpfs instead is fast
mkdir -p /mnt/tmp
mount -t tmpfs -o size=1G none /mnt/tmp
cd /mnt/tmp
qemu-img create test 500G
time qemu-img map test

I did run a few more tests on different systems and made an interessting observation.
lseek is damn slow if the blockdevice has an I/O size of 512 bytes (like the raid controller of my server or a ramdisk) and runs fast with 4096 bytes (like the ssd of my workstation or tmpfs).
I confirmned this also with with a few other drives but it still could be coincidence...

You can check the I/O size by running 
fdisk <dev>
p

Cheers,
David

To: stefanha@gmail.com
Cc: qemu-devel@nongnu.org

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

[Stefan Hajnoczi]

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

On Wed, Jun 03, 2015 at 03:09:40PM +0000, David Weber wrote:
> > > 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?
> I never waited for it to complete but I guess it just takes very long.
> 
> > 
> > Can you post a shell script that reproduces this with a ramdisk?  That
> > seems like the easiest way to get people debugging it.
> 
> You can use the following commands.
> 
> mkfs.ext4 /dev/ram0
> mkdir -p /mnt/tmp
> mount /dev/ram0 /mnt/tmp
> cd /mnt/tmp
> qemu-img create test 500G
> time qemu-img map test
> 
> This takes foreover on all my systems.

I experience the same thing on Linux 4.1.0-rc5 with ext4 (4 KB file
system block size, 512B device sector size).

The lseek() calls take *seconds* to complete on a completely empty
(sparse) 500G file.

Here is the perf-top(1) output:

  34.08%  [kernel]                         [k] _raw_read_lock
  21.11%  [kernel]                         [k] ext4_es_lookup_extent
  20.67%  [kernel]                         [k] ext4_es_find_delayed_extent_range
   8.68%  [kernel]                         [k] ext4_map_blocks
   4.99%  [kernel]                         [k] ext4_llseek
   1.90%  [kernel]                         [k] rb_next
   0.14%  [kernel]                         [k] __fget

Yikes!

The syscall causing this is just:

lseek(7, 0, SEEK_DATA)

Lukas: I've CCed you because you have helped with ext4 issues in the
past.  Not sure if you have time or if this is your area.

Stefan

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

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

[Lukáš Czerner]

On Fri, 5 Jun 2015, Stefan Hajnoczi wrote:

> Date: Fri, 5 Jun 2015 15:05:15 +0100
> From: Stefan Hajnoczi <stefanha@gmail.com>
> To: David Weber <wb@munzinger.de>
> Cc: qemu-devel@nongnu.org, linux-ext4@vger.kernel.org,
>     Lukas Czerner <lczerner@redhat.com>, wency@cn.fujitsu.com
> Subject: Re: [Qemu-devel] Re-2:  Strange problems with lseek in qemu-img map
> 
> On Wed, Jun 03, 2015 at 03:09:40PM +0000, David Weber wrote:
> > > > 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?
> > I never waited for it to complete but I guess it just takes very long.
> > 
> > > 
> > > Can you post a shell script that reproduces this with a ramdisk?  That
> > > seems like the easiest way to get people debugging it.
> > 
> > You can use the following commands.
> > 
> > mkfs.ext4 /dev/ram0
> > mkdir -p /mnt/tmp
> > mount /dev/ram0 /mnt/tmp
> > cd /mnt/tmp
> > qemu-img create test 500G
> > time qemu-img map test
> > 
> > This takes foreover on all my systems.
> 
> I experience the same thing on Linux 4.1.0-rc5 with ext4 (4 KB file
> system block size, 512B device sector size).
> 
> The lseek() calls take *seconds* to complete on a completely empty
> (sparse) 500G file.
> 
> Here is the perf-top(1) output:
> 
>   34.08%  [kernel]                         [k] _raw_read_lock
>   21.11%  [kernel]                         [k] ext4_es_lookup_extent
>   20.67%  [kernel]                         [k] ext4_es_find_delayed_extent_range
>    8.68%  [kernel]                         [k] ext4_map_blocks
>    4.99%  [kernel]                         [k] ext4_llseek
>    1.90%  [kernel]                         [k] rb_next
>    0.14%  [kernel]                         [k] __fget
> 
> Yikes!
> 
> The syscall causing this is just:
> 
> lseek(7, 0, SEEK_DATA)
> 
> Lukas: I've CCed you because you have helped with ext4 issues in the
> past.  Not sure if you have time or if this is your area.
> 
> Stefan

Hi,

this is definitely an issue with extent status tree and I have not seen
it before. I'll look at it first thing next week, but meanwhile I'll
add Zheng Liu who is the author of the extent status tree so he
might be able to help you.

Regards,
-Lukas

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

[Wen Congyang]

At 2015/6/5 23:14, Lukáš Czerner Wrote:
> On Fri, 5 Jun 2015, Stefan Hajnoczi wrote:
>
>> Date: Fri, 5 Jun 2015 15:05:15 +0100
>> From: Stefan Hajnoczi <stefanha@gmail.com>
>> To: David Weber <wb@munzinger.de>
>> Cc: qemu-devel@nongnu.org, linux-ext4@vger.kernel.org,
>>      Lukas Czerner <lczerner@redhat.com>, wency@cn.fujitsu.com
>> Subject: Re: [Qemu-devel] Re-2:  Strange problems with lseek in qemu-img map
>>
>> On Wed, Jun 03, 2015 at 03:09:40PM +0000, David Weber wrote:
>>>>> 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?
>>> I never waited for it to complete but I guess it just takes very long.
>>>
>>>>
>>>> Can you post a shell script that reproduces this with a ramdisk?  That
>>>> seems like the easiest way to get people debugging it.
>>>
>>> You can use the following commands.
>>>
>>> mkfs.ext4 /dev/ram0
>>> mkdir -p /mnt/tmp
>>> mount /dev/ram0 /mnt/tmp
>>> cd /mnt/tmp
>>> qemu-img create test 500G
>>> time qemu-img map test
>>>
>>> This takes foreover on all my systems.
>>
>> I experience the same thing on Linux 4.1.0-rc5 with ext4 (4 KB file
>> system block size, 512B device sector size).
>>
>> The lseek() calls take *seconds* to complete on a completely empty
>> (sparse) 500G file.
>>
>> Here is the perf-top(1) output:
>>
>>    34.08%  [kernel]                         [k] _raw_read_lock
>>    21.11%  [kernel]                         [k] ext4_es_lookup_extent
>>    20.67%  [kernel]                         [k] ext4_es_find_delayed_extent_range
>>     8.68%  [kernel]                         [k] ext4_map_blocks
>>     4.99%  [kernel]                         [k] ext4_llseek
>>     1.90%  [kernel]                         [k] rb_next
>>     0.14%  [kernel]                         [k] __fget
>>
>> Yikes!
>>
>> The syscall causing this is just:
>>
>> lseek(7, 0, SEEK_DATA)
>>
>> Lukas: I've CCed you because you have helped with ext4 issues in the
>> past.  Not sure if you have time or if this is your area.
>>
>> Stefan
>
> Hi,
>
> this is definitely an issue with extent status tree and I have not seen
> it before. I'll look at it first thing next week, but meanwhile I'll
> add Zheng Liu who is the author of the extent status tree so he
> might be able to help you.

It is an known bug, and Dmitry Monakhov tried to fix it:
http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=14516bb7bb6ffbd49f35389f9ece3b2045ba5815

But this patch introduced another problem, and have been reverted.

Thanks
Wen Congyang

>
> Regards,
> -Lukas
>
>

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

[Lukáš Czerner]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 3579 bytes --]

On Sat, 6 Jun 2015, Wen Congyang wrote:

> Date: Sat, 06 Jun 2015 11:53:50 +0800
> From: Wen Congyang <ghostwcy@gmail.com>
> To: Lukáš Czerner <lczerner@redhat.com>, Stefan Hajnoczi <stefanha@gmail.com>
> Cc: David Weber <wb@munzinger.de>, linux-ext4@vger.kernel.org,
>     qemu-devel@nongnu.org, wenqing.lz@taobao.com
> Subject: Re: [Qemu-devel] Re-2: Strange problems with lseek in qemu-img map
> 
> At 2015/6/5 23:14, Lukáš Czerner Wrote:
> > On Fri, 5 Jun 2015, Stefan Hajnoczi wrote:
> > 
> > > Date: Fri, 5 Jun 2015 15:05:15 +0100
> > > From: Stefan Hajnoczi <stefanha@gmail.com>
> > > To: David Weber <wb@munzinger.de>
> > > Cc: qemu-devel@nongnu.org, linux-ext4@vger.kernel.org,
> > >      Lukas Czerner <lczerner@redhat.com>, wency@cn.fujitsu.com
> > > Subject: Re: [Qemu-devel] Re-2:  Strange problems with lseek in qemu-img
> > > map
> > > 
> > > On Wed, Jun 03, 2015 at 03:09:40PM +0000, David Weber wrote:
> > > > > > 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?
> > > > I never waited for it to complete but I guess it just takes very long.
> > > > 
> > > > > 
> > > > > Can you post a shell script that reproduces this with a ramdisk?  That
> > > > > seems like the easiest way to get people debugging it.
> > > > 
> > > > You can use the following commands.
> > > > 
> > > > mkfs.ext4 /dev/ram0
> > > > mkdir -p /mnt/tmp
> > > > mount /dev/ram0 /mnt/tmp
> > > > cd /mnt/tmp
> > > > qemu-img create test 500G
> > > > time qemu-img map test
> > > > 
> > > > This takes foreover on all my systems.
> > > 
> > > I experience the same thing on Linux 4.1.0-rc5 with ext4 (4 KB file
> > > system block size, 512B device sector size).
> > > 
> > > The lseek() calls take *seconds* to complete on a completely empty
> > > (sparse) 500G file.
> > > 
> > > Here is the perf-top(1) output:
> > > 
> > >    34.08%  [kernel]                         [k] _raw_read_lock
> > >    21.11%  [kernel]                         [k] ext4_es_lookup_extent
> > >    20.67%  [kernel]                         [k]
> > > ext4_es_find_delayed_extent_range
> > >     8.68%  [kernel]                         [k] ext4_map_blocks
> > >     4.99%  [kernel]                         [k] ext4_llseek
> > >     1.90%  [kernel]                         [k] rb_next
> > >     0.14%  [kernel]                         [k] __fget
> > > 
> > > Yikes!
> > > 
> > > The syscall causing this is just:
> > > 
> > > lseek(7, 0, SEEK_DATA)
> > > 
> > > Lukas: I've CCed you because you have helped with ext4 issues in the
> > > past.  Not sure if you have time or if this is your area.
> > > 
> > > Stefan
> > 
> > Hi,
> > 
> > this is definitely an issue with extent status tree and I have not seen
> > it before. I'll look at it first thing next week, but meanwhile I'll
> > add Zheng Liu who is the author of the extent status tree so he
> > might be able to help you.
> 
> It is an known bug, and Dmitry Monakhov tried to fix it:
> http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=14516bb7bb6ffbd49f35389f9ece3b2045ba5815
> 
> But this patch introduced another problem, and have been reverted.
> 
> Thanks
> Wen Congyang

Wow, the code is so broken :) Luckily the fix should be fairly easy,
I am testing it now.

Thanks everyone for pointing this out.

-Lukas

> 
> > 
> > Regards,
> > -Lukas
> > 
> >