qemu-img V1.0 hangs on creating Image (0.15.1 runs)

[Michael Niehren]

Hi,

i try the following command:
  /usr/bin/qemu-img create -f qcow2 test.img 10G

if i run it on V0.15.1 it works, on V1.0 it hangs. Starting qemu-kvm hangs too, i think it's the same Bug.

Strace on the hanging qemu-img ends on:

select(5, [4], [], NULL, NULL) = 1 (in [4])
read(4, "\0", 16) = 1
close(3) = 0
open("test.img", O_RDONLY|O_NONBLOCK) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=131072, ...}) = 0
close(3) = 0
open("test.img", O_RDONLY|O_NONBLOCK) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=131072, ...}) = 0
close(3) = 0
stat("test.img", {st_mode=S_IFREG|0644, st_size=131072, ...}) = 0
open("test.img", O_RDWR|O_CLOEXEC) = 3
lseek(3, 0, SEEK_END) = 131072

next line in the strace on working qemu-img V0.15.1 is:
pread(3, "QFI\373\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0\0"..., 512, 0) = 512
...

The only linking difference i see is the libgthread on the new version V1.0. I am using glib V2.26.

Can someone help ?

best regards,
  Michael

[Stefan Hajnoczi (stefanha)]

On Fri, Dec 9, 2011 at 1:10 PM, Michael Niehren
<email address hidden> wrote:
> Strace on the hanging qemu-img ends on:
>
> select(5, [4], [], NULL, NULL)          = 1 (in [4])
> read(4, "\0", 16)                       = 1
> close(3)                                = 0
> open("test.img", O_RDONLY|O_NONBLOCK)   = 3
> fstat(3, {st_mode=S_IFREG|0644, st_size=131072, ...}) = 0
> close(3)                                = 0
> open("test.img", O_RDONLY|O_NONBLOCK)   = 3
> fstat(3, {st_mode=S_IFREG|0644, st_size=131072, ...}) = 0
> close(3)                                = 0
> stat("test.img", {st_mode=S_IFREG|0644, st_size=131072, ...}) = 0
> open("test.img", O_RDWR|O_CLOEXEC)      = 3
> lseek(3, 0, SEEK_END)                   = 131072
>
> next line in the strace on working qemu-img V0.15.1 is:
> pread(3, "QFI\373\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\0\0\0\0\0\0\0\0"..., 512, 0) = 512
> ...

When it hangs does it consume CPU?

Please attach gdb to the process and capture a backtrace:
$ gdb -p $PID_OF_QEMU
(gdb) thread apply all bt

Stefan

[Michael Niehren (hu6hzq0z-michael-t16qijz8)]

Hi Stefan,

here is the output of gdb:

tux64@/usr/src/redhat/RPMS/x86_64# gdb -p 16606
GNU gdb (GDB) 7.3
Copyright (C) 2011 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-unknown-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 16606
Reading symbols from /usr/bin/qemu-img...(no debugging symbols found)...done.
Reading symbols from /lib64/librt.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/librt.so.1
Reading symbols from /usr/lib/libgthread-2.0.so.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libgthread-2.0.so.0
Reading symbols from /usr/lib/libglib-2.0.so.0...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libglib-2.0.so.0
Reading symbols from /usr/lib/libz.so.1...(no debugging symbols found)...done.
Loaded symbols for /usr/lib/libz.so.1
Reading symbols from /lib64/libuuid.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libuuid.so.1
Reading symbols from /lib64/libaio.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libaio.so.1
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
0x00007fd75a287f28 in bdrv_rw_co ()
(gdb) quit
A debugging session is active.

after compiling qemu-img with option --enable-debug everything works as expected.

hope that help's,

Greetings,
  Michael

[Stefan Hajnoczi (stefanha)]

On Mon, Dec 19, 2011 at 10:02 AM, Michael Niehren
<email address hidden> wrote:
> 0x00007fd75a287f28 in bdrv_rw_co ()
> (gdb) quit
> A debugging session is active.

Please run the 'thread apply all bt' gdb command to produce backtraces
for all threads.

Your system does not have symbols installed for these binaries so the
backtrace might consist mostly of memory addresses (which are harder
to track down). If possible, please install the qemu-img -debug RPM.

> after compiling qemu-img with option --enable-debug everything works as expected.

Interesting but are you sure you compiled exactly the same code as
your system's qemu-img RPM?

