Infinite Loop in Guest Addition for Windows XP (1 Core always 100% on VBoxTray.exe)

[Francesco Bucciantini]

Hi guys, on July 8th 2024 I raised an issue with the development snapshot uploaded on 2024-07-04T18:53:02, namely version 7.0.97 r163779 on Fedora 40, kernel 6.9.6 as it was cycling through something. In my 4c/8th configuration the process VirtualBoxVM constantly used at least 15% CPU time which means that it's always using 1 core at 100% despite the guest being completely idling. This seems to be occurring regardless of the guest, although I made the tests in particular on Windows XP. Anyway everything pointed towards an issue within the hypervisor. This didn't happen with the last but one development snapshot version and it also doesn't happen with the last but one stable build, namely 7.0.18 r162988. I was hoping this was gonna be debugged and caught early before the stable release, but unfortunately I can now confirm that the issue has been carried over from the development snapshot 7.0.97 r163779 to the last stable release 7.0.20 r163906.

Logs: ​https://forums.virtualbox.org/download/file.php?id=52945

Forum reference for 7.0.97 r163779 Development Snapshot ​https://forums.virtualbox.org/viewtopic.php?p=548925#p548925

Forum reference for 7.0.20 r163906 Stable: ​https://forums.virtualbox.org/viewtopic.php?t=111893

[Francesco Bucciantini]

Screenshot highlighting the problem with the guest addition (25% CPU in 4c/4th means 1 core is always at 100%)

[Francesco Bucciantini]

Logs of the VM experiencing the issue

[Francesco Bucciantini]

I can also confirm that reverting to the guest additions version 7.0.19 r163782 works and the infinite loop is gone.

So now it's just a matter of comparing the changes between 7.0.19 r163782 and 7.0.20 r163906 and spot which commit caused the issue.

[Francesco Bucciantini]

Virtualbox 7.1.0 r164395

[Francesco Bucciantini]

The issue is also occurring on 7.1.0 r164369 and 7.1.0 r164395 from August 15th, 2024. Given that 7.1.0 is Beta, it has also been reported in the dedicated Beta section of the forum: ​https://forums.virtualbox.org/viewtopic.php?t=111997

Once again, downgrading the guest additions to 7.0.19 r163782 (or, for those who prefer stable, 7.0.18 ​https://download.virtualbox.org/virtualbox/7.0.18/VBoxGuestAdditions_7.0.18.iso) solves the issue. In other words, I can confirm that the last guest additions to not show the issue are 7.0.19 r163782 and using those solves the issue on both 7.0.20 and 7.1.0.

[pentagonik]

Thanks for the report; I'll have a look into this.

[pentagonik]

It could be that this particular snapshot version(s) had the same bug we were seeing in some other reports, which caused a high host CPU load.

Did the host CPU load drop as soon as you terminated VBoxTray on the guest?

[Francesco Bucciantini]

Yes, the host CPU load dropped as soon as I killed the VBoxTray.exe process. That is, if you're using Bridged Network and not NAT, if you're using NAT, then you still had the high CPU load in the host despite the guest using basically nothing. This was until yesterday's release Virtualbox 7.1.0 r164443 which addressed the NAT issue.

In other words:

Test 1:

Virtualbox: 7.1.0 r164369 / r164395 Guest Additions: 7.1.0 r164395 Network: NAT

Guest CPU: 25% for a 4c configuration (infinite loop in VBoxTray.exe in one core) Host CPU: 66% for a 4c/8th configuration (high CPU usage beyond 1 core in infinite loop)

Test 2:

Virtualbox: 7.1.0 r164369 / r164395 Guest Additions: 7.1.0 r164395 Network: Bridged Network

Guest CPU: 25% for a 4c configuration (infinite loop in VBoxTray.exe in one core) Host CPU: 15% for a 4c/8th configuration (1 core stuck in infinite loop changing every few seconds, typical in Linux + a little vm overhead, which is normal)

Test 3:

Virtualbox: 7.1.0 r164369 / r164395 Guest Additions: 7.0.19 r163782 Network: NAT

Guest CPU: 5% for a 4c configuration (normal usage) Host CPU: 55% for a 4c/8th configuration (high CPU usage)

Test 4:

Virtualbox: 7.1.0 r164369 / r164395 Guest Additions: 7.0.19 r163782 Network: Bridged Network

Guest CPU: 5% for a 4c configuration (normal usage) Host CPU: 9% for a 4c/8th configuration (normal usage)

In other words, using the old guest additions makes the infinite loop in the guest go away, however it does nothing to prevent the infinite loop in the host if you're using NAT. That isn't the case if you're using bridged network, though. That is until yesterday's release, Virtualbox 7.1.0 r164443, as I was saying. With yesterday's release, I can confirm that the NAT infinite loop on the host is solved:

Virtualbox: 7.1.0 r164443 Guest Additions: 7.0.19 r163782 Network: NAT

Guest CPU: 5% for a 4c configuration (normal usage) Host CPU: 9% for a 4c/8th configuration (normal usage)

Virtualbox: 7.1.0 r164443 Guest Additions: 7.0.19 r163782 Network: Bridged Network

Guest CPU: 5% for a 4c configuration (normal usage) Host CPU: 9% for a 4c/8th configuration (normal usage)

So... one problem down, one to go. :D Thank you for fixing the first problem by the way (the NAT one). Now all is left is to also fix the issue in the guest addition for the guest. :)

