Understanding "Giving up catch-up attempt at"

Discussions related to using VirtualBox on Linux hosts.
Post Reply
wfor
Posts: 5
Joined: 24. Dec 2021, 09:15

Understanding "Giving up catch-up attempt at"

Post by wfor »

Hello,

I have a Debian 11 host with AMD 2700x processor (8 physical) with 16 threads with 64 GB of RAM
I am running Virtualbox 6.1.30.
I am using Vagrant to run a few virtual machines on my host machine. These guests are Debian 10 or Debian 11
Most of the time, all of these VMs are completely idle.

Right now, I have these virtual machines up and running
  • 1 CPU core and 512 MB of RAM running Debian 11
  • 2 CPU cores and 8GB GB of RAM running Debian 10
When I create a 3rd VM
  • 4 CPU cores and 8 GB of RAM running Debian 10. The host is idle
I start to see:

Code: Select all

00:00:00.121685 ******************** End of CPUID dump **********************
00:00:00.121703 VMEmt: Halt method global1 (5)
00:00:00.121750 VMEmt: HaltedGlobal1 config: cNsSpinBlockThresholdCfg=2000
00:00:00.121799 Changing the VM state from 'CREATING' to 'CREATED'
00:00:00.122710 Changing the VM state from 'CREATED' to 'POWERING_ON'
00:00:00.122827 Changing the VM state from 'POWERING_ON' to 'RUNNING'
00:00:00.122839 Console: Machine state changed to 'Running'
00:00:00.123120 VBoxHeadless: starting event loop
00:00:00.119554 HM: fUsePauseFilter=false fUseLbrVirt=false fUseVGif=true  fUseVirtVmsaveVmload=true
00:00:00.129148 VMMDev: Guest Log: BIOS: VirtualBox 6.1.30
00:00:00.129148 PCI: Setting up resources and interrupts
00:00:00.129148 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:00.144511 ERROR [COM]: aRC=VBOX_E_VM_ERROR (0x80bb0003) aIID={4680b2de-8690-11e9-b83d-5719e53cf1de} aComponent={DisplayWrap} aText={Could not take a screenshot (VERR_NOT_SUPPORTED)}, preserve=false aResultDetail=-37
00:00:00.144540 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:00.144731 VMMDev: Guest Log: CPUID EDX: 0x178bfbff
00:00:00.145045 VMMDev: Guest Log: BIOS: No PCI IDE controller, not probing IDE
00:00:00.145224 AHCI#0: Reset the HBA
00:00:00.145232 VD#0: Cancelling all active requests
00:00:00.145270 AHCI#0: Port 0 reset
00:00:00.145287 VD#0: Cancelling all active requests
00:00:00.145601 VMMDev: Guest Log: BIOS: AHCI 0-P#0: PCHS=16383/16/63 LCHS=1024/255/63 0x0000000003c00000 sectors
00:00:00.146616 PIT: mode=2 count=0x48d3 (18643) - 64.00 Hz (ch=0)
00:00:00.164235 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=00007f484e1bd000 w=640 h=480 bpp=32 cbLine=0xA00 flags=0x0 origin=0,0
00:00:02.624959 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:02.625255 VMMDev: Guest Log: BIOS: Boot : bseqnr=1, bootseq=0231
00:00:02.625371 VMMDev: Guest Log: BIOS: Boot from Floppy 0 failed
00:00:02.625497 VMMDev: Guest Log: BIOS: Boot : bseqnr=2, bootseq=0023
00:00:02.625623 VMMDev: Guest Log: BIOS: CDROM boot failure code : 0002
00:00:02.625721 VMMDev: Guest Log: BIOS: Boot from CD-ROM failed
00:00:02.625847 VMMDev: Guest Log: BIOS: Boot : bseqnr=3, bootseq=0002
00:00:02.626085 VMMDev: Guest Log: BIOS: Booting from Hard Disk...
00:00:02.679900 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:02.789902 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=00007f484e1bd000 w=640 h=480 bpp=32 cbLine=0xA00 flags=0x0 origin=0,0
00:00:02.954715 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0 origin=0,0
00:00:03.393392 GIM: KVM: VCPU  0: Enabled system-time struct. at 0x000000011adec000 - u32TscScale=0x8a60e078 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x2d121a75f uVirtNanoTS=0xc2e68493 TscKHz=3699998
00:00:03.393491 TM: Switching TSC mode from 'VirtTscEmulated' to 'RealTscOffset'
00:00:03.633953 GIM: KVM: Enabled wall-clock struct. at 0x000000011adeb008 - u32Sec=1640855493 u32Nano=10420673 uVersion=2
00:00:03.656764 PIT: mode=2 count=0x12a5 (4773) - 249.98 Hz (ch=0)
00:00:03.778130 PIT: mode=0 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:03.780085 GIM: KVM: VCPU  1: Enabled system-time struct. at 0x000000011adec040 - u32TscScale=0x8a60e078 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x3266aa3db uVirtNanoTS=0xd9f353b4 TscKHz=3699998
00:00:03.782921 GIM: KVM: VCPU  2: Enabled system-time struct. at 0x000000011adec080 - u32TscScale=0x8a60e078 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x3270c0d0d uVirtNanoTS=0xda1ef399 TscKHz=3699998
00:00:03.785670 GIM: KVM: VCPU  3: Enabled system-time struct. at 0x000000011adec0c0 - u32TscScale=0x8a60e078 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x327a8880e uVirtNanoTS=0xda493e5c TscKHz=3699998
00:00:04.617595 AHCI#0: Reset the HBA
00:00:04.617617 VD#0: Cancelling all active requests
00:00:04.619386 AHCI#0: Port 0 reset
00:00:04.620495 VD#0: Cancelling all active requests
00:00:06.152512 VMMDev: Guest Log: vboxguest: host-version: 6.1.30r148432 0x8000000f
00:00:06.152737 VMMDev: Guest Additions information report: Version 5.2.0 r68940 '5.2.0'
00:00:06.152754 VMMDev: Guest Additions information report: Interface = 0x00010004 osType = 0x00053100 (Linux >= 2.6, 64-bit)
00:00:06.152811 VMMDev: Guest Additions capability report: (0x0 -> 0x0) seamless: no, hostWindowMapping: no, graphics: no
00:00:06.152838 VMMDev: vmmDevReqHandler_HeartbeatConfigure: No change (fHeartbeatActive=false)
00:00:06.152859 VMMDev: Heartbeat flatline timer set to trigger after 4 000 000 000 ns
00:00:06.153026 VMMDev: Guest Log: vbg_heartbeat_init: Setting up heartbeat to trigger every 2000 milliseconds
00:00:06.154469 VMMDev: Guest Log: vboxguest: misc device minor 58, IRQ 20, I/O port d020, MMIO at 0x00000000f0400000 (size 0x0000000000400000)
00:00:06.292698 Enabling different vbva mode
00:00:06.295070 Display::i_handleDisplayResize: uScreenId=0 pvVRAM=00007f484e1bd000 w=800 h=600 bpp=32 cbLine=0xC80 flags=0x1 origin=0,0
01:20:27.327853 TM: Giving up catch-up attempt at a 60 006 204 758 ns lag; new total: 60 006 204 758 ns
01:21:49.317818 TM: Giving up catch-up attempt at a 60 000 237 245 ns lag; new total: 120 006 442 003 ns
01:23:07.166750 TM: Giving up catch-up attempt at a 60 009 221 952 ns lag; new total: 180 015 663 955 ns
01:24:25.914019 TM: Giving up catch-up attempt at a 60 008 247 481 ns lag; new total: 240 023 911 436 ns
01:25:45.958795 TM: Giving up catch-up attempt at a 60 002 603 037 ns lag; new total: 300 026 514 473 ns
01:27:04.025043 TM: Giving up catch-up attempt at a 60 012 467 709 ns lag; new total: 360 038 982 182 ns
01:28:24.031358 TM: Giving up catch-up attempt at a 60 000 240 113 ns lag; new total: 420 039 222 295 ns
...
in the logs of that newly created VM. Once it happened 1 minute after booting, in another case, it happened 1 hour after booting. In both cases, the host and guests are completely idle.

