[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

[Xen-users] RFH xen-4.1: Time jumps after migration notwithstanding ntpdate


  • To: xen-users@xxxxxxxxxxxxx
  • From: Philipp Hahn <hahn@xxxxxxxxxxxxx>
  • Date: Mon, 15 Feb 2016 09:10:31 +0100
  • Delivery-date: Mon, 15 Feb 2016 08:11:45 +0000
  • List-id: Xen user discussion <xen-users.lists.xen.org>

Hello,

while preparing for an upgrade our infrastructure from xen-4.1 to
something newer we observed the following strange behaviour while
migrating some VMs between hosts still running xen-4.1 having different
CPU generations:

source host:
        dom0: 1/16 Intel(R) Xeon(R) CPU           E5620  @ 2.40GHz
        linux-3.10.X
        /proc/cpuinfo: tsc
        uptime: 382 days

target host:
        dom0: 4/24 Intel(R) Xeon(R) CPU E5-2430L v2 @ 2.40GHz
        linux-3.10.X
        /proc/cpuinfo: tsc constant_tsc nonstop_tsc tsc_deadline_timer
        uptime: 9 days

domU:
        4 vCPU
        linux-3.2.X
        /proc/cpuinfo: tsc constant_tsc
        upime: 144 days
        
Both host and the VM run linux seeing
/sys/devices/system/clocksource/clocksource0/current_clocksource=xen.

The VMs were migrated from source to target, which shows the following
for `xm debug-key s; xm dmesg`:
> (XEN) TSC marked as reliable, warp = 0 (count=2)
> (XEN) dom1: mode=0,ofs=0xff8d83a804c7866d,khz=2400147,inc=2,vtsc count: 
> 1596899605 kernel, 4044707 user
> (XEN) dom2: mode=0,ofs=0xff8d83a804e58066,khz=2400147,inc=2,vtsc count: 
> 1709436299 kernel, 4439657 user
> (XEN) dom3: mode=0,ofs=0xff8d83a804fdef6f,khz=2400147,inc=2,vtsc count: 
> 1651649576 kernel, 4336582 user
> (XEN) dom4: mode=0,ofs=0xff99cb63236c84ce,khz=2400137,inc=3,vtsc count: 
> 2006269345 kernel, 1461832 user

For the source host (now empty):
> (XEN) TSC marked as reliable, warp = 0 (count=2)
> (XEN) No domains have emulated TS

All host run "ntpdate" as a cron-job every minute (management decided to
not use NTPd, as it had(has?) the bad habit to quit itself if the time
difference gets to big and it takes too long to get the time correct again)


Just after migration all 4 domUs had time problems: For 5 minutes the
time of the domU jumped forward and backward several times up to several
weeks:

> Time on log server    Time in domU + message
> Feb 09 10:01:17       Feb 9 10:01:15 ntpdate[18949]: step time server 
> X.X.X.241 offset -267.036154 sec
> Feb 09 10:01:17       Feb 9 09:56:48 ntpdate[18982]: step time server 
> X.X.X.241 offset -267.035203 sec
> Feb 09 10:01:23       Feb 9 09:52:22 ntpdate[19004]: step time server 
> X.X.X.241 offset -267.035192 sec
> Feb 09 10:01:23       Feb 9 09:47:55 ntpdate[19057]: step time server 
> X.X.X.241 offset -267.034859 sec
> Feb 09 10:01:29       Feb 9 09:52:29 ntpdate[19225]: step time server 
> X.X.X.242 offset 267.036897 sec
> Feb 09 10:01:29       Feb 9 10:01:24 ntpdate[19259]: step time server 
> X.X.X.241 offset 534.071787 sec
> Feb 09 10:01:29       Feb 9 10:23:40 ntpdate[19302]: step time server 
> X.X.X.241 offset 801.106797 sec
> Feb 09 10:01:29       Feb 9 10:10:18 ntpdate[19273]: step time server 
> X.X.X.241 offset 534.071745 sec
> Feb 09 10:01:35       Feb 9 10:37:07 ntpdate[19454]: step time server 
> X.X.X.241 offset 801.105406 sec
> Feb 09 10:01:35       Feb 9 10:46:02 ntpdate[19472]: step time server 
> X.X.X.242 offset 534.070318 sec
> Feb 09 10:01:35       Feb 9 10:37:09 ntpdate[19521]: step time server 
> X.X.X.241 offset -534.073792 sec
> Feb 09 10:01:35       Feb 9 10:28:15 ntpdate[19544]: step time server 
> X.X.X.241 offset -534.073642 sec
> Feb 09 10:01:35       Feb 9 09:43:45 ntpdate[19615]: step time server 
> X.X.X.241 offset -1335.180374 sec
> Feb 09 10:01:35       Feb 9 09:21:30 ntpdate[19627]: step time server 
> X.X.X.241 offset -1335.180260 sec
> Feb 09 10:01:35       Feb 9 10:06:00 ntpdate[19566]: step time server 
> X.X.X.241 offset -1335.180483 sec
> Feb 09 10:01:41       Feb 9 08:46:00 ntpdate[19755]: step time server 
> X.X.X.241 offset -2136.285654 sec
> Feb 09 10:01:48       Feb 9 08:01:30 ntpdate[19785]: step time server 
> X.X.X.241 offset -2670.355858 sec
> Feb 09 10:01:49       Feb 9 07:34:48 ntpdate[19820]: step time server 
> X.X.X.241 offset -1602.208335 sec
> Feb 09 10:01:49       Feb 9 07:30:21 ntpdate[19828]: step time server 
> X.X.X.241 offset -267.027900 sec
> Feb 09 10:01:49       Feb 9 08:28:14 ntpdate[19885]: step time server 
> X.X.X.242 offset 2403.333094 sec
> Feb 09 10:01:49       Feb 9 09:08:17 ntpdate[19896]: step time server 
> X.X.X.241 offset 2403.332812 sec
> Feb 09 10:01:49       Feb 9 07:48:10 ntpdate[19854]: step time server 
> X.X.X.241 offset 1068.152487 sec
> Feb 09 10:01:53       Feb 9 10:24:03 ntpdate[19962]: step time server 
> X.X.X.241 offset 4539.618620 sec
> Feb 09 10:01:53       Feb 9 12:24:13 ntpdate[19983]: step time server 
> X.X.X.241 offset 7209.974582 sec
> Feb 09 10:01:53       Feb 9 17:09:05 ntpdate[20042]: step time server 
> X.X.X.241 offset 8011.058341 sec
> Feb 09 10:01:53       Feb 9 19:35:57 ntpdate[20110]: step time server 
> X.X.X.241 offset 3204.392280 sec
> Feb 09 10:01:53       Feb 9 18:42:33 ntpdate[20080]: step time server 
> X.X.X.242 offset 5607.723221 sec
> Feb 09 10:01:53       Feb 9 21:22:46 ntpdate[20138]: step time server 
> X.X.X.241 offset 3204.392452 sec
> Feb 09 10:01:53       Feb 9 14:55:33 ntpdate[20012]: step time server 
> X.X.X.241 offset 9079.210735 sec
> Feb 09 10:01:53       Feb 9 20:29:22 ntpdate[20122]: step time server 
> X.X.X.241 offset 3204.392221 sec
> Feb 09 10:02:01       Feb 9 21:00:37 ntpdate[20191]: step time server 
> X.X.X.241 offset -1335.226079 sec
> Feb 09 10:02:01       Feb 9 09:57:30 ntpdate[20280]: step time server 
> X.X.X.241 offset -31243.192884 sec
> Feb 09 10:02:01       Feb 9 18:38:12 ntpdate[20223]: step time server 
> X.X.X.241 offset -8545.200672 sec
> Feb 09 10:02:01       Feb 8 13:02:27 ntpdate[20366]: step time server 
> X.X.X.241 offset -40856.369882 sec
> Feb 09 10:02:01       Feb 8 01:41:31 ntpdate[20414]: step time server 
> X.X.X.241 offset -40856.369613 sec
> Feb 09 10:02:01       Feb 9 00:23:23 ntpdate[20321]: step time server 
> X.X.X.241 offset -34447.585077 sec
> Feb 09 10:02:09       Feb 7 17:05:21 ntpdate[20580]: step time server 
> X.X.X.241 offset -30975.942829 sec
> Feb 09 10:02:09       Feb 7 08:29:06 ntpdate[20641]: step time server 
> X.X.X.241 offset -30975.942754 sec
> Feb 09 10:02:09       Feb 7 08:33:34 ntpdate[20663]: step time server 
> X.X.X.241 offset 267.250120 sec
> Feb 09 10:02:09       Feb 8 15:11:40 ntpdate[20702]: step time server 
> X.X.X.241 offset 75571.205087 sec
> Feb 09 10:02:09       Feb 7 18:12:09 ntpdate[20683]: step time server 
> X.X.X.241 offset 34714.835227 sec
> Feb 09 10:02:09       Feb 9 23:32:08 ntpdate[20713]: step time server 
> X.X.X.242 offset 116427.575179 sec
> Feb 09 10:02:26       Feb 3 01:54:08 ntpdate[21230]: step time server 
> X.X.X.241 offset -490811.957749 sec
> Feb 09 10:02:26       Feb 8 18:14:19 ntpdate[21196]: step time server 
> X.X.X.241 offset -312432.497250 sec
> Feb 09 10:02:26       Jan 6 05:16:44 ntpdate[21320]: step time server 
> X.X.X.241 offset -255549.968204 sec
> Feb 09 10:02:26       Jan12 03:15:03 ntpdate[21295]: step time server 
> X.X.X.242 offset -255549.967986 sec
> Feb 09 10:02:26       Jan 9 04:15:53 ntpdate[21306]: step time server 
> X.X.X.241 offset -255549.968430 sec
> Feb 09 10:02:26       Jan15 02:14:13 ntpdate[21280]: step time server 
> X.X.X.242 offset -420578.947688 sec
> Feb 09 10:02:26       Jan26 17:43:59 ntpdate[21253]: step time server 
> X.X.X.241 offset -634209.335155 sec
> Feb 09 10:02:26       Jan19 23:03:51 ntpdate[21266]: step time server 
> X.X.X.241 offset -585607.927827 sec
> Feb 09 10:02:35       Jan 6 21:04:52 ntpdate[21395]: step time server 
> X.X.X.241 offset 56882.529017 sec
> Feb 09 10:02:35       Jan13 05:13:07 ntpdate[21419]: step time server 
> X.X.X.241 offset 547694.486803 sec
> Feb 09 10:02:36       Feb 2 16:11:39 ntpdate[21450]: step time server 
> X.X.X.241 offset 1767511.749673 sec
> Feb 09 10:02:46       Feb 6 15:37:42 ntpdate[21870]: step time server 
> X.X.X.242 offset -6583241.180182 sec
> Feb 09 10:03:10       Jan 1 15:10:10 ntpdate[22814]: step time server 
> X.X.X.241 offset -524871911.919809 sec
> Feb 09 10:03:38       Jan22 03:13:59 ntpdate[23881]: step time server 
> X.X.X.241 offset 76808329.582176 sec
> Feb 09 10:04:15       Jan12 14:48:50 ntpdate[25071]: step time server 
> X.X.X.241 offset -822031692.768995 sec
> Feb 09 10:04:15       Jan30 20:57:02 ntpdate[25028]: step time server 
> X.X.X.241 offset 1258830934.958623 sec
> Feb 09 10:04:33       Jan17 08:11:40 ntpdate[25470]: step time server 
> X.X.X.241 offset 267894201.981337sec
> Feb 09 10:05:10       Feb 9 10:05:04 ntpdate[26345]: step time server 
> X.X.X.241 offset 1187205584.985695 sec

This is just the log for 1 domU - the other 3 look similar.

Looking for that phenomenon we have found several more instances, where
ntpdate reports a larger time step just after migration.

* Is this a known bug with xen-4.1?

* Is it fixed with newer versions of xen or doesn't buy us the upgrade
anything in regard with this issue?

* Or is running ntpdate from cron a very bad idea anyway, as it possibly
confuses cron too much?

Thanks in advance
Philipp
-- 
Philipp Hahn
Open Source Software Engineer

Univention GmbH
be open.
Mary-Somerville-Str. 1
D-28359 Bremen
Tel.: +49 421 22232-0
Fax : +49 421 22232-99
hahn@xxxxxxxxxxxxx

http://www.univention.de/
GeschÃftsfÃhrer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-02876

_______________________________________________
Xen-users mailing list
Xen-users@xxxxxxxxxxxxx
http://lists.xen.org/xen-users

 


Rackspace

Lists.xenproject.org is hosted with RackSpace, monitoring our
servers 24x7x365 and backed by RackSpace's Fanatical Support®.