[pentagonik]

Does this still apply to Beta 2?

[Francesco Bucciantini]

Yes, it also applies to Virtualbox 7.1.0 r164448 (aka BETA 2). New logs depicting the same issue occurring with Beta 2 in attachment (WindowsEmbedded-2024-08-25-18-51-31.zip).

[Francesco Bucciantini]

Issue still occurring with Virtualbox 7.1.0 r164448 (aka BETA 2)

[Francesco Bucciantini]

Logs of the issue occurring on Virtualbox 7.1.0 r164448 (aka BETA 2)

[Francesco Bucciantini]

I've just installed the new Guest Addition version 7.1.0 r164481 and the problem persists. I tried to set the environment variables as it says here: https://www.virtualbox.org/wiki/AdditionsLogging however it didn't work as it didn't create any file in the specified folder. In attachment the normal logs for 7.1.0 r164481 (WindowsEmbedded-2024-08-28-10-17-42.zip).

[Francesco Bucciantini]

Virtualbox 7.1.0 r164481

[Francesco Bucciantini]

Virtualbox 7.1.0 r164481

[Francesco Bucciantini]

New logs, also from within the guest. Essentially, I went into

and I created the DWORD entry LoggingEnabled with Decimal 255 (Hex ff)

Then I added the two Environment Variables:

and I created the "Temp" folder in C: to allow logs to be written there:

At this point, I rebooted and logged in with my normal Active Directory user and sure enough the logs were there. :)

Unfortunately, however, when I opened them, I was a bit surprised by the lack of details. It looks like there isn't much being logged... :(

00:00:00.011718 main     VBoxTray 7.1.0_BETA2 r164482 win.x86 (Aug 21 2024 16:45:56) release log
00:00:00.011718 main     Log opened 2024-08-30T06:41:27.714716700Z
00:00:00.011718 main     OS Product: Windows XP Professional
00:00:00.012695 main     OS Release: 5.1.2600
00:00:00.012695 main     Executable: C:\WINDOWS\system32\VBoxTray.exe
00:00:00.012695 main     Process ID: 3836
00:00:00.012695 main     Package type: WINDOWS_32BITS_GENERIC
00:00:00.012695 main     Verbosity level: 0

