sporadic boot failure on multiple systems

Discussions related to using VirtualBox on Linux hosts.
Post Reply
MrBurns
Posts: 9
Joined: 29. Oct 2020, 17:29

sporadic boot failure on multiple systems

Post by MrBurns »

I am trying to get to the bottom of an unreliability issue that plagues my Virtualbox usage.
I am using Virtualbox 6.1.40 with matching GA.
I have written some bash scripts that loop through booting a stripped down vm.
The scripts run until they encounter an error.
Sometimes I boot in series 10, or 20, or 50, or 100 instances, but I always eventually encounter a boot failure.
The Gui appears in its tty stage, black and with nothing in it.
All I can do is hard poweroff such instances.
There are five attached logs that are named per my system I have run them on.
My test systems are as follows...

P1 - Lenovo P1 with ample memory
Skylake - Intel Skylake 6800k with ample memory
Ryzen - AMD Ryzen 5950x with 64G memory
Epyc - AMD Epyc (first gen) with 64G memory

All eventually fail.

I posted this before with logs in the Windows section. I would have continued with that posting, but it was locked.

viewtopic.php?f=6&t=108370

Seeing as the following tests come from an Ubuntu 20.04 system I am posting in this channel instead.

In myy comparison of the logs of a working vs non-working instance I have condensed the differences to be the following...

