Bug 576924

Summary: KVM is too slow (~16% of the time is spent in disas_insn) and the load is high (15%)
Product: [Fedora] Fedora Reporter: Catalin BOIE <fedora-bugzilla>
Component: kvmAssignee: Glauber Costa <gcosta>
Status: CLOSED NOTABUG QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 12CC: berrange, clalance, ehabkost, gcosta, knoel, markmc, quintela, virt-maint
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2010-03-27 12:29:49 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Catalin BOIE 2010-03-25 16:10:40 UTC 
Description of problem:

Running a F13alpha guest under a F12 host eats around 15% of a core. This seems too much. In this time the guest do almost nothing.
Host is running 32 bits, guest is 32 bits.
Even if guest in text mode, the same 16% are used by 'disas_insn'.

Version-Release number of selected component (if applicable):

qemu-kvm-0.11.0-13.fc12.i686

How reproducible:
Run a F13alpha under a F12 host and run 'perf record --pid <pid_of_qemu>'.

Steps to Reproduce:
1.
2.
3.
  
Actual results:
Guests puts a lot of load on the host.

Expected results:
Guest, if idle, should generate less load on the host.

Additional info:
15.92%  qemu-kvm  /usr/bin/qemu-kvm          [.] disas_insn
 7.07%  qemu-kvm  /lib/libc-2.11.1.so        [.] __GI_memcpy
 4.59%  qemu-kvm  /usr/bin/qemu-kvm          [.] 0x00000000187280
 4.35%  qemu-kvm  /usr/bin/qemu-kvm          [.] main
 2.63%  qemu-kvm  [kernel]                   [k] fget_light
 2.60%  qemu-kvm  [kernel]                   [k] system_call
 2.25%  qemu-kvm  [kernel]                   [k] do_select
 2.09%  qemu-kvm  /lib/librt-2.11.1.so       [.] __GI_clock_gettime
 1.99%  qemu-kvm  /usr/bin/qemu-kvm          [.] gen_shift_rm_T1
 1.89%  qemu-kvm  [kernel]                   [k] _spin_lock_irqsave
 1.78%  qemu-kvm  [kernel]                   [k] fput
 1.63%  qemu-kvm  [kernel]                   [k] avc_has_perm_noaudit
 1.57%  qemu-kvm  [kernel]                   [k] sysenter_past_esp
 1.54%  qemu-kvm  [kernel]                   [k] _spin_unlock_irqrestore

Please let me know if this behaviour is normal or if I can help with more data.
Comment 1 Catalin BOIE 2010-03-26 07:28:34 UTC 
After a night, I can provide some missing information:
SELinux in enforcing, hardware virtualization enabled and used.

That 15% is from a host core, maybe was not clear.

Guest has 1 CPU.

Host details:
processor	: 1
vendor_id	: GenuineIntel
cpu family	: 6
model		: 15
model name	: Intel(R) Core(TM)2 CPU          6400  @ 2.13GHz
stepping	: 6
cpu MHz		: 1600.000
cache size	: 2048 KB
physical id	: 0
siblings	: 2
core id		: 1
cpu cores	: 2
apicid		: 1
initial apicid	: 1
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 10
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe nx lm constant_tsc arch_perfmon pebs bts aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm lahf_lm tpr_shadow
bogomips	: 4266.54
clflush size	: 64
cache_alignment	: 64
address sizes	: 36 bits physical, 48 bits virtual
Comment 2 Avi Kivity 2010-03-27 12:29:49 UTC 
disas_insn() is only run in tcg mode.  Make sure you processor supports hardware virtualization and that the kvm modules are loaded.
Comment 3 Catalin BOIE 2010-03-29 06:04:09 UTC 
lsmod|grep kvm
kvm_intel              34764  3 
kvm                   205352  1 kvm_intel

