Re: [Qemu-devel] Windows slow boot: contractor wanted

[Richard Davies]

Avi Kivity wrote:
> Richard Davies wrote:
> > We're running host kernel 3.5.1 and qemu-kvm 1.1.1.
> >
> > I hadn't though about it, but I agree this is related to cpu overcommit. The
> > slow boots are intermittent (and infrequent) with cpu overcommit whereas I
> > don't think it occurs without cpu overcommit.
> >
> > In addition, if there is a slow boot ongoing, and you kill some other VMs to
> > reduce cpu overcommit then this will sometimes speed it up.
> >
> > I guess the question is why even with overcommit most boots are fine, but
> > some small fraction then go slow?
>
> Could be a bug.  The scheduler and the spin-loop handling code fight
> each other instead of working well.
>
> Please provide snapshots of 'perf top' while a slow boot is in progress.

Below are two 'perf top' snapshots during a slow boot, which appear to me to
support your idea of a spin-lock problem.

There are a lot more "unprocessable samples recorded" messages at the end of
each snapshot which I haven't included. I think these may be from the guest
OS - the kernel is listed, and qemu-kvm itself is listed on some other
traces which I did, although not these.

Richard.



   PerfTop:   62249 irqs/sec  kernel:96.9%  exact:  0.0% [4000Hz cycles],  
(all, 16 CPUs)
--------------------------------------------------------------------------------------------------------------------------------

    35.80%  [kernel]          [k] _raw_spin_lock_irqsave
    21.64%  [kernel]          [k] isolate_freepages_block
     5.91%  [kernel]          [k] yield_to
     4.95%  [kernel]          [k] _raw_spin_lock
     3.37%  [kernel]          [k] kvm_vcpu_on_spin
     2.74%  [kernel]          [k] add_preempt_count
     2.45%  [kernel]          [k] _raw_spin_unlock
     2.33%  [kernel]          [k] sub_preempt_count
     2.18%  [kernel]          [k] svm_vcpu_run
     2.17%  [kernel]          [k] kvm_vcpu_yield_to
     1.89%  [kernel]          [k] memcmp
     1.50%  [kernel]          [k] get_pid_task
     1.26%  [kernel]          [k] kvm_arch_vcpu_ioctl_run
     1.16%  [kernel]          [k] pid_task
     0.70%  [kernel]          [k] rcu_note_context_switch
     0.70%  [kernel]          [k] trace_hardirqs_on
     0.52%  [kernel]          [k] __rcu_read_unlock
     0.51%  [kernel]          [k] trace_preempt_on
     0.47%  [kernel]          [k] __srcu_read_lock
     0.43%  [kernel]          [k] get_parent_ip
     0.42%  [kernel]          [k] get_pageblock_flags_group
     0.38%  [kernel]          [k] in_lock_functions
     0.34%  [kernel]          [k] trace_preempt_off
     0.34%  [kernel]          [k] trace_hardirqs_off
     0.29%  [kernel]          [k] clear_page_c
     0.23%  [kernel]          [k] __srcu_read_unlock
     0.20%  [kernel]          [k] __rcu_read_lock
     0.14%  [kernel]          [k] handle_exit
     0.11%  libc-2.10.1.so    [.] strcmp
     0.11%  [kernel]          [k] _raw_spin_unlock_irqrestore
     0.11%  [kernel]          [k] _raw_spin_lock_irq
     0.11%  [kernel]          [k] find_highest_vector
     0.09%  [kernel]          [k] ktime_get
     0.08%  [kernel]          [k] copy_page_c
     0.08%  [kernel]          [k] pause_interception
     0.08%  [kernel]          [k] kmem_cache_alloc
     0.08%  [kernel]          [k] resched_task
     0.08%  perf              [.] dso__find_symbol
     0.06%  [kernel]          [k] compaction_alloc
     0.06%  libc-2.10.1.so    [.] 0x0000000000076dab
     0.06%  [kernel]          [k] read_tsc
     0.06%  perf              [.] add_hist_entry
     0.05%  [kernel]          [k] svm_read_l1_tsc
     0.05%  [kernel]          [k] native_read_tsc
     0.05%  perf              [.] sort__dso_cmp
     0.05%  [kernel]          [k] copy_user_generic_string
     0.05%  [kernel]          [k] ktime_get_update_offsets
     0.04%  [kernel]          [k] kvm_check_async_pf_completion
     0.04%  [kernel]          [k] __schedule
     0.04%  [kernel]          [k] __rcu_pending
     0.04%  [kernel]          [k] svm_complete_interrupts
     0.04%  [kernel]          [k] perf_pmu_disable
     0.04%  [kernel]          [k] isolate_migratepages_range
     0.04%  [kernel]          [k] sched_clock_cpu
     0.04%  [kernel]          [k] kvm_cpu_has_pending_timer
     0.04%  [kernel]          [k] apic_timer_interrupt
     0.04%  [vdso]            [.] 0x00007fff2e1ff607
     0.04%  [kernel]          [k] apic_update_ppr
     0.04%  [kernel]          [k] do_select
     0.04%  [kernel]          [k] svm_scale_tsc
     0.04%  [kernel]          [k] system_call_after_swapgs
     0.03%  [kernel]          [k] kvm_lapic_get_cr8
     0.03%  perf              [.] sort__sym_cmp
     0.03%  [kernel]          [k] find_next_bit
     0.03%  [kernel]          [k] kvm_set_cr8
     0.03%  [kernel]          [k] rcu_check_callbacks
