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

["Roger Cruz" <rcruz@xxxxxxxxxxxxxxxxxxxxxxxx>]

Hi Keir,

Thanks for taking the time to answer my question.

I do not know how the kernel times are getting computed exactly.  This
is an area of Linux which I'm not very familiar with.  

Prior to my test on the reference debian VM, I performed exactly the
same test on a Linux VM we build based on the Citrix-provided Linux
2.6.18 sources (my understanding is that these are the sources dom0 is
using, correct me if wrong) and saw the same drift.  That's why I
decided to do a test on a reference VM to make sure it was not caused by
our own VM.

When I looked at the Linux 2.6.18 sources to try to track down how these
times are computed, I found the following for an x86, 32-bit platform...


MtcAbsDbgPrint -> vprintk -> printk_clock  -> sched_clock -> rdtscll

MtcAbsTimeGetTimestampGmt -> current_kernel_time -> return timespec
variable "xtime"
 
"xtime" is in UTC and I believe it's updated as a result of the timer
interrupt in the sequence below

do_timer_interrupt_hook-> do_timer-> update_times  ->update_wall_time ->
updates "xtime"

Note that I'm not 100% of these call sequences since they were derived
by looking at the sources and not tracing it with any debugger.  This is
how I came to conclude that the kernel timestamps (generated as a result
of us calling vprintk) are derived from the RDTSC instruction.  It is my
understanding that the TSC values are derived by the hypervisor from the
actual CPU register and some computed offset.  I have yet to examine
this code myself.

The walltime appears to be generated from periodic timer ticks that
update "xtime".  These values have always been correct.  Only the ones
that get generated with the vprintk appear to slip when compared to this
wall time.

Roger

-----Original Message-----
From: Keir Fraser [mailto:keir.fraser@xxxxxxxxxxxxx] 
Sent: Friday, June 13, 2008 3:48 PM
To: Roger Cruz; xen-devel
Subject: Re: [Xen-devel] Kernel printk timestamps and walltime drift

On 13/6/08 19:49, "Roger Cruz" <rcruz@xxxxxxxxxxxxxxxxxxxxxxxx> wrote:

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

Do you know how the Debian kernel is computing its kernel-log
timestamps?

One possibility here is that Xen system time is running at a slightly
different rate from wallclock (because the platform timer (PIT, HPET,
etc)
is not running at exactly its stated frequency) and ntp running in dom0
only
keeps Xen's wallclock reference in sync -- it does not affect Xen's
system
time. If the Debian kernel were perhaps based on jiffies rather than
xtime,
I think that might explain the drift.

This hypothesis would require Xen's system time to be drifting at around
2000ppm, which is not great. I would expect a platform timer to be
within a
few 100ppm of its advertised frequency, really (and with jitter of much
less
than 10ppm).

 -- Keir



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