Stefan

[Michael Niehren (hu6hzq0z-michael-t16qijz8)]

Ok, sorry, here the output:

Thread 1 (Thread 0x7f57507c2740 (LWP 27263)):
#0 0x00007f57507da952 in qemu_aio_wait ()
#1 0x00007f57507dcf2d in bdrv_rw_co ()
#2 0x00007f57507dd2c2 in bdrv_pread ()
#3 0x00007f57507ed03a in qcow2_open ()
#4 0x00007f57507dc281 in bdrv_open_common ()
#5 0x00007f57507ddb73 in bdrv_open ()
#6 0x00007f57507ecafa in qcow2_create2 ()
#7 0x00007f57507ece58 in qcow2_create ()
#8 0x00007f57507e12c1 in bdrv_img_create ()
#9 0x00007f575080bfeb in img_create ()
#10 0x00007f574f340c7d in __libc_start_main () from /lib64/libc.so.6
#11 0x00007f57507d9359 in _start ()

I compiled the rpm's myself, so i am sure the only difference of both is the enable-debug Flag, same
source code. Here are my compile-flags on running configure:

    --disable-curses --disable-curl --audio-card-list=ac97 \
    --enable-kvm --enable-spice --enable-linux-aio \
    --enable-tcg-interpreter --enable-vnc-thread

Michael

[Stefan Hajnoczi (stefanha)]

On Mon, Dec 19, 2011 at 10:52:24AM -0000, Michael Niehren wrote:
> Ok, sorry, here the output:
>
> Thread 1 (Thread 0x7f57507c2740 (LWP 27263)):
> #0 0x00007f57507da952 in qemu_aio_wait ()
> #1 0x00007f57507dcf2d in bdrv_rw_co ()
> #2 0x00007f57507dd2c2 in bdrv_pread ()
> #3 0x00007f57507ed03a in qcow2_open ()
> #4 0x00007f57507dc281 in bdrv_open_common ()
> #5 0x00007f57507ddb73 in bdrv_open ()
> #6 0x00007f57507ecafa in qcow2_create2 ()
> #7 0x00007f57507ece58 in qcow2_create ()
> #8 0x00007f57507e12c1 in bdrv_img_create ()
> #9 0x00007f575080bfeb in img_create ()
> #10 0x00007f574f340c7d in __libc_start_main () from /lib64/libc.so.6
> #11 0x00007f57507d9359 in _start ()
>
> I compiled the rpm's myself, so i am sure the only difference of both is the enable-debug Flag, same
> source code. Here are my compile-flags on running configure:
>
> --disable-curses --disable-curl --audio-card-list=ac97 \
> --enable-kvm --enable-spice --enable-linux-aio \
> --enable-tcg-interpreter --enable-vnc-thread

I cannot reproduce it here but is it possible for you to try this patch?

