WARNING - OLD ARCHIVES

This is an archived copy of the Xen.org mailing list, which we have preserved to ensure that existing links to archives are not broken. The live archive, which contains the latest emails, can be found at http://lists.xen.org/
   
 
 
Xen 
 
Home Products Support Community News
 
   
 

xen-devel

RE: [Xen-devel] Kernel printk timestamps and walltime drift

To: "Roger Cruz" <rcruz@xxxxxxxxxxxxxxxxxxxxxxxx>
Subject: RE: [Xen-devel] Kernel printk timestamps and walltime drift
From: "Dan Magenheimer" <dan.magenheimer@xxxxxxxxxx>
Date: Fri, 13 Jun 2008 15:21:41 -0600
Cc: xen-devel <xen-devel@xxxxxxxxxxxxxxxxxxx>
Delivery-date: Fri, 13 Jun 2008 14:25:27 -0700
Envelope-to: www-data@xxxxxxxxxxxxxxxxxx
In-reply-to: <40B551BEDC7945419A5897958AB3947CB354F6@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>
List-help: <mailto:xen-devel-request@lists.xensource.com?subject=help>
List-id: Xen developer discussion <xen-devel.lists.xensource.com>
List-post: <mailto:xen-devel@lists.xensource.com>
List-subscribe: <http://lists.xensource.com/cgi-bin/mailman/listinfo/xen-devel>, <mailto:xen-devel-request@lists.xensource.com?subject=subscribe>
List-unsubscribe: <http://lists.xensource.com/cgi-bin/mailman/listinfo/xen-devel>, <mailto:xen-devel-request@lists.xensource.com?subject=unsubscribe>
Organization: Oracle Corporation
Reply-to: "dan.magenheimer@xxxxxxxxxx" <dan.magenheimer@xxxxxxxxxx>
Sender: xen-devel-bounces@xxxxxxxxxxxxxxxxxxx
Thread-index: AcjM0Rhtsp0FqzEJQH+pTArFmFSulQACI1i0ACgZ8YAAApu8UAAC5XoQAACb16AAAgYDkA==
Hi Roger --

Sorry, I made a bad assumption... the solution I provided
works for hvm domains.  For pvm domains, the guest clock
will generally be determined by xen system time, and as
Keir said, if the underlying clock xen is using skews from
wallclock time, then xen system time will skew also.

I think the solution for this situation is to ensure
that /proc/sys/xen/independent_wallclock is set to 0
for each of your pvm domains and run ntpd on domain0.

Dan

