Windows 10 guest turns off but just at the end it freezes 6 minutes

[albertolozano]

I am runing a windows 10 pro guest on a windows 10 pro host with virtualbox Versión 7.0.10 r158379.
The guest starts and works fine, but when turning it off (from the guest) it allways get to this point:
.....
00:02:11.323801 ************** End of Guest state at power off ***************
00:02:11.323969 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=1920 h=977 bpp=0 cbLine=0x0 flags=0x2 origin=0,0
00:02:21.850827 VMMDevNotifyGuest: fAddEvents=0x200 ignored because enmVMState=21
00:08:09.356861 PDMR3PowerOff: Driver 'VD'/0 on LUN#0 of device 'ahci'/0 took 358 031 596 743 ns to power off
00:08:09.358615 PDMR3PowerOff: 358 034 715 141 ns run time
00:08:09.358634 Changing the VM state from 'POWERING_OFF' to 'OFF'
00:08:09.358964 Console: Machine state changed to 'Stopping'
00:08:09.359632 Console::powerDown(): A request to power off the VM has been issued (mMachineState=Stopping, InUninit=0)
00:08:09.372834 Changing the VM state from 'OFF' to 'DESTROYING'
.....

There is a 6 minutes freeze, where it looks like the guesta has ended but its windows, wich is pitch black, will not close and vituralbox manager is not responsive.

What can it be? I've tried a lot of crazy things but this efect will not go away.

[mpack]

Provide a VM log file. Make sure the VM is fully shut down, then right click it in the manager UI. Select "Show Log" and save "VBox.log" (no other file) to a zip file. Attach the zip here.

[albertolozano]

Simple and short log with the issue.

I've started the guest, toke about 47 seconds, that's not bad, then power off and that is when it goes 6 minutes without any event logged.

Thank you in advance.

[albertolozano]

I'm guessing, say this line "...VMMDevNotifyGuest: fAddEvents=0x200 ignored because enmVMState=21..." is logged just when the Guest has finish powerdowned and was ignored, then virtualbox goes for 6 minutes of stagnation until a sort of timeout goes out, recovers and stars to terminate the guest. Some feedback please?

[mpack]

I think it's more likely to be this one:

00:09:10.456778 PDMR3PowerOff: Driver 'VD'/0 on LUN#0 of device 'ahci'/0 took 362 230 511 640 ns to power off

That big number in ns is 6.04 minutes.

The device "VD0 on LUN#0" is your virtual hard drive. I note that your VD0 is located on an external hard drive on drive D. I'd look at the health and performance of your drive D.

[albertolozano]

Thank you for the feedback,

I've cloned the virtual w10 machine into C:\ (it´s an SSD drive unlike D:\) and time has went down to 4:20 minutes, it's 30% smaller but still very big:

00:02:29.805788 VMMDevNotifyGuest: fAddEvents=0x200 ignored because enmVMState=21
00:06:41.060371 PDMR3PowerOff: Driver 'VD'/0 on LUN#0 of device 'ahci'/0 took 257 721 456 597 ns to power off

[fth0]

VMMDevNotifyGuest: fAddEvents=0x200 ignored because enmVMState=21

The event VMMDEV_EVENT_MOUSE_POSITION_CHANGED (0x200) is sent to the VM in state VMSTATE_POWERING_OFF (21), so this is probably not relevant here. Additionally, that event didn't happen in one of your three logs.

---

I've cloned the virtual w10 machine into C:\ (it´s an SSD drive unlike D:\) and time has went down to 4:20 minutes, it's 30% smaller but still very big

Kudos for having the idea! I can suggest two additional ideas, an easy one and a not so easy one:

1. In the VM configuration, disable the Host I/O Cache on the AHCI/SATA Controller and see if the issue persists. I also have it enabled since my old HDD days, where it was sort-of necessary to get decent performance. But with an SSD, the performance might be good enough without it, and it might be interesting if the issue somehow depends on it.

2. A thorough investigation what happens in the interesting minutes could be done, beginning with your favorite task manager on the host OS. Enhanced investigation could be done with Sysinternals Process Monitor and Disk Monitor.

PS: Disabling any AV software on the host for a test would be yet another idea.

[albertolozano]

Thanks for the answer,