Why is this happening and how do I go about troubleshooting it? It does not appear to cause any noticeable performance issues however.

Questions:
  • What does this error indicate and why does it completely fail to catch up?
  • Is it because I am running Virtualbox on Debian 11 Host? (I installed it via apt from official virtualbox bullseye package mirror deb download [.] virtualbox [.] org/virtualbox/debian bullseye contrib)
  • Is it because I am re-using a preexisting Virtual box image from Vagrant that has Guest additions installed with 5.2.0? (see addendum below)
  • Something to do with the amount of video memory allocated? Because these VMs are intended to be headless, only 8 MB of Video Memory is allocated by default.
I also saw similar messages in the log when running Virtualbox 5.2 on Ubuntu 16.04. Those VMs were running Virtualbox 5.2 with a vagrant image having Guest additions versions 5.2.0
scottgus1
Site Moderator
Posts: 20965
Joined: 30. Dec 2009, 20:14
Primary OS: MS Windows 10
VBox Version: PUEL
Guest OSses: Windows, Linux

Re: Understanding "Giving up catch-up attempt at"

Post by scottgus1 »

wfor wrote:Right now, I have these virtual machines up and running
1 CPU core and 512 MB of RAM running Debian 11
2 CPU cores and 8GB GB of RAM running Debian 10

