virtualbox consumes all CPU -> IO-APIC

I attempted to use oprofile the other day on my Ubunut Gutsy box to find out where all of this CPU usage is happening but it would seem that the combination of oprofile and VirtualBox causes my machine to spontaneously reboot. I don't have a serial console on it yet to see what the problem is exactly, but when I do, I will update this ticket.

Any ideas in the meanwhile are much welcome.

Just to keep this issue accurately detailed, I have upgraded to the PUEL 1.6.0 release and the same problems occur. I wonder if oprofile will at least work. I will update here if it does.

Hrm. 1.6.0 is in fact worse. Mouse integration doesn't work, but never did in 1.5.6 -- I had to disable the mouse integration and explicitly click in the window to get the mouse in the guest.

But in 1.6.0 when I click in the guest window it appears that the guest gets the focus, but there is neither a mouse pointer in the guest nor can I click anything to select it, nor does the keyboard seem to do anything.

So the mouse integration is enabled in the WinXP guest and you updated the additions to 1.6.0, right? Please could you attach the VBox.log file?

Replying to frank:

So the mouse integration is enabled in the WinXP guest

Hrm. I believe so. I don't think I recall doing anything specific to enable them on either this troubled host or another where everything is working fine (1.5.6)

and you updated the additions to 1.6.0, right?

And herein lies the rub. When the mouse integration didn't work my first thought was to upgrade the guest additions to 1.6.0. But without a working mouse or even keyboard (i.e. accelerator) I can't install the new guest additions.

Please could you attach the VBox.log file?

I'd love to. But a reset (no other way to shut down winxp without a mouse or keyboard) has left me with a winxp that hangs on the splash screen, where it's always hung for a few 10s of seconds longer than it should, but now it does not seem to get past that. Might if I leave it long enough. ~sigh~

Last few entries in the log are:

00:51:37.371 Guest Log: BIOS: Booting from Hard Disk...
00:51:37.374 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=00000000 w=720 h=400 bpp=0 cbLine=0x0
00:51:38.578 Guest Log: BIOS: int13_harddisk: function 15, unmapped device for ELDL=81
00:51:54.887 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=b182b000 w=640 h=480 bpp=0 cbLine=0x140

Did you install this WinXP guest with VirtualBox or with another VMM? Or are you trying to boot a raw partition of your host?

Even if you had to reset your VM the logfile of the last session should be still available. Just go to the main VM selector window, select the Machine menu and click on Show Log ... There should be up to four VBox.log files available, if in doubt just attach every file to this defect. Please attach the complete file(s).

Replying to frank:

Did you install this WinXP guest with VirtualBox or with another VMM? Or are you trying to boot a raw partition of your host?

It's a raw partition installation that was done natively on the machine. Apart from the CPU pegging and the the flaky mouse integration, it has worked previously with 1.5.6.

Even if you had to reset your VM the logfile of the last session should be still available. Just go to the main VM selector window, select the Machine menu and click on Show Log ... There should be up to four VBox.log files available, if in doubt just attach every file to this defect. Please attach the complete file(s).

Ah, yes. Sweet. I will attach the .1 revision.

Oh, BTW: since you are now Sun it might interest you to know that this XP image is the new Sun corporate image that you get with new hardware and that ITops is encouraging everyone to upgrade (I use the term upgrade loosely since there is no real upgrade option -- it wipes your disk and installs fresh via an "image lay down") to.

Attachment per comment #7

At least I cannot see any obvious problem in the VBox.log.

Replying to frank:

At least I cannot see any obvious problem in the VBox.log.

Hrm. Yeah.

So now I have a winxp that won't boot past the splash screen, during fade in. I had booted safe mode and the last thing it showed was the agp440.sys driver loading so I:

$ sudo mv /mnt/windows/WINDOWS/system32/drivers/AGP440.SYS{,.old}

(of course only after stopping windows and mounting the disk -- and unmounting it when I was done) and it booted safe mode to a login prompt again, but I could not get past the required domain login. So I shutdown/rebooted again and again it's stuck at the winxp splash screen during the fade in. ~sigh~

Just to keep the ball rolling here, an upgrade to the 1.6.2 from the sun download center does not seem to have fixed anything. Now I am on Ubuntu 8.04 (Hardy) and having the same old problems.

