[FIXED] Beta issue? 100% CPU use for an idle guest OS

[pentagonik]

Well thank you for the updated instructions.
I went into
https://i.imgur.com/h29cOtm.png
and I created the DWORD entry LoggingEnabled with Decimal 255 (Hex ff)
https://i.imgur.com/jQm7dm8.png
Then I added the two Environment Variables:
https://i.imgur.com/EG2lk2c.png
and I created the "Temp" folder in C: to allow logs to be written there:
https://i.imgur.com/1HWMLaQ.png
At this point, I rebooted and logged in with my normal Active Directory user and sure enough the logs were there.
https://i.imgur.com/s2uUBqR.png
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...

To make sure progress here, could you please also try setting the environment variables

Code: Select all

VBOX_RELEASE_LOG=all.e.l.l2.l3.f
VBOX_RELEASE_LOG_DEST=file=c:\temp\VBoxTray.log

That should also increase the logging verbosity.

[dgrigorev]

Well thank you for the updated instructions.
I went into
https://i.imgur.com/h29cOtm.png
and I created the DWORD entry LoggingEnabled with Decimal 255 (Hex ff)
https://i.imgur.com/jQm7dm8.png
Then I added the two Environment Variables:
https://i.imgur.com/EG2lk2c.png
and I created the "Temp" folder in C: to allow logs to be written there:
https://i.imgur.com/1HWMLaQ.png
At this point, I rebooted and logged in with my normal Active Directory user and sure enough the logs were there.
https://i.imgur.com/s2uUBqR.png
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...

Code: Select all

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

https://i.imgur.com/RETtXI0.png
When I shut down the guest, then 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):
https://i.imgur.com/mJMxc2c.png
Then I killed it and I shut down the host:
https://i.imgur.com/FdWbHad.png


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

VBoxTray.zip
WindowsEmbedded-2024-08-30-07-50-45.zip

Hello FranceBB.
Your info helped us to fix a bug in VBoxTray.exe logging, thank you.
Could you install the Guest Additions version >= 164641 and repeat the steps to collect VBoxTray.log again?
https://www.virtualbox.org/download/tes ... 164641.iso
With best regards, Dmitrii

[FranceBB]

To make sure progress here, could you please also try setting the environment variables

Code: Select all

VBOX_RELEASE_LOG=all.e.l.l2.l3.f
VBOX_RELEASE_LOG_DEST=file=c:\temp\VBoxTray.log

That should also increase the logging verbosity.

Yep, they were already set, so I guess we were already trying to get as many logs as possible.

Your info helped us to fix a bug in VBoxTray.exe logging, thank you.
Could you install the Guest Additions version >= 164641 and repeat the steps to collect VBoxTray.log again?

No worries, I'm just trying to play my part as a user and give back to the community.
Testing new releases and reporting bugs is really the least I can do to support (in a tiny amount) this project.
The real thank you goes to everyone who commits the code and to Oracle for making this awesome program open source, cross platform and freely available to everyone.

Anyway, I saw that 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.

Screenshot from 2024-09-02 17-34-43.png (16.73 KiB) Viewed 3183 times

Screenshot from 2024-09-02 17-35-41.png (14.08 KiB) Viewed 3183 times

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.

Screenshot from 2024-09-02 17-42-23.png (16.28 KiB) Viewed 3183 times

Things look interesting for the guest logs this time round as there are more things going on.

Code: Select all

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.

[FranceBB]

In attachment you can find the logs from both the host and the guest running version 7.1.0 r164448 with Guest Addition r164641.
(apologies for the double post but I ran out of attachments).

Host logs:

WindowsEmbedded-2024-09-02-17-46-34.zip

(45.53 KiB) Downloaded 62 times

Guest logs:

VBoxTray.zip

(1.21 KiB) Downloaded 74 times

[pentagonik]

Thanks for all the feedback so far, this is valuable for us! So still not sure what's going here, at least I can't reproduce this here locally.
What is strange that drag'n drop isn't announced as being available, as this really should be.

Could you please try killing VBoxTray (via task manager) and start it manually on the command line with

Code: Select all

VBoxTray -vvvv --logfile c:\temp\VBoxTray.log

That should make it more verbose in the log file.

[FranceBB]

Well, I tried running it from the command line and I tried collecting the logs which led to this:

Code: Select all

00:00:00.010742 main     VBoxTray 7.1.0_BETA2 r164641 win.x86 (Sep  2 2024 13:06:42) release log
00:00:00.010742 main     Log opened 2024-09-03T09:59:21.209683700Z
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: 3260
00:00:00.012695 main     Package type: WINDOWS_32BITS_GENERIC
00:00:00.013671 main     Verbose log settings are: all.e.l.l2.l3.l4.f
00:00:00.027343 main     Verbosity level: 4
00:00:00.027343 main     Windows version 5.1 build 2600 (uNtVersion=0x50010000000a28)
00:00:00.272460 main     Starting services ...
00:00:00.273437 main     Starting service 'display' ...
00:04:58.050781 main     Service 'display' started
00:04:58.058593 main     Starting service 'clipboard' ...
00:04:58.063476 main     Shared Clipboard: New Clipboard API not available (VERR_SYMBOL_NOT_FOUND)
00:04:58.072265 main     Shared Clipboard: Guest features: 0x7 - Host features: 0x3
00:04:58.073242 main     Shared Clipboard: Using chunk size 65536 (maximum is 134213632)
00:10:43.245117 shclwnd  Shared Clipboard: Initialized OLE in window thread
00:10:43.267578 shclwnd  Shared Clipboard: Window thread running
00:15:48.870117 clipboard Shared Clipboard: Worker loop running
00:15:48.876953 main     Service 'clipboard' started
00:15:48.876953 clipboard Shared Clipboard: Initialized OLE in worker thread
00:15:48.877929 main     Starting service 'seamless' ...

After a while, it settled on 0% usage and I thought "great"

Screenshot from 2024-09-03 12-39-03.jpg (163.34 KiB) Viewed 2878 times

but my happiness was short lived as the guest became unresponsive quickly after

Screenshot from 2024-09-03 12-56-28.jpg (179.76 KiB) Viewed 2878 times

I was performing an I/O intensive task, namely a copy, so I can't know for sure whether it was the guest addition or that copy that caused it, but given that it reached 63% after several hours without crashing makes me thing about the guest addition as it crashed after I started them. About being able to reproduce the issue, I'd say that it could be because of two things: either the Microsoft Extended Support updates installed until July 2019 or Avast as antivirus. Unfortunately, testing without the first is pretty much impossible as I can't just uninstall the security updates, however later on this evening I can try disabling the antivirus and see if it makes any difference. I'm a bit skeptical, but there aren't many things I can think of that make this system different to any other XP system.

[FranceBB]

Well, I've disabled VBoxTray.exe at startup from within Windows and the computer has been solid ever since, but of course no shared clipboard (which I actually use) and no drag and drop (although I don't use it).
I've updated to Virtualbox 7.1.0 r164699 with guest addition version r164700 uploaded on September 6th and unfortunately the issue still occurs.

VBoxTray.zip

(1.08 KiB) Downloaded 10 times

WindowsEmbedded-2024-09-07-18-19-24.zip

(46.45 KiB) Downloaded 13 times

Looks like I'm still getting the line "New Clipboard API not available (VERR_SYMBOL_NOT_FOUND)" in the logs.