Clock extreme slowness/Behavior of VBoxService

[_MT_]

Virtualbox 4.3.6
VBoxService 4.3.6r91406
Host: Ubuntu 12.04.4 LTS (GNU/Linux 3.8.0-35-generic x86_64) (call it HOST)
Guest: Ubuntu 10.04.4 LTS (and others) (call it GUEST)

Problem: Using the GuestAdditions doesn't prevent rapid & erratic clock swings.
Synopsis: It appears that VBoxService is not correctly reporting the Host's time.

We've been running VirtualBox for a bit more than 6 months and have never solved the problems of the guest clock being very slow once the guest gets a heavy load. Most of our systems do not use the Guest Additions but do use NTP. However, with load, NTP can't keep up with the clock's increased slowness and quits once the difference from real time gets to a certain threshold. At that point, the clock spins totally out of control. It seems that NTP is ill-suited for a system whose clock is wildly erratic (due to varying system load).

My belief is that the approach of the GuestAdditions is better suited to VMs with varying loads (and so varying clocks). Running NTP on top of GA seems futile as NTP expects a near constant (if imperfect) ticker and GA violates that assumption.

As a test, we have one system (Ubuntu 10.04.4LTS) with GA and not NTP.
(I've sent the timesync-set-threshold to be 60 seconds (60000), which you'll see in action, as an attempt to bound the lossage.)
While it hasn't hit a point of futility, GUEST's sense of time is wildly erratic (see below).

To understand what was going on, I turned the verbosity up of VBoxService and logged it on a machine with a good clock. I did (from a third host whose clock is within a few milliseconds of HOST) ssh GUEST "/usr/sbin/VBoxService -vvv -f" | logger -t guestVBoxService
The timestamps on the the syslog lines are from the third host, but can be considered equivalent to HOST.


Before long, GUEST gets 5 seconds behind real time. Unexpectedly, the reported time of HOST is negligibly different than GUEST.

• Jun 2 19:44:30 OTHER guestVBoxService: 00:01:10.023915 timesync VBoxServiceTimeSyncWorker: Host: 2014-06-03T02:44:25.188000000Z (MinAdjust: 200 ms)
  Jun 2 19:44:30 OTHER guestVBoxService: 00:01:10.024011 timesync VBoxServiceTimeSyncWorker: Guest: - 2014-06-03T02:44:25.189669000Z => -1 669 000 ns drift

VBoxService thinks it has only run 10 more seconds (1:10 becoming 1:20) but the real clock has ticked 28 seconds, so it is now 23 seconds behind. Again, VBoxService seems to be claiming that HOST and GUEST are still synced.

• Jun 2 19:44:58 OTHER guestVBoxService: 00:01:20.024620 timesync VBoxServiceTimeSyncWorker: Host: 2014-06-03T02:44:35.189000000Z (MinAdjust: 200 ms)
  Jun 2 19:44:58 OTHER guestVBoxService: 00:01:20.024793 timesync VBoxServiceTimeSyncWorker: Guest: - 2014-06-03T02:44:35.190387000Z => -1 387 000 ns drift

Seventy-five seconds later, it is a full minute behind. VBoxService claims HOST and GUEST are still synced.

• Jun 2 19:46:15 OTHER guestVBoxService: 00:02:00.031056 timesync VBoxServiceTimeSyncWorker: Host: 2014-06-03T02:45:15.194000000Z (MinAdjust: 200 ms)
  Jun 2 19:46:15 OTHER guestVBoxService: 00:02:00.031130 timesync VBoxServiceTimeSyncWorker: Guest: - 2014-06-03T02:45:15.196813000Z => -2 813 000 ns drift

At the next clock check 17 real seconds later, VBoxService claims HOST is now exactly 1 minute ahead of GUEST. VBoxService tries to adjust the time, but that is doomed with this rate of difference.

• Jun 2 19:46:32 OTHER guestVBoxService: 00:02:10.031825 timesync VBoxServiceTimeSyncWorker: Host: 2014-06-03T02:46:25.196000000Z (MinAdjust: 100 ms)
  Jun 2 19:46:32 OTHER guestVBoxService: 00:02:10.031908 timesync VBoxServiceTimeSyncWorker: Guest: - 2014-06-03T02:45:25.197590000Z => 59 998 410 000 ns drift
  Jun 2 19:46:32 OTHER guestVBoxService: 00:02:10.031980 timesync VBoxServiceTimeSyncAdjust: adjtime by 59 998 410 000 ns