1. In the VM configuration, disable the Host I/O Cache on the AHCI/SATA Controller and see if the issue persists. I also have it enabled since my old HDD days, where it was sort-of necessary to get decent performance. But with an SSD, the performance might be good enough without it, and it might be interesting if the issue somehow depends on it.

My Test:
1) Start windows 10 VM from manager
2) login windows 10 guest
3) wait until mouse is responsive
4) power off from windows menu
5) VM is completely off

I will run the test with the c:\ (ssd) windows guest clone, first with cache enable, then with it disabled.

With cache enable: (VBox.log.1) took about 5 minutes (4 last of them powering off).

With cache disabled: (VBox.log) took about 57 minutes!!! (15 minutes to login, then 20 minutes without responsiveness, it restarted suddenly, login again, start powering off and from there another 20 minutes to go completely off).

In both cases VM manager is not responsive only after 1 minute from step 4) all along to end of step 5).

2. A thorough investigation what happens in the interesting minutes could be done, beginning with your favorite task manager on the host OS. Enhanced investigation could be done with Sysinternals Process Monitor and Disk Monitor.

I'm looking all the time at task manager and disk monitor, only "VirtualBoxVM.exe" is intensively "reading" .vdi file, 120 MB/s nonstop. Everything else looks normal to me.

PS: Disabling any AV software on the host for a test would be yet another idea.

I think you nailed it here, windows defender is running. But I cannot stop it (corporation policies, it's my PC at work, only IT can turn it off) although I have excluded every thing posible (folders, files, executables, etc.).

I am going to take this VM guest home and try it on a PC without windows defender, I'll be back.

[albertolozano]

Done.

In a PC with no AV, same guest, same os in host, same virtualbox release:

- in less then 4 minutes with an external drive (usb)

- in 2:22 minutes with a clone on c:\ (ssd)

There is no moment where VM manager seems to freeze.

So I will assume previous misbehaviours where AV related.

[fth0]

Thanks for testing!

I have a theory: If your computer and especially the SSD is quite old, and Windows 10 checks for Windows Updates, it could accumulate a lot of disk I/O that would still be executed while shutting down the virtual disk. Could that be the case here?

How much time was reported by PDMR3PowerOff in your latest tests?

[albertolozano]

Thanks for your attention and feedback.

I have a theory: If your computer and especially the SSD is quite old, and Windows 10 checks for Windows Updates, it could accumulate a lot of disk I/O that would still be executed while shutting down the virtual disk. Could that be the case here?

Yes, that´s a big thing and is why before testing I go through some updates checking, reboots etc. until the guest shows no pending updates anymore.

How much time was reported by PDMR3PowerOff in your latest tests?

VBox log external usb hdd
PDMR3PowerOff: 7 447 138 775 ns run time
That's 7 seconds!!! but with a slow external usb hdd.

VBox log from c ssd
00:02:21.379760 PDMR3PowerOff: 2 163 251 499 ns run time
That's only 2 seconds!!!

So what is normal to take some seconds is up to few minutes with AV interference

I´ll let you know If I can manage to go around the AV interference, maybe there is some path, file or procese I can still get out of it's reach.

[fth0]

So what is normal to take some seconds

I would even debate that: In my own setups, and also in some "randomly" selected log files from the VirtualBox forums, it usually takes between 1 and 5 milliseconds.

[albertolozano]

I've compared logs (host with AV vs host without AV) and these are the main differences:

VBox.log differences.png (93.61 KiB) Viewed 5891 times

As was already stated the event VMMDEV_EVENT_MOUSE_POSITION_CHANGED (0x200) is not an issue. Just happens to appear because time is so large that chances the mouse roll in or out are big as well.

What about "HM: Enabled full VMCS shadowing" is that a thing?

Thanks in advance.

[fth0]

What about "HM: Enabled full VMCS shadowing" is that a thing?

Maybe. In your VM configuration, you've enabled System > Processor > Nested VT-x/AMD-V. If you don't need nested virtualization (VM inside VM), you can disable it and see if it has any influence. To support nested virtualization better, Intel vPro CPUs provide the VMCS Shadowing capability. Search the log files for "VmcsShadowing" to see the difference between your two hosts reported by the respective CPU.