ps ax|grep kvm
/usr/bin/qemu-kvm -S -M pc-0.11 -m 512 -smp 1 -name f13alpha -uuid ca7ce04f-3482-cea9-876b-e17667d65ed9 -monitor unix:/var/lib/libvirt/qemu/f13alpha.monitor,server,nowait -boot c -drive file=/var/lib/libvirt/images/f13alpha.img,if=virtio,index=0,boot=on,format=qcow2 -drive file=/var/lib/libvirt/images/Fedora-13-Alpha-i386-DVD.iso,if=ide,media=cdrom,index=2,format=raw -net nic,macaddr=52:54:00:15:e1:a5,vlan=0,model=virtio,name=virtio.0 -net tap,fd=17,vlan=0,name=tap.0 -serial pty -parallel none -usb -usbdevice tablet -vnc 127.0.0.1:1 -k en-us -vga cirrus -soundhw es1370

Seems that kvm is used, right?

But, surprise, perf says:
     8.37%  qemu-kvm  /usr/bin/qemu-kvm          [.] slirp_init
     6.15%  qemu-kvm  /lib/libc-2.11.1.so        [.] __GI_memcpy
     3.54%  qemu-kvm  /usr/bin/qemu-kvm          [.] main
     3.25%  qemu-kvm  /usr/bin/qemu-kvm          [.] cpu_x86_exec
     2.76%  qemu-kvm  /usr/bin/qemu-kvm          [.] watch_mem_writel
     2.35%  qemu-kvm  [kernel]                   [k] fget_light
     2.27%  qemu-kvm  [kernel]                   [k] system_call
     1.87%  qemu-kvm  /usr/bin/qemu-kvm          [.] gen_helper_cmpneqpd
     1.85%  qemu-kvm  [kernel]                   [k] do_select
     1.78%  qemu-kvm  /lib/librt-2.11.1.so       [.] __GI_clock_gettime
     1.68%  qemu-kvm  [kernel]                   [k] _spin_lock_irqsave
     1.60%  qemu-kvm  /usr/bin/qemu-kvm          [.] m_copy
     1.59%  qemu-kvm  /usr/bin/qemu-kvm          [.] dsp_write
     1.56%  qemu-kvm  [kernel]                   [k] fput
     1.33%  qemu-kvm  [kernel]                   [k] _spin_unlock_irqrestore
     1.33%  qemu-kvm  /usr/bin/qemu-kvm          [.] watch_mem_writew
     1.32%  qemu-kvm  [kernel]                   [k] sysenter_past_esp

So, no trace of disas_insn(). Very strange.

But, the load on the host is still at 15% when the guest is in text mode and running nothing (almost). New perf report:
     7.09%  qemu-kvm  /lib/libc-2.11.1.so        [.] __GI_memcpy
     4.00%  qemu-kvm  /usr/bin/qemu-kvm          [.] cpu_x86_exec
     3.63%  qemu-kvm  /usr/bin/qemu-kvm          [.] main
     3.63%  qemu-kvm  /usr/bin/qemu-kvm          [.] watch_mem_writel
     2.74%  qemu-kvm  [kernel]                   [k] system_call
     2.68%  qemu-kvm  /usr/bin/qemu-kvm          [.] gen_helper_cmpneqpd
     2.51%  qemu-kvm  [kernel]                   [k] fget_light
     2.40%  qemu-kvm  /lib/librt-2.11.1.so       [.] __GI_clock_gettime
     2.24%  qemu-kvm  [kernel]                   [k] do_select
     2.03%  qemu-kvm  [kernel]                   [k] _spin_lock_irqsave
     1.86%  qemu-kvm  [kernel]                   [k] _spin_unlock_irqrestore
     1.85%  qemu-kvm  /usr/bin/qemu-kvm          [.] watch_mem_writew
     1.77%  qemu-kvm  [kernel]                   [k] fput
     1.69%  qemu-kvm  [kernel]                   [k] sysenter_past_esp
     1.53%  qemu-kvm  /usr/bin/qemu-kvm          [.] sunkbd_event
     1.43%  qemu-kvm  /usr/bin/qemu-kvm          [.] gen_helper_cmpunordss
     1.42%  qemu-kvm  /usr/bin/qemu-kvm          [.] gen_helper_cmpltpd

