Bug 970047

I don't understand step 2 in comment 0:

qemu#c

Thanks.

(In reply to Laszlo Ersek from comment #2)
> I don't understand step 2 in comment 0:
> 
> qemu#c
> 
> Thanks.

Hi Laszlo,

the vm was launched w/ a '-S' option, that means paused state,
and a 'c' would push it into running status.
if launch the vm w/o a -S, then the step 2 is not necessary.


Regards,
Xiaoqing.

Hi,

another question: what tool generated the qemu-kvm command line? For example, where does "-no-kvm-pit-reinjection" come from, and why is it necessary?

I'll try to reserve a similar machine in Beaker (given '-cpu host').

Thanks.

(In reply to Laszlo Ersek from comment #4)
> Hi,
> 
> another question: what tool generated the qemu-kvm command line? For
> example, where does "-no-kvm-pit-reinjection" come from, and why is it
> necessary?
> 
> I'll try to reserve a similar machine in Beaker (given '-cpu host').
> 
> Thanks.

Hi Laszlo,

the cmd is generated from autotest, to prevent some guest timedrift.

Regards.

The IO thread is spinning as follows:

    main_loop_wait()
      slirp_pollfds_fill()
      qemu_iohandler_fill()
(1)
      os_host_main_loop_wait()
        glib_pollfds_fill()
          g_main_context_query()
(2)
        g_poll()
        glib_pollfds_poll()
      qemu_iohandler_poll()
      slirp_pollfds_poll()

At (1), just before entering os_host_main_loop_wait(), this is the contents
of the gpollfds array (length 3):

  (gdb) print *(GPollFD (*)[3])gpollfds->data
  $24 = {{fd = 21, events = 25, revents = 0},
         {fd = 11, events = 25, revents = 0},
         {fd = 3, events = 25, revents = 0}}

Inside glib_pollfds_fill(), the value of "glib_n_poll_fds" is huge:

  (gdb) print glib_n_poll_fds
  $26 = 2897

The new size of the array is 3 + 2897 == 2900.

After glib_pollfds_fill() returns, ie. at (2), just before
os_host_main_loop_wait() calls g_poll(), the contents of the array is
(length 2900):

  (gdb) print *(GPollFD (*)[2900])gpollfds->data
  $34 = {{fd = 21, events = 25, revents = 0},
         {fd = 11, events = 25, revents = 0},
         {fd = 3, events = 25, revents = 0},
         {fd = 5, events = 1, revents = 0},
         {fd = 6, events = 1, revents = 0},
         {fd = 7, events = 1, revents = 0},
         {fd = 8, events = 1, revents = 0},
         {fd = 16, events = 1, revents = 0},
         {fd = 14, events = 1, revents = 0},
         {fd = 13, events = 1, revents = 0},
         {fd = 4, events = 1, revents = 0},
         {fd = 1, events = 4, revents = 0} <repeats 2888 times>,
         {fd = 0, events = 1, revents = 0}}

The standard output is placed 2888 times in the array. events = 4 is
POLLOUT. (G_IO_OUT / GLIB_SYSDEF_POLLOUT are identity mapped to POLLOUT,
most likely.)

When we invoke g_poll() (which is only a thin wrapper around poll(); GPollFD
being "struct pollfd" in fact), it returns -1, and sets errno to EINVAL
(errno 22).

The poll(2) manual says,

  EINVAL The nfds value exceeds the RLIMIT_NOFILE value.

and do_sys_poll() in "fs/select.c" seems to confirm that that's the only
EINVAL case.


This instance of qemu-kvm was started with "-monitor stdio". Apparently,
each one of the huge number of lines printed to the stdout monitor by "info
tlb" leaks a GPollFD.

Printing to the monitor is implemented by:

  tlb_info()
    ...
      print_pte()
        monitor_printf()
          monitor_vprintf()
            monitor_puts()
              monitor_flush()
                qemu_chr_fe_write()
                  io_channel_send() (*)
                    g_io_channel_write_chars()
                qemu_chr_fe_add_watch()
                  fd_chr_add_watch() (*)
                    g_io_create_watch()
                  g_source_set_callback()
                  g_source_attach()

(*)

  (gdb) print default_mon->chr->chr_write
  $44 = (int (*)(struct CharDriverState *, const uint8_t *, int))
        0x7f6010ab29f0 <fd_chr_write>

  (gdb) print default_mon->chr->chr_add_watch
  $45 = (GSource *(*)(struct CharDriverState *, GIOCondition))
        0x7f6010ab2870 <fd_chr_add_watch>

monitor_flush() intends to reinstall the watch (by calling
qemu_chr_fe_add_watch()) only if the write in qemu_chr_fe_write() is
partial, but I think that logic doesn't work for some reason.

Something's wrong between monitor_flush() and io_channel_send(). The former
doesn't handle negative return values (errors), it reinstalls the watch
all the same.

The latter (even in upstream!) fails to increment "offset" with
"bytes_written" in some cases, possibly reporting a partial write to
monitor_flush() rather than a full write. This would be consistent with the
symptoms.

The GLib documentation clearly states that "bytes_written" can be set to
nonzero independently of g_io_channel_write_chars()'s retval.


I'll write a patch for QE to test (apparently this test case can easily
reproduce the problem).

Created attachment 774372 [details]
proposed patch

Hmm, no. Even though I think io_channel_send() could be improved, that function doesn't fully explain how so many watches / GPollFDs accrue. Extraneously reinstalling a watch in monitor_flush() would not *increase* the number of watches, just keep it unchanged in the longer term, because monitor_unblocked(), the callback for the watch, returns FALSE, which removes the watch automatically.

Perhaps the other call chain to monitor_flush() is the culprit. tlb_info() (indirectly) invokes monitor_flush() very many times in quick succession. (Each print_pte() call ends with a newline character.)

mon->outbuf may keep growing and growing, hence the chance to a complete write decreases. After a point probably all writes are incomplete, and from that point onward each print_pte() -- ie. monitor_flush() -- call will add a brand new watch.

On the non-callback-initiated call path, no watch should be added if there's already one watch in place.

Indeed. See usbredir_write() and usbredir_write_unblocked(): they track the one watch in dev->watch. (Upstream commit c874ea97.)

Exact same pattern in flush_buf() [hw/char/virtio-console.c] and chr_write_unblocked(), same file: they track vcon->watch. (Upstream commit c3d6b96e, again by Hans.)

Created attachment 774410 [details]
proposed patch (additional)

Posted upstream series: http://thread.gmane.org/gmane.comp.emulators.qemu/222525

upstream commits:

     1  ac8c26f char: io_channel_send: don't lose written bytes
     2  293d2a0 monitor: maintain at most one G_IO_OUT watch

Fix included in qemu-kvm-1.5.2-3.el7

Verified the bug on qemu-kvm-1.5.3-31.el7.x86_64.

Steps:

(1) In terminal A, issue the following commands:

    mkfifo fifo.in fifo.out
    /usr/libexec/qemu-kvm -chardev pipe,id=fifo,path=fifo \
        -mon chardev=fifo,default

(2) In terminal B, issue the following command (same directory):

  cat fifo.out

(3) In terminal C, issue the following command (same directory):

  cat >fifo.in

(4) Still in terminal C, type the following command, and verify that its output appears in terminal B:

  info registers

(5) In terminal B, press ^Z (ie. stop (but do not kill) the "cat" process reading from "fifo.out").

(6) In terminal C, repeat the following command indefinitely (it's simples to keep pasting it from the clipboard):

  info registers

Result:
Qemu process does not die after 300 times "info registers" input.

So, this issue is fixed.

This request was resolved in Red Hat Enterprise Linux 7.0.

Contact your manager or support representative in case you have further questions about the request.