diff --git a/block.c b/block.c
index d015887..aae71c2 100644
--- a/block.c
+++ b/block.c
@@ -1042,6 +1042,8 @@ static void coroutine_fn bdrv_rw_co_entry(void *opaque)
 {
     RwCo *rwco = opaque;

+ printf("bdrv_rw_co_entry is_write %d sector_num %" PRId64 " nb_sectors %d =",
+ rwco->is_write, rwco->sector_num, rwco->nb_sectors);
     if (!rwco->is_write) {
         rwco->ret = bdrv_co_do_readv(rwco->bs, rwco->sector_num,
                                      rwco->nb_sectors, rwco->qiov);
@@ -1049,6 +1051,8 @@ static void coroutine_fn bdrv_rw_co_entry(void *opaque)
         rwco->ret = bdrv_co_do_writev(rwco->bs, rwco->sector_num,
                                       rwco->nb_sectors, rwco->qiov);
     }
+ assert(rwco->ret != NOT_DONE);
+ printf("%d\n", rwco->ret);
 }

 /*
@@ -1081,6 +1085,7 @@ static int bdrv_rw_co(BlockDriverState *bs, int64_t sector_num, uint8_t *
         co = qemu_coroutine_create(bdrv_rw_co_entry);
         qemu_coroutine_enter(co, &rwco);
         while (rwco.ret == NOT_DONE) {
+ printf("waiting for rwco.ret != NOT_DONE\n");
             qemu_aio_wait();
         }
     }

Here is my sample output from a successful run of ./qemu-img create -f qcow2 test.img 10G:

Formatting 'test.img', fmt=qcow2 size=10737418240 encryption=off cluster_size=65536
bdrv_rw_co_entry is_write 0 sector_num 0 nb_sectors 1 =waiting for rwco.ret != NOT_DONE
waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 1 sector_num 0 nb_sectors 1 =waiting for rwco.ret != NOT_DONE
waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 1 sector_num 128 nb_sectors 128 =waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 0 sector_num 0 nb_sectors 1 =waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 0 sector_num 128 nb_sectors 128 =waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 0 sector_num 0 nb_sectors 1 =waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 1 sector_num 256 nb_sectors 128 =waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 0 sector_num 128 nb_sectors 1 =w...

[Michael Niehren (hu6hzq0z-michael-t16qijz8)]

Hi Stefan,

i got the following output with your patch:

Formatting 'test.img', fmt=qcow2 size=1073741824 encryption=off cluster_size=65536
bdrv_rw_co_entry is_write 0 sector_num 0 nb_sectors 1 =waiting for rwco.ret != NOT_DONE
waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 1 sector_num 0 nb_sectors 1 =waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 1 sector_num 128 nb_sectors 128 =waiting for rwco.ret != NOT_DONE
0
bdrv_rw_co_entry is_write 1 sector_num 128 nb_sectors 128 =-5
waiting for rwco.ret != NOT_DONE
waiting for rwco.ret != NOT_DONE
waiting for rwco.ret != NOT_DONE
....

and runs forever

[Stefan Hajnoczi (stefanha)]

On Mon, Dec 19, 2011 at 05:26:22PM -0000, Michael Niehren wrote:
> i got the following output with your patch:
>
> Formatting 'test.img', fmt=qcow2 size=1073741824 encryption=off cluster_size=65536
> bdrv_rw_co_entry is_write 0 sector_num 0 nb_sectors 1 =waiting for rwco.ret != NOT_DONE
> waiting for rwco.ret != NOT_DONE
> 0
> bdrv_rw_co_entry is_write 1 sector_num 0 nb_sectors 1 =waiting for rwco.ret != NOT_DONE
> 0
> bdrv_rw_co_entry is_write 1 sector_num 128 nb_sectors 128 =waiting for rwco.ret != NOT_DONE
> 0
> bdrv_rw_co_entry is_write 1 sector_num 128 nb_sectors 128 =-5
> waiting for rwco.ret != NOT_DONE
> waiting for rwco.ret != NOT_DONE
> waiting for rwco.ret != NOT_DONE
> ....
>
> and runs forever

The '=-5' is an Input/Output Error (EIO). For some reason bdrv_rw_co()
is still waiting for the request to finish after the error has been
returned.

Is it possible for you to make the qemu-img binary available so I could
try to reproduce this and debug it?

Stefan

[Michael Niehren (hu6hzq0z-michael-t16qijz8)]

attached the binary with your patch

[Michael Niehren (hu6hzq0z-michael-t16qijz8)]

here the compiled binary with your patch and the --enable-debug option
This one works

[Stefan Hajnoczi (stefanha)]

On Tue, Dec 20, 2011 at 10:25 AM, Michael Niehren
<email address hidden> wrote:
> here the compiled binary with your patch and the --enable-debug option
> This one works

Thanks, I'm able to reproduce the problem here with your original
binary. Will send an update once I've figured out what the problem
is.

Stefan

[Stefan Hajnoczi (stefanha)]

On Tue, Dec 20, 2011 at 10:49 AM, Stefan Hajnoczi <email address hidden> wrote:
> On Tue, Dec 20, 2011 at 10:25 AM, Michael Niehren
> <email address hidden> wrote:
>> here the compiled binary with your patch and the --enable-debug option
>> This one works
>
> Thanks, I'm able to reproduce the problem here with your original
> binary.  Will send an update once I've figured out what the problem
> is.

This looks like an interesting bug, perhaps a bug in gcc. I have to
preface that with what the QEMU code is doing here is pretty tricky,
so it might be a regular bug in QEMU... :)

Here is the C function that triggers the bug:

static void coroutine_trampoline(int i0, int i1)
{
    union cc_arg arg;
    CoroutineUContext *self;
    Coroutine *co;

    arg.i[0] = i0; <-- workaround for makecontext() limitation,
    arg.i[1] = i1; need to pass Coroutine *co argument in as
    self = arg.p; two ints and use a union to extract it.
    co = &self->base;

    /* Initialize longjmp environment and switch back the caller */
    if (!setjmp(self->env)) {
        longjmp(*(jmp_buf *)co->entry_arg, 1);
    } <-- I think this part is not relevant to the bug

    while (true) { <-- here is the loop that miscompiles
        co->entry(co->entry_arg);
        qemu_coroutine_switch(co, co->caller, COROUTINE_TERMINATE);
    }
}