It is normal?
Thank you!
Comment 4 Catalin BOIE 2010-03-29 06:58:42 UTC 
More data:

Guest:
# init 1: what remain running:
udev and init, modules: ipv6, sunrpc and virtio_blk.

Host:
Around 12% CPU usage for qemu-kvm process; perf:

samples    pcnt   kernel function
_______   _____   _______________

 816.00 -  5.2% : fget_light
 762.00 -  4.9% : system_call
 672.00 -  4.3% : do_select
 599.00 -  3.8% : _spin_lock_irqsave
 569.00 -  3.6% : fput
 512.00 -  3.3% : sysenter_past_esp
 458.00 -  2.9% : _spin_unlock_irqrestore
 391.00 -  2.5% : avc_has_perm_noaudit
 382.00 -  2.4% : copy_from_user
 336.00 -  2.1% : copy_to_user
 291.00 -  1.9% : ktime_get_ts
 290.00 -  1.9% : read_tsc
 288.00 -  1.8% : audit_syscall_entry
 259.00 -  1.7% : _spin_lock_irq
 247.00 -  1.6% : __copy_to_user_ll

12% seems too much for a idle guest, isn't it?
Comment 5 Glauber Costa 2010-03-29 13:21:53 UTC 
kvm module being loaded, does not mean kvm is necessarily being used. Your bios can disable it, for example. If this is the case, your dmesg should be saying something.
Comment 6 Catalin BOIE 2010-03-29 13:29:36 UTC 
lsmod|grep kvm
kvm_intel              34764  3 
kvm                   205352  1 kvm_intel

dmesg | grep -i kvm:
kvm: emulating exchange as write

Reference count 3 means that is used, right?
Comment 7 Avi Kivity 2010-04-03 13:53:48 UTC 
Yes.  But gen_helper_cmpneqpd() means it isn't used by the qemu you are tracing.

Please make sure there is only one qemu-kvm running and that it is using kvm (verify using lsof).
Comment 8 Catalin BOIE 2010-04-06 09:55:37 UTC 
# fuser /dev/kvm -> nothing

Started a f13 guest

fuser /dev/kvm returns only one pid: 6457 (correct one)

ps ax|grep 6457:
6457 ?        Sl     1:03 /usr/bin/qemu-kvm -S -M pc-0.11 -m 512 -smp 1 -name f13alpha -uuid ca7ce04f-3482-cea9-876b-e17667d65ed9 -monitor unix:/var/lib/libvirt/qemu/f13alpha.monitor,server,nowait -boot c -drive file=/var/lib/libvirt/images/f13alpha.img,if=virtio,index=0,boot=on,format=qcow2 -net none -serial none -parallel none -usb -vnc 127.0.0.1:1 -k en-us -vga cirrus

Inside guest:
init 1

perf top --pid=6457:
               54.00 -  8.3% : fget_light
               44.00 -  6.8% : system_call
               41.00 -  6.3% : do_select
               35.00 -  5.4% : _spin_lock_irqsave
               33.00 -  5.1% : fput
               33.00 -  5.1% : sysenter_past_esp
               32.00 -  4.9% : avc_has_perm_noaudit
               26.00 -  4.0% : _spin_unlock_irqrestore
               21.00 -  3.2% : __might_sleep
               17.00 -  2.6% : copy_to_user
               16.00 -  2.5% : ktime_get_ts
               16.00 -  2.5% : copy_from_user
               15.00 -  2.3% : read_tsc
               11.00 -  1.7% : audit_syscall_entry
               11.00 -  1.7% : audit_syscall_exit

Host load is at around 1%.

I do not understand why I cannot reproduce anymore!

So, let's close it and I will reopen it if I can reproduce.