Time sync: incorrect host time

[Markus]

I have noticed that I do not get the time set correctly on my virtuals machines. They do sync but are always behind the host's time (which is set per ntp correctly) and funnily the times between several VMs running on the same host vary.

When I started to dig for the reason I started VBoxService with -vvv and saw that the Host time displayed there was not the actual time of the host (i.e. the windows machine on which the VMs are running).

I expected the time shown in the log as "Host:" would be the host time, e.g:

00:00:00.005246 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-22T13:39:47.465000000Z

Unfortunately it differs from the hosts time. Even more suspicious: it differs differently on various VMs of the same host. Could this be the reason why time sync does not work correctly?

Below more debug output.

root@orpdm-03:~#  /usr/sbin/VBoxService -f -vvv --enable-timesync --timesync-interval 1000
VBoxService 4.2.4 r81684 (verbosity: 3) linux.amd64 (Oct 26 2012 19:49:17) release log
00:00:00.002083 main     Log opened 2013-02-22T13:37:48.290070000Z
00:00:00.002159 main     OS Product: Linux
00:00:00.002180 main     OS Release: 3.2.0-37-generic
00:00:00.002199 main     OS Version: #58-Ubuntu SMP Thu Jan 24 15:28:10 UTC 2013
00:00:00.002388 main     OS Service Pack: #58-Ubuntu SMP Thu Jan 24 15:28:10 UTC 2013
00:00:00.002412 main     Executable: /opt/VBoxGuestAdditions-4.2.4/sbin/VBoxService
00:00:00.002415 main     Process ID: 31071
00:00:00.002418 main     Package type: LINUX_64BITS_GENERIC
00:00:00.002608 main     4.2.4 r81684 started. Verbose level = 3
00:00:00.002766 main     Initializing services ...
00:00:00.003517 main     Service client ID: 0x24
00:00:00.003767 main     VMInfo: Property Service Client ID: 0x25
00:00:00.003810 main     VBoxServiceBalloonInit
00:00:00.003847 main     MemBalloon: VbglR3MemBalloonRefresh failed with VERR_PERMISSION_DENIED
00:00:00.003942 main     Service 'memballoon' was disabled because of missing functionality
00:00:00.003965 main     VBoxServiceVMStatsInit
00:00:00.004058 main     VBoxStatsInit: New statistics interval 0 seconds
00:00:00.004102 main     VBoxServiceAutoMountInit
00:00:00.004353 main     VBoxServiceAutoMountInit: Service Client ID: 0x26
00:00:00.004393 main     Starting services ...
00:00:00.004414 main     Starting service     'control' ...
00:00:00.004706 control  Waiting for host msg ...
00:00:00.004831 main     Starting service     'timesync' ...
00:00:00.005097 main     Starting service     'vminfo' ...
00:00:00.005246 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-22T13:39:47.465000000Z    (MinAdjust: 100 ms)
00:00:00.005341 vminfo   Writing guest property "/VirtualBox/GuestInfo/OS/Product" = "Linux"
00:00:00.005413 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-22T13:37:48.293063000Z => 119 171 937 000 ns drift
00:00:00.005509 timesync VBoxServiceTimeSyncAdjust: adjtime by 119 171 937 000 ns

[Frank Mehnert]

Interesting. Please attach a VBox.log of such a VM session (mainly to see your VM configuration).

[Markus]

VBox.log

[Markus]

Attached a slightly anonymized log file

[Frank Mehnert]

Hmm. How big is the difference between the time displayed as host time in the VBoxService logfile and the real host time? It seems also that your host is quite busy. Are you running several VMs in parallel? If so, how many guest CPUs (sum over all VMs) have you assigned to your guests?

[Markus]

The time differences I have observed so far are between 30 seconds and 15 minutes. So far the displayed time was always behind the real time.

The cpu has 6 cores and 12 threads. There are two VMs running each assigned 4 cpus.

The load on the server is usually far below 100%. Currently it is about 25% and there is a time lag of 45 seconds.

[Markus]