> -----Original Message-----
> From: Roger Cruz [mailto:rcruz@xxxxxxxxxxxxxxxxxxxxxxxx]
> Sent: Friday, June 13, 2008 3:05 PM
> To: dan.magenheimer@xxxxxxxxxx; xen-devel
> Subject: RE: [Xen-devel] Kernel printk timestamps and walltime drift
> 
> 
> I've performed this test on two VMs, which it's my understanding are
> both PV, 32-bits and compiled from the 2.6.18.  I am using Citrix's
> XenEnterprise 4.1.0 software and you can see its VM's configuration
> below, giving the version and the PV bootloader.
> 
> I applied your changes to the grub line but I don't believe it is
> taking:
> 
> Prior to application:
> 
> p20deb:~# cat
> /sys/devices/system/clocksource/clocksource0/current_clocksource
> jiffies
> 
> after "clock=pit" added to my grub line
> 
> titleDebian GNU/Linux, kernel xenu-2.6.18.xs4.1.0.1168.6013
> root(hd0,0)
> kernel/boot/vmlinuz-xenu-2.6.18.xs4.1.0.1168.6013 root=/dev/xvda1 ro
> time clock=pit
> savedefault
> 
> p20deb:~# cat
> /sys/devices/system/clocksource/clocksource0/current_clocksource
> jiffies
> 
> I ran the test with clock=pit and it still drifted
> 
> [root@p20xen1 ~]# xe vm-list name-label=Debian\ Etch\ 4.0\ 
> \(1\) params=
> uuid ( RO)                          :
> bc40e67c-2f85-5be1-66ef-31ae3b2ab8b3
>                     name-label ( RW): Debian Etch 4.0 (1)
>               name-description ( RW):
>                   user-version ( RW): 1
>                  is-a-template ( RW): false
>              is-control-domain ( RO): false
>                    power-state ( RO): halted
>             memory-dynamic-max ( RW): 268435456
>             memory-dynamic-min ( RW): 268435456
>              memory-static-max ( RW): 268435456
>              memory-static-min ( RW): 16777216
>               suspend-VDI-uuid ( RO): <not in database>
>                   VCPUs-params (MRW):
>                      VCPUs-max ( RW): 1
>               VCPUs-at-startup ( RW): 1
>         actions-after-shutdown ( RW): Destroy
>           actions-after-reboot ( RW): Restart
>            actions-after-crash ( RW): Restart
>                  console-uuids (SRO):
> ecf5b121-6a0b-9a6d-fb98-62c608afaa24
>                       platform (MRW): nx: false; acpi: true; 
> apic: true;
> pae: true
>             allowed-operations (SRO): clone; start; start_on; export;
> destroy; make_into_template
>             current-operations (SRO):
>            allowed-VBD-devices (SRO): <expensive field>
>            allowed-VIF-devices (SRO): <expensive field>
>                 possible-hosts ( RO): <expensive field>
>                HVM-boot-policy ( RW):
>                HVM-boot-params (MRW):
>          HVM-shadow-multiplier ( RW): 1.000
>                      PV-kernel ( RW):
>                     PV-ramdisk ( RW):
>                        PV-args ( RW):
>                 PV-legacy-args ( RW):
>                  PV-bootloader ( RW): pygrub
>             PV-bootloader-args ( RW):
>            last-boot-CPU-flags ( RO):
>                    resident-on ( RO): <not in database>
>                       affinity ( RW):
> 1c29b960-78b2-46cc-a808-8cb454a3cece
>                   other-config (MRW): last_shutdown_time:
> 20080612T20:16:56Z; last_shutdown_action: Restart;
> last_shutdown_initiator: internal; last_shutdown_reason: rebooted;
> linux_template: true; mac_seed: e381c9e3-0346-09d6-d92e-815f5267bbf8
>                         dom-id ( RO): -1
>                recommendations ( RO): <restrictions><restriction
> field="memory-static-max" max="34359738368" /><restriction
> field="vcpus-max" max="8" /><restriction property="number-of-vbds"
> max="7" /><restriction property="number-of-vifs" max="7"
> /></restrictions>
>                  xenstore-data (MRW):
>                     start-time ( RO): <unknown time>
>                   install-time ( RO): <unknown time>
>                  memory-actual ( RO): <not in database>
>                   VCPUs-number ( RO): <not in database>
>              VCPUs-utilisation (MRO): <not in database>
>        vm-metrics-last-updated ( RO): <not in database>
>                     os-version (MRO): name: Debian 4.0; uname:
> 2.6.18.xs4.1.0.1168.6013; distro: debian; major: 4; minor: 0
>             PV-drivers-version (MRO): major: 4; minor: 1; micro: 0
>          PV-drivers-up-to-date ( RO): true
>                         memory (MRO):
>                          disks (MRO):
>                       networks (MRO):
>                          other (MRO):
>     guest-metrics-last-updated ( RO): 19700101T00:00:00Z
> 
> 
> -----Original Message-----
> From: Dan Magenheimer [mailto:dan.magenheimer@xxxxxxxxxx] 
> Sent: Friday, June 13, 2008 4:06 PM
> To: Roger Cruz; xen-devel
> Subject: RE: [Xen-devel] Kernel printk timestamps and walltime drift
> 
> Hi Roger --
> 
> I'm assuming this is an hvm 32-bit 2.6.18 domain and you are
> running on Xen 3.1.3 or newer?
> 
> If so, try setting clock=pit in your grub.conf file then
> after boot test that it "took" with:
> 
> cat /sys/devices/system/clocksource/clocksource0/current_clocksource
> 
> If it is pit, try your test again.
> 
> Note that there's a lot of work going on trying to fix
> hvm timer problems right now.  There are many many different
> cases because Linux has changed algorithms many times over
> the history of 2.6.
> 
> > -----Original Message-----
> > From: xen-devel-bounces@xxxxxxxxxxxxxxxxxxx
> > [mailto:xen-devel-bounces@xxxxxxxxxxxxxxxxxxx]On Behalf Of 
> Roger Cruz
> > Sent: Friday, June 13, 2008 12:49 PM
> > To: xen-devel
> > Subject: [Xen-devel] Kernel printk timestamps and walltime drift
> > 
> > 
> >  <<Roger Cruz.vcf>> Hello fellow developers,
> > 
> > I ran across a curious observation this week when trying to 
> > analyze the
> > Debian 4.0 VM kernel's printk timestamps against walltime.  
> > It looks as
> > if the kernel's timestamps are running slow.
> > 
> > On a reference debian 4.0 VM (created from Citrix templates), 
> > I ran the
> > following script after booting the OS with the "time" option 
> > in the grub
> > boot line. 
> > 
> > You can see that the kernel time in the brackets (host up time in
> > seconds) should have given us a difference of 3600 seconds 
> > when ran over
> > an hr period. I, however, got 3592.770286, a slip of  7+ 
> > seconds.  I've
> > ran a similar experiment and over the course of 12hrs, the kernel
> > timestamps lose 97 seconds!
> > 
> > So unless I'm misunderstanding the printk times, the 
> problem is either
> > with the way the Linux OS converts TSC cycles to seconds not 
> > being very
> > accurate  OR how the hypervisor feeds the VM-ified TSC counts to the
> > guest VM. 
> > 
> > Note that I'm sure the walltime was correct as I could monitor the
> > printed walltime against an atomic clock in another window 
> > and it always
> > matched (within the precision of my eyes moving back and forth, of
> > course).
> > 
> > Have any of you seen something similar or have an explanation?
> > 
> > grub line
> > title Debian GNU/Linux, kernel xenu-2.6.18.xs4.1.0.1168.6013
> > root (hd0,0)
> > kernel /boot/vmlinuz-xenu-2.6.18.xs4.1.0.1168.6013 
> root=/dev/xvda1 ro
> > time
> > savedefault
> > 
> > #/sbin/bash
> > i="0"
> > while [ $i -lt 10000 ]
> > do
> > date -u "+secs since 1970: %s, time:%c" > /dev/kmsg
> > sleep 60
> > i=$[$i + 1]
> > done
> > 
> > Reference Debian VM:
> > end time 91158.761414 - start time 87565.991128 = 3592.770286.  It
> > should have been 3600 seconds
> > Epoch time: 1213306731 - 1213303130 = 3601 close enough to 3600.
> > 
> > p20deb:~# ./timetest
> > [87565.991128] secs since 1970: 1213303130, time:Thu Jun 12 20:38:50
> > 2008
> > [87625.865258] secs since 1970: 1213303190, time:Thu Jun 12 20:39:50
> > 2008
> > [87685.745109] secs since 1970: 1213303250, time:Thu Jun 12 20:40:50
> > 2008
> > [87745.624397] secs since 1970: 1213303310, time:Thu Jun 12 20:41:50
> > 2008
> > [87805.504331] secs since 1970: 1213303370, time:Thu Jun 12 20:42:50
> > 2008
> > [87865.383613] secs since 1970: 1213303430, time:Thu Jun 12 20:43:50
> > 2008
> > [87925.263261] secs since 1970: 1213303490, time:Thu Jun 12 20:44:50
> > 2008
> > [87985.142794] secs since 1970: 1213303550, time:Thu Jun 12 20:45:50
> > 2008
> > [88045.022465] secs since 1970: 1213303610, time:Thu Jun 12 20:46:50
> > 2008
> > [88104.901993] secs since 1970: 1213303670, time:Thu Jun 12 20:47:50
> > 2008
> > [88164.781555] secs since 1970: 1213303730, time:Thu Jun 12 20:48:50
> > 2008
> > [88224.661193] secs since 1970: 1213303790, time:Thu Jun 12 20:49:50
> > 2008
> > [88284.540777] secs since 1970: 1213303850, time:Thu Jun 12 20:50:50
> > 2008
> > [88344.420448] secs since 1970: 1213303910, time:Thu Jun 12 20:51:50
> > 2008
> > [88404.299957] secs since 1970: 1213303970, time:Thu Jun 12 20:52:50
> > 2008
> > [88464.179722] secs since 1970: 1213304030, time:Thu Jun 12 20:53:50
> > 2008
> > [88524.059229] secs since 1970: 1213304090, time:Thu Jun 12 20:54:50
> > 2008
> > [88583.938799] secs since 1970: 1213304150, time:Thu Jun 12 20:55:50
> > 2008
> > [88643.818430] secs since 1970: 1213304210, time:Thu Jun 12 20:56:50
> > 2008
> > [88703.698102] secs since 1970: 1213304270, time:Thu Jun 12 20:57:50
> > 2008
> > [88763.577552] secs since 1970: 1213304330, time:Thu Jun 12 20:58:50
> > 2008
> > [88823.457180] secs since 1970: 1213304390, time:Thu Jun 12 20:59:50
> > 2008
> > [88883.336805] secs since 1970: 1213304450, time:Thu Jun 12 21:00:50
> > 2008
> > [88943.216354] secs since 1970: 1213304510, time:Thu Jun 12 21:01:50
> > 2008
> > [89003.095940] secs since 1970: 1213304570, time:Thu Jun 12 21:02:50
> > 2008
> > [89062.975550] secs since 1970: 1213304630, time:Thu Jun 12 21:03:50
> > 2008
> > [89122.855184] secs since 1970: 1213304690, time:Thu Jun 12 21:04:50
> > 2008
> > [89182.734796] secs since 1970: 1213304750, time:Thu Jun 12 21:05:50
> > 2008
> > [89242.614451] secs since 1970: 1213304810, time:Thu Jun 12 21:06:50
> > 2008
> > [89302.494083] secs since 1970: 1213304870, time:Thu Jun 12 21:07:50
> > 2008
> > [89362.373748] secs since 1970: 1213304930, time:Thu Jun 12 21:08:50
> > 2008
> > [89422.253149] secs since 1970: 1213304990, time:Thu Jun 12 21:09:50
> > 2008
> > [89482.132723] secs since 1970: 1213305050, time:Thu Jun 12 21:10:50
> > 2008
> > [89542.012413] secs since 1970: 1213305110, time:Thu Jun 12 21:11:50
> > 2008
> > [89601.892321] secs since 1970: 1213305171, time:Thu Jun 12 21:12:51
> > 2008
> > [89661.771534] secs since 1970: 1213305231, time:Thu Jun 12 21:13:51
> > 2008
> > [89721.651093] secs since 1970: 1213305291, time:Thu Jun 12 21:14:51
> > 2008
> > [89781.530707] secs since 1970: 1213305351, time:Thu Jun 12 21:15:51
> > 2008
> > [89841.410355] secs since 1970: 1213305411, time:Thu Jun 12 21:16:51
> > 2008
> > [89901.289916] secs since 1970: 1213305471, time:Thu Jun 12 21:17:51
> > 2008
> > [89961.169452] secs since 1970: 1213305531, time:Thu Jun 12 21:18:51
> > 2008
> > [90021.049277] secs since 1970: 1213305591, time:Thu Jun 12 21:19:51
> > 2008
> > [90080.928731] secs since 1970: 1213305651, time:Thu Jun 12 21:20:51
> > 2008
> > [90140.808362] secs since 1970: 1213305711, time:Thu Jun 12 21:21:51
> > 2008
> > [90200.687903] secs since 1970: 1213305771, time:Thu Jun 12 21:22:51
> > 2008
> > [90260.567678] secs since 1970: 1213305831, time:Thu Jun 12 21:23:51
> > 2008
> > [90320.447062] secs since 1970: 1213305891, time:Thu Jun 12 21:24:51
> > 2008
> > [90380.326679] secs since 1970: 1213305951, time:Thu Jun 12 21:25:51
> > 2008
> > [90440.206252] secs since 1970: 1213306011, time:Thu Jun 12 21:26:51
> > 2008
> > [90500.085917] secs since 1970: 1213306071, time:Thu Jun 12 21:27:51
> > 2008
> > [90559.965484] secs since 1970: 1213306131, time:Thu Jun 12 21:28:51
> > 2008
> > [90619.845052] secs since 1970: 1213306191, time:Thu Jun 12 21:29:51
> > 2008
> > [90679.724900] secs since 1970: 1213306251, time:Thu Jun 12 21:30:51
> > 2008
> > [90739.604366] secs since 1970: 1213306311, time:Thu Jun 12 21:31:51
> > 2008
> > [90799.483803] secs since 1970: 1213306371, time:Thu Jun 12 21:32:51
> > 2008
> > [90859.363649] secs since 1970: 1213306431, time:Thu Jun 12 21:33:51
> > 2008
> > [90919.243037] secs since 1970: 1213306491, time:Thu Jun 12 21:34:51
> > 2008
> > [90979.122646] secs since 1970: 1213306551, time:Thu Jun 12 21:35:51
> > 2008
> > [91039.002174] secs since 1970: 1213306611, time:Thu Jun 12 21:36:51
> > 2008
> > [91098.881855] secs since 1970: 1213306671, time:Thu Jun 12 21:37:51
> > 2008
> > [91158.761414] secs since 1970: 1213306731, time:Thu Jun 12 21:38:51
> > 2008
> > 
> > 
> > Roger Cruz
> > Principal SW Engineer
> > Marathon Technologies Corp.
> > 978-489-1153
> > 
> > 
> > 
> 
>


_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxxxxxxxx
http://lists.xensource.com/xen-devel