Here is the loop output of my compiler - this works fine:

   31bd0: 48 8b 44 24 08 mov 0x8(%rsp),%rax <-- co->entry
   31bd5: 48 8b 78 08 mov 0x8(%rax),%rdi <-- co->entry_arg
   31bd9: ff 10 callq *(%rax)
   31bdb: 48 8b 44 24 08 mov 0x8(%rsp),%rax
   31be0: 48 8b 7c 24 10 mov 0x10(%rsp),%rdi
   31be5: ba 02 00 00 00 mov $0x2,%edx
   31bea: 48 8b 70 10 mov 0x10(%rax),%rsi
   31bee: e8 2d ff ff ff callq 31b20 <qemu_coroutine_switch>
   31bf3: eb db jmp 31bd0 <coroutine_trampoline+0x40>

Here is your compiler output - this is broken:

   31c40: 4c 89 e7 mov %r12,%rdi <--
co->entry_args from %r12
   31c43: ff d5 callq *%rbp <--
co->entry already in %rbp
   31c45: 48 8b 3c 24 mov (%rsp),%rdi
   31c49: ba 02 00 00 00 mov $0x2,%edx
   31c4e: 48 89 de mov %rbx,%rsi
   31c51: e8 2a ff ff ff callq 31b80 <qemu_coroutine_switch>
   31c56: eb e8 jmp 31c40 <coroutine_trampoline+0x50>

Your binary does not reload the coroutine entry function pointer or
entry_args argument fields. As a result coroutines are not working in
your QEMU build.

It seems your compiler is disregarding the co->entry() function
pointer call and assuming co's fields will not change. The
setjmp()/longjmp() and cc_args union make this an ugly function -
perhaps they play a part in making the compiler think it's okay to
keep stale values of co's fields around.

Richard Sandiford has suggested a way to capture what gcc is doing:

$ cd qemu/
$ rm coroutine-ucontext.o
$ make V=1 coroutine-ucontext.o

Now copy the gcc command-lin...

[Michael Niehren (hu6hzq0z-michael-t16qijz8)]

Hi Stefan,

here we are. Attached the tgz. I am using no spezial distribution, it's a self compiled LFS with
gcc V4.5.1

Is there a different compiler-call if i use --enable-debug, which then works ?

Greetings,
  Michael

[Stefan Hajnoczi (stefanha)]

On Tue, Dec 20, 2011 at 3:25 PM, Michael Niehren
<email address hidden> wrote:
> here we are. Attached the tgz. I am using no spezial distribution, it's a self compiled LFS with
> gcc V4.5.1
>
> Is there a different compiler-call if i use --enable-debug, which then
> works ?

Richard Sandiford looked at your gcc -fdump-tree-all-details output
and suggests that this bug has been fixed in gcc 4.5.3:

http://gcc.gnu.org/bugzilla/show_bug.cgi?id=45967

Using the most recent gcc should fix the issue you are seeing.

Stefan

[Stefan Hajnoczi (stefanha)]

On Tue, Dec 20, 2011 at 4:49 PM, Stefan Hajnoczi <email address hidden> wrote:
> On Tue, Dec 20, 2011 at 3:25 PM, Michael Niehren
> <email address hidden> wrote:
>> here we are. Attached the tgz. I am using no spezial distribution, it's a self compiled LFS with
>> gcc V4.5.1
>>
>> Is there a different compiler-call if i use --enable-debug, which then
>> works ?
>
> Richard Sandiford looked at your gcc -fdump-tree-all-details output
> and suggests that this bug has been fixed in gcc 4.5.3:
>
> http://gcc.gnu.org/bugzilla/show_bug.cgi?id=45967
>
> Using the most recent gcc should fix the issue you are seeing.

