Re: [Qemu-devel] commit b1bbfe72 causes huge slowdown with no kvm

[Luigi Rizzo]

On Wed, Nov 20, 2013 at 10:41:22AM +0100, Paolo Bonzini wrote:
> Il 20/11/2013 00:00, Luigi Rizzo ha scritto:
> > I recently found out that without kvm enabled, and especially
> > with -smp 2 or greater, qemu becomes incredibly slow
> > (to the point that you can see kernel messages in the
> > quest print one character at a time).
> > 
> > This happens with a Linux host (even with -smp 1)
> > and with FreeBSD host (in this case -smp 2 or greater;
> > -smp 1 seems to work fine there).

Here is my test case that shows the problem:

HOW TO REPRODUCE:

    boot a (small) FreeBSD image below:

        http://info.iet.unipi.it/~luigi/20131119-picobsd.bin 

    with this command (note no kvm, also i disconnect the nic
    so i can generate traffic without causing trouble)

        x86_64-softmmu/qemu-system-x86_64 -m 1024 -hda 20131119-picobsd.bin 
-curses -monitor tcp::4444,server,nowait -net nic,model=e1000 -smp 2

    The image is readonly so you can kill the qemu without problems.

SYMPTOMS:
    as soon as the kernel starts its timer services (there is an
    active kernel thread woken up every millisecons) booting and
    runtime performance in the guest becomes terribly slow.
    See details on the test below.

HOST / OS
    Tried on a linux host (ubuntu 13.10 i believe, with kernel 3.11
    and CPU Intel(R) Core(TM) i5-3470 CPU @ 3.20GHz, but similar
    things occur also on a FreeBSD host. With a FreeBSD host,
    using -smp 1 seems to bypass the problem, whereas on Linux hosts
    the -smp setting does not seem to make a difference.

QEMU VERSION and MODIFICATIONS:

    > git branch -v
    * master     5c5432e Merge remote-tracking branch 'luiz/queue/qmp' into 
staging

    No changes other than the small diff i proposed to fix the problem:
    > git diff

    diff --git a/qemu-timer.c b/qemu-timer.c
    index e15ce47..4180a86 100644
    --- a/qemu-timer.c
    +++ b/qemu-timer.c
    @@ -380,6 +380,7 @@ static void timerlist_rearm(QEMUTimerList *timer_list)
     {
         /* Interrupt execution to force deadline recalculation.  */
         qemu_clock_warp(timer_list->clock->type);
    +if (use_icount) // XXX
         timerlist_notify(timer_list);
     }

DETAILED SYMPTOMS:

    WITH THE ABOVE PATCH, the kernel boots to a login prompt in 32
    seconds (10 of which are the initial pause, you can skip it
    by pressing enter). Then you can run the "pkt-gen" program which i
    normally use to test netmap performance in the guest, and you
    see between 2 and 3 million packets per second (the NIC is disconnected
    form the host so this should be harmles). Example:

        login: root
        Password: setup
        # pkt-gen -i em0 -f tx

        <should return something between 2 and 3 Mpps>
        <ctrl-c to terminate it >

    WITHOUT THE PATCH, booting becomes slow as soon as the timer tick starts
    and we load dummynet (which also starts a kernel thread every millisecond).
    You should be able to see how the printing of kernel messages slows down
    terribly around this point:

        ...
        Timecounters tick every 1.000 msec
          ipfw2 initialized, divert loadable, nat loadable, default to accept, 
logging disabled
          DUMMYNET 0 with IPv6 initialized (100409)
        ....

    and then it takes a long/varible time to reach the login prompt,
    easily a couple of minutes or more.
    If you start pkt-gen now, you should see a much lower rate,
    around 300-500Kpps



Since the problem seems timer-related, it makes sense that you are
not seeing much difference in linux which is probably tickless,
and that the trouble comes out on FreeBSD after the timers are
initialized.

But again I have no idea if my patch (which simply reverts part of
the offending commit) makes sense.

        cheers
        luigi


> 
> I could not reproduce it; the profile here seems normal, too:
> 
>  24,69%  perf-3281.map                       [.] 0x00007f4ab5ac9903
>  14,18%  qemu-system-x86_64                  [.] cpu_x86_exec
>   2,67%  libglib-2.0.so.0.3800.1             [.] g_source_iter_next
>   2,63%  qemu-system-x86_64                  [.] tcg_optimize
>   2,47%  qemu-system-x86_64                  [.] helper_pcmpeqb_xmm
>   2,28%  qemu-system-x86_64                  [.] phys_page_find
>   1,92%  qemu-system-x86_64                  [.] 
> address_space_translate_internal
>   1,53%  qemu-system-x86_64                  [.] tcg_liveness_analysis
>   1,40%  qemu-system-x86_64                  [.] tcg_reg_alloc_op
>   1,17%  qemu-system-x86_64                  [.] helper_psubb_xmm
>   0,97%  qemu-system-x86_64                  [.] disas_insn
>   0,96%  qemu-system-x86_64                  [.] cpu_x86_handle_mmu_fault
>   0,92%  qemu-system-x86_64                  [.] tcg_out_opc
>   0,92%  qemu-system-x86_64                  [.] helper_pmovmskb_xmm
>   0,91%  qemu-system-x86_64                  [.] tlb_set_page
>   0,75%  qemu-system-x86_64                  [.] address_space_translate
>   0,74%  qemu-system-x86_64                  [.] ldq_phys
>   0,61%  qemu-system-x86_64                  [.] tcg_gen_code
>   0,58%  qemu-system-x86_64                  [.] helper_le_ldq_mmu
>   0,56%  qemu-system-x86_64                  [.] helper_ctz
> 
> This is on Linux, -smp 2, booting a RHEL6.4 guest.
> 
> Paolo