BTW: I found that the version is 4.2.4 (not 4.2.6 as set in the properties above)

[Markus]

I tried a reboot of the host. No success.

Then I tried the following:

• measure the lag (46 sec)
• switch of the time service
• set the system clock directly

The host time reported by VBoxServiceTimeSyncWorker reflects the updated time immediately - however with the lag measured before.

Is there a mechanism in the vboxadd-service which keeps some delta to the host clock?

[Frank Mehnert]

No, there is no mechanism to keep a time difference between guest and host, at least not from VBox tools.

Which Linux guest are you using (distribution) and which Linux kernel version is that?

And do you have some NTP service installed in your guest? If so, disable it.

[Markus]

We are using ubuntu 12.04, kernel 3.2.0. Details below.

There is no ntp server running. The ntp client seems to be a basic package in ubuntu and I could not remove it. It is called as part of the if-up scripts but should not do any harm since it can not connect to a ntp server.

root@orpdm-02:~# ntpdate
26 Feb 10:23:50 ntpdate[20158]: no servers can be used, exiting
root@orpdm-02:~# dpkg --list | grep ntp
pi  ntpdate                          1:4.2.6.p3+dfsg-1ubuntu3.1       client for setting system time from NTP servers
root@orpdm-02:~# dpkg --purge ntpdate
dpkg: dependency problems prevent removal of ntpdate:
 ubuntu-minimal depends on ntpdate.
dpkg: error processing ntpdate (--purge):
 dependency problems - not removing
Errors were encountered while processing:
 ntpdate
root@orpdm-02:~# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 12.04.1 LTS
Release:        12.04
Codename:       precise
root@orpdm-02:~# uname -a
Linux orpdm-02 3.2.0-38-generic #61-Ubuntu SMP Tue Feb 19 12:18:21 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

[Frank Mehnert]

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.

It is very likely that your guest time problems go away if you reduce the number of guest CPUs to 3 per VM. I don't know if it is really necessary to add the time offset to the reported host time, I have to investigate that.

[Markus]

Thanks. I reduced the number of CPUs to three and started only one VM. Now I get a better picture, details below. I hope that the changing drift is normal.

Sorry, I was mislead from the UI which shows 12 cpus whereas there are only 6 cores available and hyperthreading does not seem to be activated at all (the task manager shows 6 CPUs).

00:01:40.013 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:22:30.512137000Z => -1 137 000 ns drift
00:01:50.014 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:22:40.511000000Z    (MinAdjust: 200 ms)
00:01:50.014 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:22:40.513079000Z => -2 079 000 ns drift
00:02:00.019 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:22:50.525000000Z    (MinAdjust: 100 ms)
00:02:00.020 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:22:50.517685000Z => 7 315 000 ns drift
00:02:10.020 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:23:00.526000000Z    (MinAdjust: 100 ms)
00:02:10.020 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:23:00.519213000Z => 6 787 000 ns drift
00:02:20.021 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:23:10.525000000Z    (MinAdjust: 100 ms)
00:02:20.021 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:23:10.520052000Z => 4 948 000 ns drift
00:02:30.023 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:23:20.525000000Z    (MinAdjust: 100 ms)
00:02:30.023 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:23:20.522130000Z => 2 870 000 ns drift
00:02:40.024 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:23:30.525000000Z    (MinAdjust: 100 ms)
00:02:40.024 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:23:30.523016000Z => 1 984 000 ns drift
00:02:50.025 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:23:40.525000000Z    (MinAdjust: 100 ms)
00:02:50.025 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:23:40.524239000Z => 761 000 ns drift
00:03:00.025 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:23:50.524000000Z    (MinAdjust: 100 ms)
00:03:00.026 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:23:50.524491000Z => -491 000 ns drift
00:03:10.026 timesync VBoxServiceTimeSyncWorker: Host:    2013-02-26T14:24:00.524000000Z    (MinAdjust: 100 ms)
00:03:10.026 timesync VBoxServiceTimeSyncWorker: Guest: - 2013-02-26T14:24:00.524990000Z => -990 000 ns drift