Besides using a more recent gcc you could also try building with -O0
or -O2 instead of the default -O2 optimization level. Try
"./configure --extra-cflags=-O1 ...".

Stefan

[Michael Niehren (hu6hzq0z-michael-t16qijz8)]

Hi Stefan,

after upgrading GCC to V4.5.3 everything work's perfect.

thanks for your help,
  Michael

[Kevin Wolf (kwolf-redhat)]

Am 20.12.2011 17:49, schrieb Stefan Hajnoczi:
> On Tue, Dec 20, 2011 at 3:25 PM, Michael Niehren
> <email address hidden> wrote:
>> here we are. Attached the tgz. I am using no spezial distribution, it's a self compiled LFS with
>> gcc V4.5.1
>>
>> Is there a different compiler-call if i use --enable-debug, which then
>> works ?
>
> Richard Sandiford looked at your gcc -fdump-tree-all-details output
> and suggests that this bug has been fixed in gcc 4.5.3:
>
> http://gcc.gnu.org/bugzilla/show_bug.cgi?id=45967
>
> Using the most recent gcc should fix the issue you are seeing.

Can we add some workaround? Not sure what will work, maybe a simple
compiler barrier?

Kevin

[Stefan Hajnoczi (stefanha)]

On Mon, Jan 9, 2012 at 11:25 AM, Kevin Wolf <email address hidden> wrote:
> Am 20.12.2011 17:49, schrieb Stefan Hajnoczi:
>> On Tue, Dec 20, 2011 at 3:25 PM, Michael Niehren
>> <email address hidden> wrote:
>>> here we are. Attached the tgz. I am using no spezial distribution, it's a self compiled LFS with
>>> gcc V4.5.1
>>>
>>> Is there a different compiler-call if i use --enable-debug, which then
>>> works ?
>>
>> Richard Sandiford looked at your gcc -fdump-tree-all-details output
>> and suggests that this bug has been fixed in gcc 4.5.3:
>>
>> http://gcc.gnu.org/bugzilla/show_bug.cgi?id=45967
>>
>> Using the most recent gcc should fix the issue you are seeing.
>
> Can we add some workaround? Not sure what will work, maybe a simple
> compiler barrier?

Sure though it seems like a very rare case - OP was running Linux From
Scratch and hence got the broken gcc. But if someone does a small
workaround and tests it then that would be nice.

Stefan

[Stefan Hajnoczi (stefanha)]

On Sat, Jan 14, 2012 at 3:40 PM, Zhi Yong Wu <email address hidden> wrote:
> On Mon, Jan 9, 2012 at 9:00 PM, Stefan Hajnoczi <email address hidden> wrote:
>> On Mon, Jan 9, 2012 at 11:25 AM, Kevin Wolf <email address hidden> wrote:
>>> Am 20.12.2011 17:49, schrieb Stefan Hajnoczi:
>>>> On Tue, Dec 20, 2011 at 3:25 PM, Michael Niehren
>>>> <email address hidden> wrote:
>>>>> here we are. Attached the tgz. I am using no spezial distribution, it's a self compiled LFS with
>>>>> gcc V4.5.1
>>>>>
>>>>> Is there a different compiler-call if i use --enable-debug, which then
>>>>> works ?
>>>>
>>>> Richard Sandiford looked at your gcc -fdump-tree-all-details output
>>>> and suggests that this bug has been fixed in gcc 4.5.3:
>>>>
>>>> http://gcc.gnu.org/bugzilla/show_bug.cgi?id=45967
>>>>
>>>> Using the most recent gcc should fix the issue you are seeing.
>>>
>>> Can we add some workaround? Not sure what will work, maybe a simple
>>> compiler barrier?
>>
>> Sure though it seems like a very rare case - OP was running Linux From
>> Scratch and hence got the broken gcc.  But if someone does a small
>> workaround and tests it then that would be nice.
> How to do this workaround in qemu since it is one gcc bug?

The problem is that that compiler keeps values in registers across a
point where C semantics require that they be reloaded.

There are several ways to force a compiler to reload values including
a barrier (which Kevin suggested) or the volatile keyword. One of
these techniques can probably be used as a workaround, but it would be
necessary to check gcc 4.5.1 output to make sure it's effective.

I think it's not worth doing unless we think more users will be
affected. Unless a distro ships the broken compiler version or it's
the latest gcc release that people would build from source, I bet the
number of users is very small.

Stefan