First boot worked as much as it has in the past. Booted up to Windows XP with a pause at the WinXP spash fade in and then mouse integration was not working.

I tried to install the 1.6.2 guest additions and it wanted to uninstall the 1.5.6 ones first, which I let it do, and it wanted a reboot after that uninstall, which I let it do also, and now it's hanging on boot up again, right in the middle of the spash fade in.

CPU is always at 100% of a single core. Still.

Is there no desire at all to debug this?

I want to add, when it's stuck at the winxp splash fade in and chewing, the virtualbox process is in a tight loop of doing

[pid 20446] select(55, [47 50 51 52 53 54], [], [47], {0, 0}) = 0 (Timeout)
[pid 20453] <... rt_sigtimedwait resumed> {si_signo=SIGALRM, si_code=0x80, si_pid=0, si_uid=0, si_value={int=0, ptr=0}}, 0, 8) = 14
[pid 20446] gettimeofday( <unfinished ...>
[pid 20453] rt_sigtimedwait([ALRM],  <unfinished ...>
[pid 20446] <... gettimeofday resumed> {1214509715, 20051}, NULL) = 0
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1410
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1121
[pid 20449] <... poll resumed> [{fd=34, events=POLLIN}], 1, 199) = 0
[pid 20433] <... select resumed> )      = 0 (Timeout)
[pid 20453] <... rt_sigtimedwait resumed> {si_signo=SIGALRM, si_code=0x80, si_pid=0, si_uid=0, si_value={int=0, ptr=0}}, 0, 8) = 14
[pid 20453] rt_sigtimedwait([ALRM], {si_signo=SIGALRM, si_code=0x80, si_pid=0, si_uid=0, si_value={int=0, ptr=0}}, 0, 8) = 14
[pid 20453] rt_sigtimedwait([ALRM],  <unfinished ...>
[pid 20446] select(55, [47 50 51 52 53 54], [], [47], {0, 0}) = 0 (Timeout)
[pid 20446] gettimeofday({1214509715, 98427}, NULL) = 0
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1410
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1121
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1121
[pid 20446] ioctl(3, VIDIOC_TRY_FMT <unfinished ...>
[pid 20453] <... rt_sigtimedwait resumed> {si_signo=SIGALRM, si_code=0x80, si_pid=0, si_uid=0, si_value={int=0, ptr=0}}, 0, 8) = 14
[pid 20446] <... ioctl resumed> , 0)    = 1121
[pid 20453] rt_sigtimedwait([ALRM],  <unfinished ...>
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] select(55, [47 50 51 52 53 54], [], [47], {0, 0}) = 0 (Timeout)
[pid 20446] gettimeofday({1214509715, 101265}, NULL) = 0
[pid 20446] ioctl(3, VIDIOC_TRY_FMT <unfinished ...>
[pid 20449] gettimeofday( <unfinished ...>
[pid 20433] gettimeofday( <unfinished ...>
[pid 20446] <... ioctl resumed> , 0)    = 1121
[pid 20449] <... gettimeofday resumed> {1214509715, 103155}, NULL) = 0
[pid 20433] <... gettimeofday resumed> {1214509715, 103160}, NULL) = 0
[pid 20446] ioctl(3, VIDIOC_TRY_FMT <unfinished ...>
[pid 20449] gettimeofday( <unfinished ...>
[pid 20433] read(22,  <unfinished ...>
[pid 20446] <... ioctl resumed> , 0)    = 1121
[pid 20449] <... gettimeofday resumed> {1214509715, 103309}, NULL) = 0
[pid 20433] <... read resumed> 0x82be804, 4096) = -1 EAGAIN (Resource temporarily unavailable)
[pid 20446] ioctl(3, VIDIOC_TRY_FMT <unfinished ...>
[pid 20449] read(34,  <unfinished ...>
[pid 20433] gettimeofday( <unfinished ...>
[pid 20449] <... read resumed> 0x8447fec, 4096) = -1 EAGAIN (Resource temporarily unavailable)
[pid 20446] <... ioctl resumed> , 0)    = 1121
[pid 20433] <... gettimeofday resumed> {1214509715, 103518}, NULL) = 0
[pid 20449] read(34,  <unfinished ...>
[pid 20446] ioctl(3, VIDIOC_TRY_FMT <unfinished ...>
[pid 20433] select(30, [22 27 29], [], [], {0, 49642} <unfinished ...>
[pid 20449] <... read resumed> 0x8447fec, 4096) = -1 EAGAIN (Resource temporarily unavailable)
[pid 20446] <... ioctl resumed> , 0)    = 1121
[pid 20449] gettimeofday( <unfinished ...>
[pid 20446] ioctl(3, VIDIOC_TRY_FMT <unfinished ...>
[pid 20449] <... gettimeofday resumed> {1214509715, 103820}, NULL) = 0
[pid 20446] <... ioctl resumed> , 0)    = 1121
[pid 20449] poll( <unfinished ...>
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1410
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] select(55, [47 50 51 52 53 54], [], [47], {0, 0}) = 0 (Timeout)
[pid 20446] gettimeofday({1214509715, 106135}, NULL) = 0
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1121
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] select(55, [47 50 51 52 53 54], [], [47], {0, 0}) = 0 (Timeout)
[pid 20446] gettimeofday({1214509715, 108370}, NULL) = 0
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1410
[pid 20446] ioctl(3, VIDIOC_TRY_FMT <unfinished ...>
[pid 20453] <... rt_sigtimedwait resumed> {si_signo=SIGALRM, si_code=0x80, si_pid=0, si_uid=0, si_value={int=0, ptr=0}}, 0, 8) = 14
[pid 20446] <... ioctl resumed> , 0)    = 1121
[pid 20453] rt_sigtimedwait([ALRM],  <unfinished ...>
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1121
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1121
[pid 20446] ioctl(3, VIDIOC_TRY_FMT, 0) = 1135
[pid 20446] select(55, [47 50 51 52 53 54], [], [47], {0, 0}) = 0 (Timeout)
[pid 20446] gettimeofday({1214509715, 111949}, NULL) = 0

As you could probably guess, FD 3 is:

COMMAND     PID  USER   FD   TYPE     DEVICE     SIZE    NODE NAME
...
VirtualBo 20433 brian    3u   CHR      10,62          3305635 /dev/vboxdrv

I'm not yet positive of the requirement, but it's seeming like I have to unload and reload the vboxdrv module between boots of this WinXP guest.

This ioctl just means that VBox switches very often to the guest. It seems that some of your WinXP guest application, probably one service of the guest additions, is using your whole CPU. Any chance to remove the guest additions with booting in safe mode? Try to remove all VBox stuff from the guest hard disk and from the registry. Does it make a difference if the guest additions are completely removed?

I think it's worth adding at this point, that something I have seen in the log a number of times while booting this winxp is this:

00:00:06.563 Guest Log: BIOS: Boot from Floppy 0 failed
00:00:06.566 Guest Log: BIOS: CDROM boot failure code : 0003
00:00:06.567 Guest Log: BIOS: Boot from CD-ROM failed
00:00:06.568 Guest Log: BIOS: Booting from Hard Disk...
00:00:07.743 Guest Log: BIOS: int13_harddisk: function 15, unmapped device for ELDL=81
00:00:43.399 PIIX3 ATA: LUN#0: IDLE IMMEDIATE, CmdIf=0xef (-1 usec ago)
00:00:43.399 PIIX3 ATA: LUN#0: aborting current command
00:00:55.196 EHCI: Hardware reset
00:00:55.196 EHCI: USB Operational
00:00:56.615 OHCI: Software reset
00:00:56.616 OHCI: USB Reset
00:00:56.616 OHCI: USB Operational
00:00:57.933 Guest Additions information report: additionsVersion = 0x00010004  osType = 0x00033000
00:00:58.240 Guest reported fixed hypervisor window at 0xf6000000 (size = 0xc00000, rc = VINF_SUCCESS)
00:00:58.593 EHCI: USB Suspended
00:00:59.455 OHCI: USB Suspended
00:01:15.807 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=b1620000 w=800 h=600 bpp=32 cbLine=0xC80
00:01:17.319 Guest requests mouse pointer integration

Notice the huge honkin' pause before the

00:00:43.399 PIIX3 ATA: LUN#0: IDLE IMMEDIATE, CmdIf=0xef (-1 usec ago)
00:00:43.399 PIIX3 ATA: LUN#0: aborting current command

This doesn't look too normal, nor good.

Replying to frank:

This ioctl just means that VBox switches very often to the guest. It seems that some of your WinXP guest application, probably one service of the guest additions, is using your whole CPU.

I think it's worth noting that this 100% CPU usage starts as soon as the guest starts. Even with WinXP sitting at the "hardware profile" choice menu, the guest is chewing up 100% CPU.

Any chance to remove the guest additions with booting in safe mode? Try to remove all VBox stuff from the guest hard disk and from the registry. Does it make a difference if the guest additions are completely removed?

Nope.

I wonder what the chances are of trying to use oprofile on VirtualBox on Hardy are or whether it will crash the host O/S as it did no Gutsy.

OK. Cool. oprofile seems to be working on Hardy. From just a few minutes of my WinXP guest sitting at the hardware profile selection menu here is what overall system performance looks like:

$ opreport 
CPU: Core 2, speed 800 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 100000
CPU_CLK_UNHALT...|
  samples|      %|
------------------
      652 54.7439 vmlinux-debug-2.6.24-18-generic
      200 16.7926 processor
       92  7.7246 libc-2.7.so
       38  3.1906 nvidia
       27  2.2670 VBoxVMM.so
       21  1.7632 libcrypto.so.0.9.8
       17  1.4274 libglib-2.0.so.0.1600.3
       15  1.2594 ld-2.7.so
       14  1.1755 VBoxREM.so
       10  0.8396 libpthread-2.7.so
        9  0.7557 libvte.so.9.2.17
        8  0.6717 libncurses.so.5.6
        8  0.6717 libxul.so
        8  0.6717 sshd
        7  0.5877 libqt-mt.so.3.3.8
        6  0.5038 VBoxRT.so
        6  0.5038 libX11.so.6.2.0
        6  0.5038 VirtualBox
	CPU_CLK_UNHALT...|
	  samples|      %|
	------------------
	        5 83.3333 anon (tgid:5720 range:0xb4866000-0xb5867000)
	        1 16.6667 VirtualBox
        5  0.4198 top
	CPU_CLK_UNHALT...|
	  samples|      %|
	------------------
	        4 80.0000 [vdso] (tgid:29637 range:0xb7f2c000-0xb7f2d000)
	        1 20.0000 top
        4  0.3359 e1000
        4  0.3359 libxcb.so.1.0.0
        3  0.2519 libproc-3.2.7.so
        3  0.2519 watch
        3  0.2519 libdbus-1.so.3.4.0
        3  0.2519 libgobject-2.0.so.0.1600.3
        2  0.1679 nf_conntrack
        2  0.1679 oprofile
        2  0.1679 snd_hda_intel
        2  0.1679 uhci_hcd
        2  0.1679 libXft.so.2.1.2
        2  0.1679 libnspr4.so.0d
        1  0.0840 af_packet
        1  0.0840 ip_tables
        1  0.0840 iptable_nat
        1  0.0840 nf_conntrack_ipv4
        1  0.0840 usbcore
        1  0.0840 libcairo.so.2.17.3
        1  0.0840 libgdk-x11-2.0.so.0.1200.9
        1  0.0840 libgthread-2.0.so.0.1600.3
        1  0.0840 VBoxSVC
        1  0.0840 NetworkManager
	CPU_CLK_UNHALT...|
	  samples|      %|
	------------------
	        1 100.000 [vdso] (tgid:5814 range:0xb7f33000-0xb7f34000)

And here is the VirtualBox binary itself:

$ opreport -l /usr/lib/virtualbox/VirtualBox 
CPU: Core 2, speed 800 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (Unhalted core cycles) count 100000
samples  %        image name               symbol name
5        83.3333  anon (tgid:5720 range:0xb4866000-0xb5867000) (no symbols)
1        16.6667  VirtualBox               (no symbols)

Not sure how helpful that is, but I'd be willing to follow some instruction if there is any more information I can help gather.

I want to add to this ticket, that it appears that the problem has nothing to do with the guest OS as a Ubuntu Linux guest on this same machine exhibits this same problem -- pegged CPU.

You know, I did quite a bit of work/research into this problem almost a year ago and nobody seems to have taken any notice.

This is still a problem now on 2.1.4 and has always been a problem through every version I have upgraded.

I want to re-iterate, even a Linux guess sitting at a GRUB prompt, doing nothing, waiting for input will consume over 100% of a single core on a dual core machine.

Surely this is not normal and expected.

As an additional data point. Two VMs, one running the above, do-nothing-sitting-at-a-GRUB-prompt task and the other running WindowsXP will each consume the equivalent of a single core in a dual core system. So yes, that's two VMs consuming all of the CPU cycles in a dual core system. One of the VMs isn't even doing anything.

Surely debugging a VM using up 100% of a single core doing nothing (like just sitting at a GRUB prompt) must not be terribly difficult. It's entirely easy to see that the guest O/S is not what is causing the problem, yes?

It doesn't help to jump to conclusions here. Afaik GRUB doesn't play nice and just burns CPU cycles. Same with DOS guests without some special TSR that executes hlt when doing nothing.

I'd hardly say this is a major problem if all you tested was grub.

Replying to sandervl73:

It doesn't help to jump to conclusions here.

Look, I'm just adding additional data points in the absence of anyone commenting on any of my last 3 or 4 posts (before today). Nobody even said "none of that helps us, here's what would help us..."

I'd hardly say this is a major problem if all you tested was grub.

Did you read the whole ticket? I have done a heck of a lot more testing than just with GRUB. Windows XP is the main subject of my complaint, but the problem is you always get somebody saying "oh, well there must be some process in WinXP that eating up CPU, like a virus scanner or something" so I am trying to find a way to prove (or disprove) that the guest o/s is not the CPU eating culprit. So far, I have found no way at all to not have my VM eating 100% of a core, constantly.

If sitting at a GRUB prompt is not a satisfactory test, then why don't you suggest a test I can do to prove (or disprove) that an otherwise idle guest still results in 100% usage of a core. What would a guest have to be doing to satisfy you that it's really idle and exerting no pressure on the VM at all?

The problem is the IO-APIC. That kills performance with 32 bits guests. Did you migrate a VMWare image? Anyway, check http://www.virtualbox.org/wiki/Migrate_Windows for information on how to switch the HAL to a non-IO-APIC version.

As for the age of the bug. It's unfortunate that I didn't see it before, but we get a lot of bug reports coming in and I have a lot of work to do as well.

Replying to sandervl73:

The problem is the IO-APIC. That kills performance with 32 bits guests.

Ahhhh! Now we are getting somewhere!

Did you migrate a VMWare image?

No, but I am using an image installed on a physical partition that was installed on the raw hardware, so I am most likely falling victim to this IO-APIC problem.

Anyway, check http://www.virtualbox.org/wiki/Migrate_Windows for information on how to switch the HAL to a non-IO-APIC version.

The problem is, I don't have "official media". This is a Sun ITOPS issued laptop and they send out their own install CDs. Is there any other way other than doing a "Repair Installation" from a Windows CD to change the HAL to using the non-IO-APIC version?

And what does changing that mean for running the same Windows on the real hardware (not that I can recall the last time I did that, but good to know anyway)?

There are some hints in the linked MS page. As for side effects when booting the physical system, that's hard to say. It shouldn't, but a different irq allocation strategy might trigger problems. You can probably create different hardware profiles to deal with this, but don't ask me how. :)

And the winner is sandervl73!

Changing my WinXP to use the non-IO-APIC HAL has fixed my problem. VB CPU usage hovers in the 30% range now (when the guest o/s is idle), occasionally dipping down to the 20s even.

I found this extremely helpful in changing the HAL. I wonder if the steps it takes can be integrated into the Guest Additions process. Likely there would want to be the creation of a new hardware profile, so I don't know how feasible that is really.

At least, the Windows Migration wiki page could point to that video, or re-document the steps.

Please feel free to close this bug with the reason "Happy Camper" if you wish. :-)

I'll mark this as a duplicate of #638. What you propose is a bit too much work. Instead a simple warning from the GUI might be useful.