9750 unprocessable samples recorded.9751 unprocessable samples recorded.9752 
unprocessable samples recorded.9753 unprocessable samples recorded.9754 
unprocessable samples recorded.9755 unprocessable samples recorded.9756 
unprocessable samples recorded.9757 u    nprocessable samples recorded.9758 
unprocessable samples recorded.9759 unprocessable samples recorded.9760 
unprocessable samples     recorded.9761 unprocessable samples recorded.9762 
unprocessable samples recorded.9763 unprocessable samples recorded.



   PerfTop:   61584 irqs/sec  kernel:97.4%  exact:  0.0% [4000Hz cycles],  
(all, 16 CPUs)
--------------------------------------------------------------------------------------------------------------------------------

    36.73%  [kernel]          [k] _raw_spin_lock_irqsave
    19.00%  [kernel]          [k] isolate_freepages_block
     5.80%  [kernel]          [k] yield_to
     5.23%  [kernel]          [k] _raw_spin_lock
     3.97%  [kernel]          [k] kvm_vcpu_on_spin
     2.98%  [kernel]          [k] add_preempt_count
     2.45%  [kernel]          [k] sub_preempt_count
     2.37%  [kernel]          [k] _raw_spin_unlock
     2.22%  [kernel]          [k] svm_vcpu_run
     2.19%  [kernel]          [k] kvm_vcpu_yield_to
     1.90%  [kernel]          [k] memcmp
     1.54%  [kernel]          [k] get_pid_task
     1.39%  [kernel]          [k] kvm_arch_vcpu_ioctl_run
     1.30%  [kernel]          [k] pid_task
     0.75%  [kernel]          [k] rcu_note_context_switch
     0.74%  [kernel]          [k] trace_hardirqs_on
     0.58%  [kernel]          [k] __rcu_read_unlock
     0.55%  [kernel]          [k] trace_preempt_on
     0.47%  [kernel]          [k] __srcu_read_lock
     0.44%  [kernel]          [k] get_parent_ip
     0.41%  [kernel]          [k] clear_page_c
     0.40%  [kernel]          [k] get_pageblock_flags_group
     0.39%  [kernel]          [k] in_lock_functions
     0.36%  [kernel]          [k] trace_preempt_off
     0.35%  [kernel]          [k] trace_hardirqs_off
     0.23%  [kernel]          [k] __srcu_read_unlock
     0.20%  [kernel]          [k] __rcu_read_lock
     0.15%  [kernel]          [k] _raw_spin_lock_irq
     0.14%  [kernel]          [k] handle_exit
     0.12%  [kernel]          [k] find_highest_vector
     0.11%  [kernel]          [k] resched_task
     0.10%  libc-2.10.1.so    [.] strcmp
     0.09%  [kernel]          [k] _raw_spin_unlock_irqrestore
     0.09%  [kernel]          [k] ktime_get
     0.08%  [kernel]          [k] pause_interception
     0.08%  [kernel]          [k] copy_page_c
     0.07%  [kernel]          [k] __schedule
     0.07%  [kernel]          [k] compact_zone
     0.07%  perf              [.] dso__find_symbol
     0.06%  perf              [.] add_hist_entry
     0.06%  [kernel]          [k] read_tsc
     0.06%  [kernel]          [k] svm_read_l1_tsc
     0.05%  [kernel]          [k] native_read_tsc
     0.05%  [kernel]          [k] ktime_get_update_offsets
     0.05%  [kernel]          [k] compaction_alloc
     0.05%  libc-2.10.1.so    [.] 0x0000000000073ae0
     0.05%  [kernel]          [k] kmem_cache_alloc
     0.05%  [kernel]          [k] svm_complete_interrupts
     0.05%  [kernel]          [k] kvm_check_async_pf_completion
     0.05%  [kernel]          [k] apic_timer_interrupt
     0.05%  perf              [.] sort__dso_cmp
     0.05%  [kernel]          [k] kvm_cpu_has_pending_timer
     0.04%  [kernel]          [k] svm_scale_tsc
     0.04%  [kernel]          [k] isolate_migratepages_range
     0.04%  [kernel]          [k] sched_clock_cpu
     0.04%  [kernel]          [k] __rcu_pending
     0.04%  [kernel]          [k] apic_update_ppr
     0.04%  [kernel]          [k] do_select
     0.04%  [kernel]          [k] perf_pmu_disable
     0.04%  [kernel]          [k] kvm_set_cr8
     0.04%  [kernel]          [k] update_curr
     0.04%  [kernel]          [k] reschedule_interrupt
     0.03%  [kernel]          [k] kvm_lapic_get_cr8
     0.03%  libc-2.10.1.so    [.] strstr
     0.03%  [kernel]          [k] apic_has_pending_timer
     0.03%  perf              [.] sort__sym_cmp
4963 unprocessable samples recorded.4964 unprocessable samples recorded.4965 
unprocessable samples recorded.4966 unprocessable samples recorded.4967 
unprocessable samples recorded.4968 unprocessable samples recorded.4969 
unprocessable samples recorded.4970 unprocessable samples recorded.4971 
unprocessable samples recorded.4972 unprocessable samples recorded.4973 
unprocessable samples recorded.4974 unprocessable samples recorded.4975 
unprocessable samples recorded.