At the next clock check 28 real seconds later, the guest has not yet made any real progress in adjusting the time, but keeps trying.

• Jun 2 19:47:00 OTHER guestVBoxService: 00:02:20.032582 timesync VBoxServiceTimeSyncWorker: Host: 2014-06-03T02:46:35.192000000Z (MinAdjust: 100 ms)
  Jun 2 19:47:00 OTHER guestVBoxService: 00:02:20.032776 timesync VBoxServiceTimeSyncWorker: Guest: - 2014-06-03T02:45:35.198333000Z => 59 993 667 000 ns drift
  Jun 2 19:47:00 OTHER guestVBoxService: 00:02:20.032868 timesync VBoxServiceTimeSyncAdjust: adjtime by 59 993 667 000 ns

90 real seconds later, VBoxService shows the HOST's clock again jumping by a minute relative to the GUEST. The clock is now over 2 minutes off (> timesync_set_interval), so the adjtime is dropped and the clock is just set. So, in 5:12 of real time, the GUEST clock advanced only 3:10.

• Jun 2 19:48:28 OTHER guestVBoxService: 00:03:10.038097 timesync VBoxServiceTimeSyncWorker: Host: 2014-06-03T02:48:25.177000000Z (MinAdjust: 100 ms)
  Jun 2 19:48:28 OTHER guestVBoxService: 00:03:10.038209 timesync VBoxServiceTimeSyncWorker: Guest: - 2014-06-03T02:46:25.203817000Z => 119 973 183 000 ns drift
  Jun 2 19:48:28 OTHER guestVBoxService: 00:03:10.038435 timesync time set to 2014-06-03T02:48:25.177261000Z

At the next clock check, the guest is back to the point where the VBoxService shows a relatively small difference, but there really is about 25 seconds of difference.

• Jun 2 19:49:00 OTHER guestVBoxService: 00:03:20.039198 timesync VBoxServiceTimeSyncWorker: Host: 2014-06-03T02:48:35.178000000Z (MinAdjust: 100 ms)
  Jun 2 19:49:00 OTHER guestVBoxService: 00:03:20.039332 timesync VBoxServiceTimeSyncWorker: Guest: - 2014-06-03T02:48:35.178132000Z => -132 000 ns drift

And so the process repeats...

What I can't understand is the claim that the parent clock and the guest clock are close here. Nor can I understand where the seconds part of the parent's clock is coming from. If that were working right, VBoxService should have started adjusting the time earlier.

[loukingjr]

In the 5 years I've been running VirtualBox and hundreds of guest installs, I have never seen the guest time and host time vary by more than a second. There was one Linux distro whose name I've long forgotten that just wouldn't sync with the host's time. It wasn't Ubuntu however. I set all my guests to UTC time when I install them if available. Not much I can add.

[mpack]

There was one Linux distro whose name I've long forgotten that just wouldn't sync with the host's time. It wasn't Ubuntu however.

From memory:

This wasn't a problem with a specific Linux distro, the problem came when the user had selected a kernel with an unusually high system tick rate (e.g. so-called real time kernels). Use or non-use of the IO-APIC may also have an influence.

[_MT_]

This report seems to explain to the problem I'm having
https://www.virtualbox.org/ticket/11514

First, the offset of your guests is the same as reported in the log file: The TM: Giving up catch-up attempt at a 60 000 040 446 ns lag; new total: 46 960 224 999 916 ns message says that the current guest offset is now 46 seconds.

This behavior comes from some timing problem. Most likely one or both VMs are not able to keep the internal timing up-to-date because 8 guest CPUs are sometimes too many for 6 host cores. Don't take the hyperthreads into account here as they wouldn't help much for virtualization.

Basically the person setting this up thought he could use up to 8 virtual cpus on a system with 4 cores (where hyperthreading could support up to 8 threads).
That's wrong. He can only use 4 virtual CPUs. We had 5 assigned. When the systems got busy, things didn't go so well.

More reference on the issue:
http://wahlnetwork.com/2013/09/30/hyper ... pu-sizing/