Bug 609119

Summary: kvm takes a lot of CPU waiting in GRUB screen
Product: [Fedora] Fedora Reporter: Catalin BOIE <fedora-bugzilla>
Component: grubAssignee: Peter Jones <pjones>
Status: CLOSED WONTFIX QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 13CC: amit.shah, berrange, clalance, dwmw2, ehabkost, extras-orphan, gcosta, itamar, jaswinder, jforbes, jonathan, knoel, lkundrak, madhu.chinakonda, markmc, notting, ondrejj, pjones, quintela, scottt.tw, virt-maint
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 609383 (view as bug list) Environment:
Last Closed: 2011-06-27 19:08:02 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-06-29 13:24:02 UTC
Description of problem:
Fedora 13, booting a machine using the following line:
qemu-kvm -enable-kvm -cpu n270,+x2apic -M fedora-13 -m 512 -hda Stick-test.qcow2 -net nic,macaddr=00:11:11:11:11:72 -net tap,script=run.net -boot c -usb -usbdevice tablet -serial pty -vga cirrus

The guest is a Fedora 13 system.

The CPU is at 100%.
# lsof /dev/kvm returns:
/dev/kvm:             6123

# pstack 6123 (1):
Thread 2 (Thread 0xb757bb70 (LWP 6131)):
#0  0x0031a424 in __kernel_vsyscall ()
#1  0x0092e1f9 in ioctl () from /lib/libc.so.6
#2  0x080728e9 in kvm_run ()
#3  0x08072db2 in kvm_cpu_exec ()
#4  0x08073b43 in ap_main_loop ()
#5  0x00a19919 in start_thread () from /lib/libpthread.so.0
#6  0x00936dde in clone () from /lib/libc.so.6
Thread 1 (Thread 0xb787ea60 (LWP 6123)):
#0  0x0031a424 in __kernel_vsyscall ()
#1  0x0092f1d1 in select () from /lib/libc.so.6
#2  0x080516d2 in main_loop_wait ()
#3  0x0807053c in kvm_main_loop ()
#4  0x08054c7a in main ()

perf top reports:
14536.00 69.3% vmx_vcpu_run                [kvm_intel]             
491.00  2.3% ksm_scan_thread             [kernel.kallsyms]       
416.00  2.0% follow_page                 [kernel.kallsyms]       
376.00  1.8% native_flush_tlb_single     [kernel.kallsyms]       
262.00  1.2% find_vma                    [kernel.kallsyms]       
235.00  1.1% __might_sleep               [kernel.kallsyms]    


Version-Release number of selected component (if applicable):
qemu-kvm-0.12.3-8.fc13.i686

How reproducible:
Always.

Steps to Reproduce:
1.
2.
3.
  
Actual results:
Lots of CPU used by doing almost nothing.

Expected results:
Almost zero CPU.

Additional info:

Comment 1 Catalin BOIE 2010-06-29 13:26:03 UTC
strace:
16:25:26.798910 gettimeofday({1277817926, 798923}, NULL) = 0
16:25:26.798954 select(19, [5 8 10 16 18], [], [], {1, 0}) = 3 (in [5 16 18], left {0, 999997})
16:25:26.799018 read(18, "\16\0\0\0\0\0\0\0\376\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
16:25:26.799083 rt_sigaction(SIGALRM, NULL, {0x80519c0, ~[KILL STOP RTMIN RT_1], 0}, 8) = 0
16:25:26.799162 write(6, "\0", 1)       = 1
16:25:26.799553 write(17, "\1\0\0\0\0\0\0\0", 8) = 8
16:25:26.799623 read(18, 0xbfd8457c, 128) = -1 EAGAIN (Resource temporarily unavailable)
16:25:26.799664 read(16, "\2\0\0\0\0\0\0\0", 4096) = 8
16:25:26.799710 read(16, 0xbfd8360c, 4096) = -1 EAGAIN (Resource temporarily unavailable)
16:25:26.799750 read(5, "\0\0", 512)    = 2
16:25:26.799793 read(5, 0xbfd8440c, 512) = -1 EAGAIN (Resource temporarily unavailable)
16:25:26.799835 clock_gettime(CLOCK_MONOTONIC, {2786898, 619445093}) = 0
16:25:26.799876 gettimeofday({1277817926, 799889}, NULL) = 0
16:25:26.799917 clock_gettime(CLOCK_MONOTONIC, {2786898, 619527481}) = 0
16:25:26.799958 timer_gettime(0, {it_interval={0, 0}, it_value={0, 0}}) = 0
16:25:26.800548 timer_settime(0, 0, {it_interval={0, 0}, it_value={0, 250000}}, NULL) = 0
16:25:26.800601 clock_gettime(CLOCK_MONOTONIC, {2786898, 620212611}) = 0
16:25:26.800646 clock_gettime(CLOCK_MONOTONIC, {2786898, 620256359}) = 0
16:25:26.800688 clock_gettime(CLOCK_MONOTONIC, {2786898, 620298276}) = 0
16:25:26.800729 gettimeofday({1277817926, 800742}, NULL) = 0
16:25:26.800770 clock_gettime(CLOCK_MONOTONIC, {2786898, 620380571}) = 0
16:25:26.800812 timer_gettime(0, {it_interval={0, 0}, it_value={0, 1929}}) = 0
16:25:26.801425 clock_gettime(CLOCK_MONOTONIC, {2786898, 621038785}) = 0
16:25:26.801471 gettimeofday({1277817926, 801485}, NULL) = 0
16:25:26.801518 select(19, [5 8 10 16 18], [], [], {1, 0}) = 1 (in [18], left {0, 999994})
16:25:26.801604 read(18, "\16\0\0\0\0\0\0\0\376\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128
16:25:26.801672 rt_sigaction(SIGALRM, NULL, {0x80519c0, ~[KILL STOP RTMIN RT_1], 0}, 8) = 0
16:25:26.801757 write(6, "\0", 1)       = 1
16:25:26.802571 write(17, "\1\0\0\0\0\0\0\0", 8) = 8
16:25:26.813892 read(18, 0xbfd8457c, 128) = -1 EAGAIN (Resource temporarily unavailable)
16:25:26.813959 clock_gettime(CLOCK_MONOTONIC, {2786898, 633572383}) = 0
16:25:26.814009 gettimeofday({1277817926, 814024}, NULL) = 0
16:25:26.814054 clock_gettime(CLOCK_MONOTONIC, {2786898, 633665631}) = 0
16:25:26.814098 timer_gettime(0, {it_interval={0, 0}, it_value={0, 0}}) = 0
16:25:26.814148 timer_settime(0, 0, {it_interval={0, 0}, it_value={0, 250000}}, NULL) = 0
16:25:26.814199 clock_gettime(CLOCK_MONOTONIC, {2786898, 633810858}) = 0
16:25:26.814246 clock_gettime(CLOCK_MONOTONIC, {2786898, 633867104}) = 0
16:25:26.814299 clock_gettime(CLOCK_MONOTONIC, {2786898, 633911283}) = 0
16:25:26.814343 gettimeofday({1277817926, 814357}, NULL) = 0
16:25:26.814386 clock_gettime(CLOCK_MONOTONIC, {2786898, 633997170}) = 0
16:25:26.814431 timer_gettime(0, {it_interval={0, 0}, it_value={0, 0}}) = 0
16:25:26.814480 timer_settime(0, 0, {it_interval={0, 0}, it_value={0, 250000}}, NULL) = 0

Comment 2 Catalin BOIE 2010-06-29 13:37:08 UTC
Host kernel: 2.6.33.4-95.fc13.i686.PAE

Pressing CTRL+B in SeaBIOS and getting the prompts, the CPU is just fine.

Comment 3 Glauber Costa 2010-06-29 17:12:59 UTC
By the description, it sounds like an instruction emulation issue.

Can you post the output of kvm_stat at the moment it happens? Anything suspicions in dmesg?

Comment 4 Catalin BOIE 2010-06-30 06:05:53 UTC
Nothing in dmesg.

Please note that as long as I stay in the grub menu, the CPU is at 100%. So, it happens every time.

kvm statistics

 efer_reload                  0       0
 exits                   895013    2514
 fpu_reload               38598    1045
 halt_exits                  23       0
 halt_wakeup                  1       0
 host_state_reload       105504    1047
 hypercalls                   0       0
 insn_emulation          755807       0
 insn_emulation_fail          0       0
 invlpg                       0       0
 io_exits                 79510      18
 irq_exits                33670    1507
 irq_injections             567      18
 irq_window                 373      10
 largepages                   0       0
 mmio_exits                2731       0
 mmu_cache_miss             167       0
 mmu_flooded                  0       0
 mmu_pde_zapped               0       0
 mmu_pte_updated              0       0
 mmu_pte_write            56339       0
 mmu_recycled                 0       0
 mmu_shadow_zapped          268       0
 mmu_unsync                   0       0
 nmi_injections               0       0
 nmi_window                   0       0
 pf_fixed                   643       0
 pf_guest                     0       0
 remote_tlb_flush             3       0
 request_irq                  0       0
 signal_exits                 1       0
 tlb_flush                    0       0

Comment 5 Avi Kivity 2010-07-03 16:59:56 UTC
It's probably grub spinning instead of waiting for an interrupt when it has nothing to do.

Comment 6 Avi Kivity 2010-07-03 17:38:53 UTC
Sticking an 

   asm volatile ("hlt");

at the end of the first while (1) loop in stage2.c:run_menu() should improve things.

Comment 7 Bug Zapper 2011-06-01 15:16:23 UTC
This message is a reminder that Fedora 13 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 13.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '13'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 13's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 13 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 8 Bug Zapper 2011-06-27 19:08:02 UTC
Fedora 13 changed to end-of-life (EOL) status on 2011-06-25. Fedora 13 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.