[Xen-devel] Kernel printk timestamps and walltime drift

["Roger Cruz" <rcruz@xxxxxxxxxxxxxxxxxxxxxxxx>]

 <<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

Attachment: Roger Cruz.vcf
Description: Roger Cruz.vcf

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