SUCCESSFULL RUN...
...
00:00:01.793431 ******************** End of CPUID dump **********************
00:00:01.793466 VMEmt: Halt method global1 (5)
00:00:01.793503 VMEmt: HaltedGlobal1 config: cNsSpinBlockThresholdCfg=2000
00:00:01.793511 Changing the VM state from 'CREATING' to 'CREATED'
00:00:01.795776 SharedFolders host service: Adding host mapping
00:00:01.795776 Host path '/home/picasso/pwork/basebox/ubuntu2004-amd64-lvm', map name 'vagrant', writable, automount=false, automntpnt=, create_symlinks=true, missing=false
00:00:01.795776 Changing the VM state from 'CREATED' to 'POWERING_ON'
00:00:01.795776 AIOMgr: Endpoints without assigned bandwidth groups:
00:00:01.795776 AIOMgr: /home/picasso/VirtualBox VMs/ubuntu2004-amd64-lvm_default_1674755058763_18761/box-disk001.vmdk
00:00:01.795776 Changing the VM state from 'POWERING_ON' to 'RUNNING'
00:00:01.795776 Console: Machine state changed to 'Running'
00:00:01.788231 HM: fUsePauseFilter=false fUseLbrVirt=false fUseVGif=true fUseVirtVmsaveVmload=true
00:00:01.795776 GUI: Capturing keyboard on resume
00:00:01.800201 VMMDev: Guest Log: BIOS: VirtualBox 6.1.40
00:00:01.800351 PCI: Setting up resources and interrupts
00:00:01.801625 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:01.821261 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:01.824637 VMMDev: Guest Log: CPUID EDX: 0x178bfbff
00:00:01.825014 AHCI#0: Reset the HBA
00:00:01.825019 VD#0: Cancelling all active requests
00:00:01.825066 AHCI#0: Port 0 reset
00:00:01.825110 VD#0: Cancelling all active requests
00:00:01.825539 VMMDev: Guest Log: BIOS: AHCI 0-P#0: PCHS=16383/16/63 LCHS=1024/255/63 0x0000000010000000 sectors
00:00:01.826002 PIT: mode=2 count=0x48d3 (18643) - 64.00 Hz (ch=0)
00:00:01.849497 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=00007f1a0e000000 w=640 h=480 bpp=32 cbLine=0xA00 flags=0x0 origin=0,0
00:00:02.298917 GUI: UIMachineViewNormal::resendSizeHint: Restoring guest size-hint for screen 0 to 800x600
00:00:02.302370 GUI: 2D video acceleration is disabled
00:00:02.302487 GUI: HID LEDs sync is not supported on this platform
00:00:02.312525 GUI: UIMachineLogicNormal::sltCheckForRequestedVisualStateType: Requested-state=0, Machine-state=5
00:00:02.573985 NAT: Old socket recv size: 128KB
00:00:02.574024 NAT: Old socket send size: 128KB
00:00:02.987361 GUI: Machine-window #0 deactivated
00:00:02.987408 GUI: Releasing mouse on focus out
00:00:02.987414 GUI: Releasing keyboard on focus out
00:00:02.990817 GUI: Machine-view #0 unfocused, reason=3
00:00:04.311527 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:04.318969 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:04.319156 VMMDev: Guest Log: BIOS: Boot : bseqnr=1, bootseq=0002
00:00:04.323838 VMMDev: Guest Log: BIOS: Booting from Hard Disk...
00:00:04.595857 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=00007f1a0e000000 w=640 h=480 bpp=32 cbLine=0xA00 flags=0x0 origin=0,0
00:00:05.966440 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:06.179195 PIT: mode=2 count=0x12a5 (4773) - 249.98 Hz (ch=0)
00:00:06.712922 IEM: rdmsr(0x48) -> #GP(0)
00:00:06.712944 IEM: rdmsr(0x122) -> #GP(0)
00:00:06.712951 IEM: rdmsr(0x10f) -> #GP(0)
00:00:06.712958 IEM: rdmsr(0x123) -> #GP(0)
00:00:07.061485 AHCI#0: Reset the HBA
00:00:07.061522 VD#0: Cancelling all active requests
00:00:07.082185 AHCI#0: Port 0 reset
00:00:07.087471 VD#0: Cancelling all active requests
00:00:07.223716 PIT: mode=4 count=0xff3 (4083) - 292.23 Hz (ch=0)
00:00:07.227235 PIT: mode=4 count=0x126d (4717) - 252.95 Hz (ch=0)
00:00:07.227264 PIT: mode=4 count=0x126d (4717) - 252.95 Hz (ch=0)
00:00:07.231310 PIT: mode=4 count=0x1295 (4757) - 250.82 Hz (ch=0)
00:00:07.231344 PIT: mode=4 count=0x1295 (4757) - 250.82 Hz (ch=0)
00:00:07.235468 PIT: mode=4 count=0x1264 (4708) - 253.43 Hz (ch=0)
00:00:07.235501 PIT: mode=4 count=0x124a (4682) - 254.84 Hz (ch=0)
00:00:07.238827 PIT: mode=4 count=0x1249 (4681) - 254.89 Hz (ch=0)
00:00:07.238856 PIT: mode=4 count=0x1249 (4681) - 254.89 Hz (ch=0)
00:00:07.242859 PIT: mode=4 count=0x129a (4762) - 250.56 Hz (ch=0)
00:00:07.242887 PIT: mode=4 count=0x129a (4762) - 250.56 Hz (ch=0)
00:00:07.246974 PIT: mode=4 count=0x128b (4747) - 251.35 Hz (ch=0)
00:00:07.247003 PIT: mode=4 count=0x128b (4747) - 251.35 Hz (ch=0)
00:00:07.251076 PIT: mode=4 count=0x1286 (4742) - 251.61 Hz (ch=0)
00:00:07.251105 PIT: mode=4 count=0x1286 (4742) - 251.61 Hz (ch=0)
00:00:07.255125 PIT: mode=4 count=0x17 (23) - 51877.47 Hz (ch=0)
00:00:07.255183 PIT: mode=4 count=0xf (15) - 79545.46 Hz (ch=0)
00:00:07.255250 PIT: mode=4 count=0x129a (4762) - 250.56 Hz (ch=0)
00:00:07.255274 PIT: mode=4 count=0x128e (4750) - 251.19 Hz (ch=0)
00:00:07.259329 PIT: mode=4 count=0x1291 (4753) - 251.03 Hz (ch=0)
00:00:07.259362 PIT: mode=4 count=0x128b (4747) - 251.35 Hz (ch=0)
00:00:07.263392 PIT: mode=4 count=0x129f (4767) - 250.30 Hz (ch=0)
00:00:07.263421 PIT: mode=4 count=0x1292 (4754) - 250.98 Hz (ch=0)
00:00:07.267480 PIT: mode=4 count=0x1294 (4756) - 250.87 Hz (ch=0)
00:00:07.267508 PIT: mode=4 count=0x1237 (4663) - 255.88 Hz (ch=0)
00:00:07.270846 PIT: mode=4 count=0x1252 (4690) - 254.40 Hz (ch=0)
00:00:07.270875 PIT: mode=4 count=0x1252 (4690) - 254.40 Hz (ch=0)
00:00:07.464105 Enabling different vbva mode
00:00:07.470272 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=00007f1a0e000000 w=800 h=600 bpp=32 cbLine=0xC80 flags=0x1 origin=0,0
00:00:09.437272 NAT: Link up
00:00:10.137400 VMMDev: Guest Additions information report: Version 6.1.38 r153438 '6.1.38_Ubuntu'
00:00:10.137454 VMMDev: Guest Additions information report: Interface = 0x00010004 osType = 0x00053100 (Linux >= 2.6, 64-bit)
00:00:10.137545 VMMDev: Guest Additions capability report: (0x0 -> 0x0) seamless: no, hostWindowMapping: no, graphics: no
00:00:10.137590 VMMDev: vmmDevReqHandler_HeartbeatConfigure: No change (fHeartbeatActive=false)
00:00:10.137634 VMMDev: Heartbeat flatline timer set to trigger after 4 000 000 000 ns
00:00:10.137680 VMMDev: Guest Log: vgdrvHeartbeatInit: Setting up heartbeat to trigger every 2000 milliseconds
...