When I create a 3rd VM
4 CPU cores and 8 GB of RAM running Debian 10.
Could be overdriving the host. But without a complete log, we can't tell.
wfor wrote:I am using Vagrant
We don't support Vagrant-initiated VMs here, because we don't grok Vagrant.

If you have a VM made in and started directly from Virtualbox that does this "giving up catch-up" thing (which I unfortunately do not know what it means) please post a full Virtualbox vbox.log for that unVagrantized VM run:

Start the VM from full power off, not save-state. Run until you see the problem happen, then shut down the VM from within the VM OS if possible. If not possible, close the Virtualbox window for the VM with the Power Off option set.

Please right-click the VM in the main Virtualbox window's VM list, choose Show Log. Save the far left tab's log, zip the log file, and post the zip file, using the forum's Upload Attachment tab.

And while the "giving up catch-up" is going on, please report what the Debian host's "Task Manager" says about CPU and disk usage.
wfor
Posts: 5
Joined: 24. Dec 2021, 09:15

Re: Understanding "Giving up catch-up attempt at"

Post by wfor »

Thank you for the quick reply! It will take a while to get and reproduce this without vagrant.

I don't understand how this 3rd VM it would be overdriving it when only 7 out of the 8 physical cores are allocated. Especially since there 16 logical cores.
The entire host and guests are practically idle.
mpack
Site Moderator
Posts: 39156
Joined: 4. Sep 2008, 17:09
Primary OS: MS Windows 10
VBox Version: PUEL
Guest OSses: Mostly XP

Re: Understanding "Giving up catch-up attempt at"

Post by mpack »

I've seen the "giving up catch-up attempt" log entry thing before. I believe it happens when the GAs have been configured to maintain time sync between host and guest. If it finds the guest lagging behind the host I expect it generates dummy timer events to bring things back to sync, but if the lag keeps getting worse despite its best efforts then it will eventually just reset the time.

It could indicate a badly resourced VM, e.g. one which had too many cores assigned to it. Or not enough (2 cores is usually the sweet spot).

Another thing that jumps out at me is the use of VERY out of date GAs.

We might be able to say more if we had the complete log, rather than just a snippet from it.
wfor
Posts: 5
Joined: 24. Dec 2021, 09:15

