[Qemu-devel] QEMU hangs in main_loop_wait

[Qemu-devel] QEMU hangs in main_loop_wait

[Frank Yang]

Hi all,

After quite some backports, such as

https://android.googlesource.com/platform/external/qemu/+/a8da859b1b011e509056f03cbcb73df27afe4337

we are not seeing hangs in flatview_do_translate, but are still getting
hangs in main-loop:

    qemu_mutex_unlock_iothread();
    replay_mutex_unlock();

    ret = qemu_poll_ns((GPollFD *)gpollfds->data, gpollfds->len, timeout);
<-------------this seems to be the hanging part

    replay_mutex_lock();
    qemu_mutex_lock_iothread();

Any idea how to diagnose the cause of taking too much time in g_poll in
qemu_poll_ns?

Frank

Re: [Qemu-devel] QEMU hangs in main_loop_wait

[Paolo Bonzini]

On 17/10/2018 17:44, Frank Yang wrote:
> 
> we are not seeing hangs in flatview_do_translate, but are still getting
> hangs in main-loop:
> 
>     qemu_mutex_unlock_iothread();
>     replay_mutex_unlock();
> 
>     ret = qemu_poll_ns((GPollFD *)gpollfds->data, gpollfds->len,
> timeout); <-------------this seems to be the hanging part
> 
>     replay_mutex_lock();
>     qemu_mutex_lock_iothread();
> 
> Any idea how to diagnose the cause of taking too much time in g_poll in
> qemu_poll_ns?

Is there any event (timer or file descriptor) that you know should be
ready, but is not causing a wakeup?

Paolo

Re: [Qemu-devel] QEMU hangs in main_loop_wait

[Frank Yang]

We don't yet have visibility into that, but is there a way to enumerate
what callbacks are running? We see that sometimes, actually qemu_poll_ns
takes much, much longer than the specified timeout to return:

    qemu_mutex_unlock_iothread();
    replay_mutex_unlock();

    struct timeval tv;
    gettimeofday(&tv, NULL);

    uint64_t start_us = tv.tv_usec + tv.tv_sec * 1000000LL;
    uint64_t duration = 0;
        ret = qemu_poll_ns((GPollFD *)gpollfds->data, gpollfds->len,
timeout);
        gettimeofday(&tv, NULL);
        uint64_t end_us = tv.tv_usec + tv.tv_sec * 1000000LL;
        duration = end_us - start_us;

    if (duration > 100000LL) {
        fprintf(stderr, "%s: polled for %f ms (timeout: %f ms) ret: %d
nfds: %d\n", __func__, duration / 1000.0f, timeout / 1000000.0f, ret,
gpollfds->len);
    }

prints:

os_host_main_loop_wait: polled for 580.517029 ms (timeout: 6.150904 ms)
ret: 1 nfds: 50
os_host_main_loop_wait: polled for 10001.063477 ms (timeout: 1.277816 ms)
ret: 0 nfds: 50
os_host_main_loop_wait: polled for 792.466003 ms (timeout: 0.149536 ms)
ret: 1 nfds: 47
os_host_main_loop_wait: polled for 8359.308594 ms (timeout: 1.791392 ms)
ret: 1 nfds: 47
os_host_main_loop_wait: polled for 2478.096924 ms (timeout: 5.850920 ms)
ret: 1 nfds: 47
os_host_main_loop_wait: polled for 139.272995 ms (timeout: 5.442976 ms)
ret: 1 nfds: 47
os_host_main_loop_wait: polled for 10001.864258 ms (timeout: 1.946600 ms)
ret: 0 nfds: 47


On Wed, Oct 17, 2018 at 10:03 AM Paolo Bonzini <pbonzini@redhat.com> wrote:

> On 17/10/2018 17:44, Frank Yang wrote:
> >
> > we are not seeing hangs in flatview_do_translate, but are still getting
> > hangs in main-loop:
> >
> >     qemu_mutex_unlock_iothread();
> >     replay_mutex_unlock();
> >
> >     ret = qemu_poll_ns((GPollFD *)gpollfds->data, gpollfds->len,
> > timeout); <-------------this seems to be the hanging part
> >
> >     replay_mutex_lock();
> >     qemu_mutex_lock_iothread();
> >
> > Any idea how to diagnose the cause of taking too much time in g_poll in
> > qemu_poll_ns?
>
> Is there any event (timer or file descriptor) that you know should be
> ready, but is not causing a wakeup?
>
> Paolo
>

Re: [Qemu-devel] QEMU hangs in main_loop_wait

[Frank Yang]

Also, those only happen when using the browser in the guest; leave it on a
single webpage, and get these long timeouts. We are using slirp.

On Tue, Oct 23, 2018 at 8:02 AM Frank Yang <lfy@google.com> wrote:

> We don't yet have visibility into that, but is there a way to enumerate
> what callbacks are running? We see that sometimes, actually qemu_poll_ns
> takes much, much longer than the specified timeout to return:
>
>     qemu_mutex_unlock_iothread();
>     replay_mutex_unlock();
>
>     struct timeval tv;
>     gettimeofday(&tv, NULL);
>
>     uint64_t start_us = tv.tv_usec + tv.tv_sec * 1000000LL;
>     uint64_t duration = 0;
>         ret = qemu_poll_ns((GPollFD *)gpollfds->data, gpollfds->len,
> timeout);
>         gettimeofday(&tv, NULL);
>         uint64_t end_us = tv.tv_usec + tv.tv_sec * 1000000LL;
>         duration = end_us - start_us;
>
>     if (duration > 100000LL) {
>         fprintf(stderr, "%s: polled for %f ms (timeout: %f ms) ret: %d
> nfds: %d\n", __func__, duration / 1000.0f, timeout / 1000000.0f, ret,
> gpollfds->len);
>     }
>
> prints:
>
> os_host_main_loop_wait: polled for 580.517029 ms (timeout: 6.150904 ms)
> ret: 1 nfds: 50
> os_host_main_loop_wait: polled for 10001.063477 ms (timeout: 1.277816 ms)
> ret: 0 nfds: 50
> os_host_main_loop_wait: polled for 792.466003 ms (timeout: 0.149536 ms)
> ret: 1 nfds: 47
> os_host_main_loop_wait: polled for 8359.308594 ms (timeout: 1.791392 ms)
> ret: 1 nfds: 47
> os_host_main_loop_wait: polled for 2478.096924 ms (timeout: 5.850920 ms)
> ret: 1 nfds: 47
> os_host_main_loop_wait: polled for 139.272995 ms (timeout: 5.442976 ms)
> ret: 1 nfds: 47
> os_host_main_loop_wait: polled for 10001.864258 ms (timeout: 1.946600 ms)
> ret: 0 nfds: 47
>
>
> On Wed, Oct 17, 2018 at 10:03 AM Paolo Bonzini <pbonzini@redhat.com>
> wrote:
>
>> On 17/10/2018 17:44, Frank Yang wrote:
>> >
>> > we are not seeing hangs in flatview_do_translate, but are still getting
>> > hangs in main-loop:
>> >
>> >     qemu_mutex_unlock_iothread();
>> >     replay_mutex_unlock();
>> >
>> >     ret = qemu_poll_ns((GPollFD *)gpollfds->data, gpollfds->len,
>> > timeout); <-------------this seems to be the hanging part
>> >
>> >     replay_mutex_lock();
>> >     qemu_mutex_lock_iothread();
>> >
>> > Any idea how to diagnose the cause of taking too much time in g_poll in
>> > qemu_poll_ns?
>>
>> Is there any event (timer or file descriptor) that you know should be
>> ready, but is not causing a wakeup?
>>
>> Paolo
>>
>