FAILED RUN...
...
00:00:01.767654 ******************** End of CPUID dump **********************
00:00:01.767685 VMEmt: Halt method global1 (5)
00:00:01.767720 VMEmt: HaltedGlobal1 config: cNsSpinBlockThresholdCfg=2000
00:00:01.767726 Changing the VM state from 'CREATING' to 'CREATED'
00:00:01.769982 SharedFolders host service: Adding host mapping
00:00:01.770025 Host path '/home/picasso/pwork/basebox/ubuntu2004-amd64-lvm', map name 'vagrant', writable, automount=false, automntpnt=, create_symlinks=true, missing=false
00:00:01.770855 Changing the VM state from 'CREATED' to 'POWERING_ON'
00:00:01.770878 AIOMgr: Endpoints without assigned bandwidth groups:
00:00:01.770881 AIOMgr: /home/picasso/VirtualBox VMs/ubuntu2004-amd64-lvm_default_1674700599507_33248/box-disk001.vmdk
00:00:01.771335 Changing the VM state from 'POWERING_ON' to 'RUNNING'
00:00:01.771343 Console: Machine state changed to 'Running'
00:00:01.764130 HM: fUsePauseFilter=false fUseLbrVirt=false fUseVGif=true fUseVirtVmsaveVmload=true
00:00:01.771815 GUI: Capturing keyboard on resume
00:00:01.772603 VMMDev: Guest Log: BIOS: VirtualBox 6.1.40
00:00:01.772677 PCI: Setting up resources and interrupts
00:00:01.773102 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:01.787311 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:01.790815 VMMDev: Guest Log: CPUID EDX: 0x178bfbff
00:00:01.791186 AHCI#0: Reset the HBA
00:00:01.791209 VD#0: Cancelling all active requests
00:00:01.791260 AHCI#0: Port 0 reset
00:00:01.791300 VD#0: Cancelling all active requests
00:00:01.791716 VMMDev: Guest Log: BIOS: AHCI 0-P#0: PCHS=16383/16/63 LCHS=1024/255/63 0x0000000010000000 sectors
00:00:01.792173 PIT: mode=2 count=0x48d3 (18643) - 64.00 Hz (ch=0)
00:00:01.819591 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=00007f05514af000 w=640 h=480 bpp=32 cbLine=0xA00 flags=0x0 origin=0,0
00:00:02.272334 GUI: UIMachineViewNormal::resendSizeHint: Restoring guest size-hint for screen 0 to 800x600
00:00:02.275315 GUI: 2D video acceleration is disabled
00:00:02.275315 GUI: HID LEDs sync is not supported on this platform
00:00:02.288234 GUI: UIMachineLogicNormal::sltCheckForRequestedVisualStateType: Requested-state=0, Machine-state=5
00:00:02.579815 NAT: Old socket recv size: 128KB
00:00:02.579862 NAT: Old socket send size: 128KB
00:00:04.273862 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:04.274118 VMMDev: Guest Log: BIOS: Boot : bseqnr=1, bootseq=0002
00:00:04.279053 VMMDev: Guest Log: BIOS: Booting from Hard Disk...
00:00:04.328802 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:04.549896 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=00007f05514af000 w=640 h=480 bpp=32 cbLine=0xA00 flags=0x0 origin=0,0
00:00:05.812156 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:05.923578 GIM: KVM: VCPU 0: Enabled system-time struct. at 0x0000000021c01000 - u32TscScale=0xf3cf4552 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x207ae53a1 uVirtNanoTS=0xf7779e06 TscKHz=2099998
00:00:05.923619 TM: Switching TSC mode from 'Dynamic' to 'RealTscOffset'
00:00:06.012127 GIM: KVM: Enabled wall-clock struct. at 0x0000000021c00000 - u32Sec=1674700607 u32Nano=699450919 uVersion=2
00:00:06.069271 PIT: mode=2 count=0x12a5 (4773) - 249.98 Hz (ch=0)
00:00:06.185766 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.207413 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.207470 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.234285 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.234340 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.259287 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.259342 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.287345 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.287406 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.315101 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.315158 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.343376 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.343438 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.371053 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.371110 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.397615 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.397671 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.426580 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.426638 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.453748 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.453805 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.480468 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.480524 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.507693 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.507750 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.536199 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:00:06.536254 PIT: mode=4 count=0x7fff (32767) - 36.41 Hz (ch=0)
00:05:39.683787 GUI: Machine-window #0 deactivated
00:05:39.683850 GUI: Releasing mouse on focus out
00:05:39.683857 GUI: Releasing keyboard on focus out
00:05:39.686843 GUI: Machine-view #0 unfocused, reason=3
nothing more - hung
Post Reply