When I shut down the guest, I've got the message that VBoxTray couldn't be stopped correctly (probably 'cause it was still using resources being stuck in an infinite loop with the same 25% CPU usage in a 4c/4th configuration):

Then I killed it and I shut down the host:

Anyway, in attachment you can find the logs, both from the Host and the Guest.

[Francesco Bucciantini]

VBoxTray logs 7.1.0 r164481

[Francesco Bucciantini]

Virtualbox logs 7.1.0 r164481

[Francesco Bucciantini]

The Guest Additions were updated today at 13:14:26 BST in the development snapshot page, so I installed the new version, namely r164641 and I rebooted the guest. Unfortunately, things got... uhm... worse, but you know what they say "things have to get worse before they get better". Jokes aside, I have no idea what the new VBoxTray.exe is doing, but whatever it is, it's no longer single threaded with 1 core out of 4 being at 100% resulting in 25% CPU usage, but rather multithreaded with the load being spread across 2 cores and the CPU usage being 50% now in a 4c configuration. After waiting for a while (around 20 minutes), however, the CPU usage dropped down to 25% once again, thus going back to the old behavior. Things look interesting for the guest logs this time round as there are more things going on.

00:00:00.007812 main     VBoxTray 7.1.0_BETA2 r164641 win.x86 (Sep  2 2024 13:06:42) release log
00:00:00.007812 main     Log opened 2024-09-02T16:15:36.763906500Z
00:00:00.008789 main     OS Product: Windows XP Professional
00:00:00.009765 main     OS Release: 5.1.2600
00:00:00.009765 main     Executable: C:\WINDOWS\system32\VBoxTray.exe
00:00:00.009765 main     Process ID: 3572
00:00:00.009765 main     Package type: WINDOWS_32BITS_GENERIC
00:00:00.009765 main     Verbosity level: 0
00:00:00.014648 main     Windows version 5.1 build 2600 (uNtVersion=0x50010000000a28)
00:00:23.383789 main     Starting services ...
00:00:23.383789 main     Starting service 'display' ...
00:03:01.079101 main     Service 'display' started
00:03:01.080078 main     Starting service 'clipboard' ...
00:03:01.081054 main     Shared Clipboard: New Clipboard API not available (VERR_SYMBOL_NOT_FOUND)
00:03:01.088867 main     Shared Clipboard: Guest features: 0x7 - Host features: 0x3
00:03:01.089843 main     Shared Clipboard: Using chunk size 65536 (maximum is 134213632)
00:05:54.214843 shclwnd  Shared Clipboard: Initialized OLE in window thread
00:05:54.232421 shclwnd  Shared Clipboard: Window thread running
00:08:18.444335 clipboard Shared Clipboard: Worker loop running
00:08:18.445312 main     Service 'clipboard' started
00:08:18.446289 clipboard Shared Clipboard: Initialized OLE in worker thread
00:08:18.447265 main     Starting service 'seamless' ...
00:10:45.871093 main     Service 'seamless' started
00:10:45.871093 main     Starting service 'VRDP' ...
00:13:08.093750 main     Service 'VRDP' started
00:13:08.094726 main     Starting service 'IPC' ...
00:13:08.096679 main     VBoxIPCInit: Local IPC server now running at "\\.\pipe\VBoxTrayIPC-Bucciantinif"
00:15:32.291015 main     Service 'IPC' started
00:15:32.291015 main     Starting service 'LA' ...
00:15:32.291992 main     LA: RegQueryValueExW: failed [SOFTWARE\Oracle\VirtualBox Guest Additions/VBoxTrayLog]
00:15:32.291992 main     LA: RegQueryValueExW: failed [SOFTWARE\Oracle\VirtualBox Guest Additions/VBoxTrayLA]
00:15:32.292968 main     LA: DetachOnDisconnect=true
00:18:04.646484 main     Service 'LA' started
00:18:04.647460 main     Starting service 'draganddrop' ...
00:21:04.146484 dndwnd   DnD: Guest features: 0x0 - Host features: 0x0
00:21:34.138671 main     DnD: Failed to initialize proxy window, rc=VERR_NOT_SUPPORTED
00:22:34.139648 main     DnD: Initializing drag and drop service failed with rc=VERR_NOT_SUPPORTED
00:22:34.139648 main     Service 'draganddrop' is not supported on this system
00:22:34.139648 main     All services started
00:23:25.402343 dndwnd   DnD: Creating drop target failed with hr=0x80070057

The total run of the guest was 45 minutes after which I shut it down. In attachment you can find the screenshots along with the logs from both the host and the guest running version 7.1.0 r164448 with Guest Addition r164641.

[Francesco Bucciantini]

CPU Usage 7.1.0 r164448 with Guest Addition r164641

[Francesco Bucciantini]

Host logs Virtualbox 7.1.0 r164448 with Guest Addition r164641

[Francesco Bucciantini]

Guest logs Virtualbox 7.1.0 r164448 with Guest Addition r164641