Re: Understanding "Giving up catch-up attempt at"

Post by wfor »

Attaching a log. I installed Debian 11 guest from scratch via packer. Let's call this guest test-machine The guest additions now match the version of virtualbox.

The entire time test-machine been idle. At 03:38:35 after the test-machine has been alive for ~3.5 hours, I stopped the 2nd VM that had 2 cores to see if the "giving up" messages would stop being printed out but they did not.

Let me know if the logs help
Attachments
giving_up_log.zip
(28.53 KiB) Downloaded 16 times
fth0
Volunteer
Posts: 5668
Joined: 14. Feb 2019, 03:06
Primary OS: Mac OS X other
VBox Version: PUEL
Guest OSses: Linux, Windows 10, ...
Location: Germany

Re: Understanding "Giving up catch-up attempt at"

Post by fth0 »

FWIW, the accumulated time difference is in the magnitude of 19 of 195 minutes, or roughly 10%. While this is unusual, it must not necessarily pose a problem. Search the VBox.log files for your 3 VMs for lines containing "/TM/VirtualSync" ...
wfor
Posts: 5
Joined: 24. Dec 2021, 09:15

Re: Understanding "Giving up catch-up attempt at"

Post by wfor »

I did more testing. With test-machine above, I initially created it with 2 CPUs and 2 GB of RAM using packer. I then re-used the packer created VM and modified it to have 4 CPUs and 8 GB of RAM

I then used packer to create a VM from scratch with 4 CPUs and 8 GB of RAM. I launched 2 of these without any modification from the initial virtual machine configuration of 4 CPU/8GB RAM. After 16 hours, I did not see any "giving up" log message being printed.

Question: if I create a brand new virtual machine from scratch with 2 CPUs and 2 GB of RAM, and I later modify it to have 4 CPUs and 8 GB of RAM can that cause problems? Perhaps since the already installed guest OS assumes 2 CPUs were present and suddenly there are 4?
wfor
Posts: 5
Joined: 24. Dec 2021, 09:15

Re: Understanding "Giving up catch-up attempt at"

Post by wfor »

Any other thoughts on this topic?

What exactly causes this to happen? Is there any documentation on this particular topic? What is the sync that the Guest Additions are trying to maintain? Is the wall clock time related?
fth0
Volunteer
Posts: 5668
Joined: 14. Feb 2019, 03:06
Primary OS: Mac OS X other
VBox Version: PUEL
Guest OSses: Linux, Windows 10, ...
Location: Germany

Re: Understanding "Giving up catch-up attempt at"

Post by fth0 »

wfor wrote:Question: if I create a brand new virtual machine from scratch with 2 CPUs and 2 GB of RAM, and I later modify it to have 4 CPUs and 8 GB of RAM can that cause problems? Perhaps since the already installed guest OS assumes 2 CPUs were present and suddenly there are 4?
This depends on the guest OS. For example, a Linux OS usually detects CPUs and RAM automatically during booting and therefore has no problems with the changing quantities.
wfor wrote:Any other thoughts on this topic?
The error message is part of the VirtualBox internal handling of clocks, times and timers, and the only documentation that I know is the VirtualBox source code. I'm talking about a deeper level than the wall clock synchronization between the host and the guest here.

For example, imagine a VirtualBox internal timer that would be used to call some function every 4 ms (milliseconds), and the function would execute for 1 ms (which is a very long time for a CPU, BTW). Since the guest OS wouldn't be executed during this time, but the host OS executing VirtualBox would be, VirtualBox must catch-up this 1 ms somehow, preferably during the next 3 ms. VirtualBox can catch-up quite large delays, but when the delays have accumulated 60 seconds, those 60 seconds are given up and added to all previously given-up 60 second delays.

If you're interested in a live show, open a terminal on your host, and execute watch -d -n 1 VBoxManage debugvm "VM name" info clocks. ;)
Post Reply