repeatable time jump

repeatable time jump

[David Becker]

I got the time jump to reproduce.  Shutting down xenU shifts system time on
xen0 by over an hour.  xen0 hwclock stays steady:

        xen0# date
        Tue Sep 28 10:45:13 EDT 2004
        xen0# xm list
        Name              Id  Mem(MB)  CPU  State  Time(s)  Console
        Domain-0           0       34    0  r----    120.1        
        xen0# xm create  memory=800  name=athos14
        builder=linux kernel=/boot/vmlinuz-2.6.8.1-xenU ipaddr=172.16.11.24
        ip=172.16.11.24 gateway= netmask=255.255.255.0 hostname=athos14
        interface=eth0 dhcp=off disk=phy:/dev/xenvg/athos14.root,hda1,w cpu=-1
        disk=phy:/dev/xenvg/athos14.swap,hda2,w root=/dev/hda1
        Using config file "/etc/xen/xmdefconfig".
        Started domain athos14, console on port 9605
        xen0# date
        Tue Sep 28 10:47:16 EDT 2004
        xen0# xm shutdown athos14
        xen0# xm list
        Name              Id  Mem(MB)  CPU  State  Time(s)  Console
        Domain-0           0       34    0  r----    129.2        
        xen0# date
        Tue Sep 28 11:59:01 EDT 2004
        xen0# hwclock
        Tue Sep 28 10:48:02 2004  -0.000000 seconds


The xen0 shift happens when xen0 clock is correct.  Further starting/stopping
of domains after the xen0 clock is off has more effect on xen0's system time.

xenU does not run ntp or hwclock.  If xenU is started after xen0's
system time is off, xenU has the right time.  I assume xenU is synced to
the hwclock time.

This is with today's pull of 2.6.8.1. I'm using 2.6 for all domains.



-------------------------------------------------------
This SF.Net email is sponsored by: YOU BE THE JUDGE. Be one of 170
Project Admins to receive an Apple iPod Mini FREE for your judgement on
who ports your project to Linux PPC the best. Sponsored by IBM.
Deadline: Sept. 24. Go here: http://sf.net/ppc_contest.php

Re: repeatable time jump typo

[David Becker]

THis is a typo

" of domains after the xen0 clock is off has more effect on xen0's system time.

Should be:  has *NO MORE* effect ....



-------------------------------------------------------
This SF.Net email is sponsored by: YOU BE THE JUDGE. Be one of 170
Project Admins to receive an Apple iPod Mini FREE for your judgement on
who ports your project to Linux PPC the best. Sponsored by IBM.
Deadline: Sept. 24. Go here: http://sf.net/ppc_contest.php

Re: repeatable time jump

[Ian Pratt]

> 
> I got the time jump to reproduce.  Shutting down xenU shifts system time on
> xen0 by over an hour.  xen0 hwclock stays steady:

Weird. I can't reproduce.

Are your xenU domains being started with access to any IO devices
or such like that might be giving them Privileged domain status?

The only way that I can see that xen's system time can be changed
is via the DOM0_SETTIME dom0 op.

You might want to add a printk in common/dom0_ops.c to see if
it's getting called unexpectedly on your system. If you print
current->domain you'll be able to see which domain is calling it.

Ian


-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[David Becker]

" Weird. I can't reproduce.

I can reproduce it on that host, but most hosts don't have the problem.

" The only way that I can see that xen's system time can be changed
" is via the DOM0_SETTIME dom0 op.

Its the system time in domain 0 that is changing.   The time dom0 gets
by reading hwclock is ok.  Would hwclock time be what DOM0_SETTIME sets?



-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[Ian Pratt]

> " The only way that I can see that xen's system time can be changed
> " is via the DOM0_SETTIME dom0 op.
> 
> Its the system time in domain 0 that is changing.   The time dom0 gets
> by reading hwclock is ok.  Would hwclock time be what DOM0_SETTIME sets?
> 

No -- SETTIME effectively sets the dom0 system time, that Xen
also exports to other domains.

> I can reproduce it on that host, but most hosts don't have the
> problem.

Are you sure its only shutting down the xenU domain that causes
problems, rather than arbitrary activity in either domain?
Are the domains on the same CPU?

None of this makes much sense. It's certainly worth instrumenting
SETTIME.

Ian



-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[David Becker]

" None of this makes much sense. It's certainly worth instrumenting
" SETTIME.

I added a printk in do_dom0ops.   I saw the same 70 minute jump ahead in
the system clock in domain 0 when I shutdown domain 1.   I did not get any
new SETTIME printk from xm dmesg.  The only settime calls occured when
dom0 booted and ntp started.  


The client domains do not have CONFIG_XEN_PRIVILEGED_GUEST set and
nothing unusual is running on dom0.  I start up xen0, then xenU, then
kill xenU and the xen0 date immediately jumps.

" No -- SETTIME effectively sets the dom0 system time, that Xen
" also exports to other domains.

So does that mean from the dom0 perspective that system time and hwclock
time should always be identical?

What hwclock says on dom0 did not change. Just what date says changed.



-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[Ian Pratt]

> 
> " None of this makes much sense. It's certainly worth instrumenting
> " SETTIME.
> 
> I added a printk in do_dom0ops.   I saw the same 70 minute jump ahead in
> the system clock in domain 0 when I shutdown domain 1.   I did not get any
> new SETTIME printk from xm dmesg.  The only settime calls occured when
> dom0 booted and ntp started.  

That's what I'd expect.
> 
> " No -- SETTIME effectively sets the dom0 system time, that Xen
> " also exports to other domains.
> 
> So does that mean from the dom0 perspective that system time and hwclock
> time should always be identical?

Close, but not identical. The hwclock time will be written back
periodically.

> What hwclock says on dom0 did not change. Just what date says changed.

Bizarre. Anything unusual about this machine compared to the
others that are OK? 

Ian


-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[David Becker]

" Close, but not identical. The hwclock time will be written back
" periodically.

How periodically?

" Bizarre. Anything unusual about this machine compared to the
" others that are OK? 

As of now I am getting repeatable time jumps on 4 of 16, plus another 3 that
jump occasionally but not always.

The machines are all IBMs.  IBM x330, x335 and HS20 blades.
The repeatable hosts have 1GB of mem.  THe hosts with only 512 or
256MB ram don't seem to be affected. 
How could memory size matter?

They are running 2.6 in xen0 and xenU, and use the latest sarge
distribution from Debian.



-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[Ian Pratt]

> 
> " Close, but not identical. The hwclock time will be written back
> " periodically.
> 
> How periodically?

Once a minute.

> " Bizarre. Anything unusual about this machine compared to the
> " others that are OK? 
> 
> As of now I am getting repeatable time jumps on 4 of 16, plus another 3 that
> jump occasionally but not always.

Is the time jump you see on all machines constant? Could you run
"while true; date; sleep 1; done" so that we can see what the
exact warp is. [it would be very interesting, for example, if it
always turned out to be 71 minutes 35 seconds, which is 2^32
usec.]

Is it definitely the act of shutting down the domU that causes
the problem? What if you just destroy the domain?

> The machines are all IBMs.  IBM x330, x335 and HS20 blades.
> The repeatable hosts have 1GB of mem.  THe hosts with only 512 or
> 256MB ram don't seem to be affected. 
> How could memory size matter?

It seems unlikely that memory size is involved, but the whole
thing is weird...

Ian



-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[David Becker]

" always turned out to be 71 minutes 35 seconds, which is 2^32
" usec.]

Huh, thats right. I'm seeing a 4294 second jump on the hosts that jump an hour.
It happens with both xm shutdown and xm destroy.

# while true; do date +%s.%N; done
...
1096481915.880540000
1096481915.884033000
1096481915.887550000
1096486208.893708000
1096486208.897248000
...


This experiment also showed that once the date jumps, time stops advancing
in xen0.  So checking the date after the fact would show different errors and
after 71 minutes the error would be gone. 

# while true; do date '+%c %s'; sleep 1; done
Wed Sep 29 15:30:08 2004 1096486208
Wed Sep 29 15:30:08 2004 1096486208
Wed Sep 29 15:30:08 2004 1096486208
Wed Sep 29 15:30:08 2004 1096486208
Wed Sep 29 15:30:08 2004 1096486208
Wed Sep 29 15:30:08 2004 1096486208



-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[Ian Pratt]

> 
> " always turned out to be 71 minutes 35 seconds, which is 2^32
> " usec.]
> 
> Huh, thats right. I'm seeing a 4294 second jump on the hosts that jump an hour.
> It happens with both xm shutdown and xm destroy.

OK, this bug is now officially annoying me.

I've checked in a tiny fix I spotted in a code review, but I
doubt it will solve the problem. 

I think the easiest way to solve it since we can't reproduce
locally is to apply tracing.

David: please can you apply the following patch to
linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c and see what
comes out when you run your test. It's also interesting to see
what output comes out after the time skip whenever you run date. 

Thanks,
Ian


--- /usr/groups/xeno/BK/xeno.bk/linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c    2004-09-30 21:14:58.000000000 +0100
+++ linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c        2004-09-30 21:28:09.000000000 +0100
@@ -114,28 +114,34 @@
 
 #define NS_PER_TICK (1000000000ULL/HZ)
 
-#define HANDLE_USEC_UNDERFLOW(_tv) do {                \
+#define HANDLE_USEC_UNDERFLOW(_tv) do {        int i=0;        \
        while ((_tv).tv_usec < 0) {             \
                (_tv).tv_usec += USEC_PER_SEC;  \
                (_tv).tv_sec--;                 \
-       }                                       \
+       }if(i>100)printk(KERN_ALERT"USEC_UNDER %d\n",i);        \
 } while (0)
-#define HANDLE_USEC_OVERFLOW(_tv) do {         \
+#define HANDLE_USEC_OVERFLOW(_tv) do { int i=0;        \
        while ((_tv).tv_usec >= USEC_PER_SEC) { \
                (_tv).tv_usec -= USEC_PER_SEC;  \
-               (_tv).tv_sec++;                 \
-       }                                       \
+               (_tv).tv_sec++; i++;            \
+       }if(i>100)printk(KERN_ALERT"USEC_OVER %d\n",i); \
 } while (0)
 static inline void __normalize_time(time_t *sec, s64 *nsec)
 {
+int i=0,j=0;
        while (*nsec >= NSEC_PER_SEC) {
                (*nsec) -= NSEC_PER_SEC;
                (*sec)++;
+               i++;
        }
        while (*nsec < 0) {
                (*nsec) += NSEC_PER_SEC;
                (*sec)--;
+               j++;
        }
+
+if( i>100 || j>100 ) printk(KERN_ALERT"normalize time %d %d\n",i,j);
+
 }
 
 /* Does this guest OS track Xen time, or set its wall clock independently? */
@@ -155,6 +161,8 @@
  */
 static void __get_time_values_from_xen(void)
 {
+long last = shadow_tv.tv_sec;
+
        shared_info_t *s = HYPERVISOR_shared_info;
 
        do {
@@ -169,6 +177,7 @@
        while (shadow_time_version != s->time_version1);
 
        cur_timer->mark_offset();
+if( shadow_tv.tv_sec-last > 600 ) printk(KERN_ALERT"**** __get_time_values_from_xen(void) JUPMED!\n");
 }
 
 #define TIME_VALUES_UP_TO_DATE \
@@ -241,6 +250,7 @@
            ((sec == last_seen_tv.tv_sec) && (usec < last_seen_tv.tv_usec))) {
                sec = last_seen_tv.tv_sec;
                usec = last_seen_tv.tv_usec;
+printk(KERN_ALERT"Clamp time %ld %ld\n",sec,last_seen_tv.tv_sec); 
        } else {
                last_seen_tv.tv_sec = sec;
                last_seen_tv.tv_usec = usec;





-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[David Becker]

" linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c and see what
" comes out when you run your test. It's also interesting to see
" what output comes out after the time skip whenever you run date. 

OK, I pulled and patched.   I ran date in a loop as xenU was shutdown
and time jumped 4293 secs from 1096637912.846396000 to 1096642205.961018000
ntpd was running in xen0.

The console is getting continuous Clamp messages.  The xen0 Syslog says:

Oct  1 09:34:44 rack043-xen kernel: device eth0 entered promiscuous mode
Oct  1 09:34:44 rack043-xen kernel: xen-br0: port 1(eth0) entering learning stat e
Oct  1 09:34:44 rack043-xen kernel: xen-br0: topology change detected, propagati ng
Oct  1 09:34:44 rack043-xen kernel: xen-br0: port 1(eth0) entering forwarding st ate
Oct  1 09:34:44 rack043-xen kernel: Clamp time 1096637684 1096637684
Oct  1 09:36:20 rack043-xen kernel: device vif1.0 entered promiscuous mode
Oct  1 09:36:21 rack043-xen kernel: xen-br0: port 2(vif1.0) entering learning st ate
Oct  1 09:36:21 rack043-xen kernel: xen-br0: topology change detected, propagati ng
Oct  1 09:36:21 rack043-xen kernel: xen-br0: port 2(vif1.0) entering forwarding state
Oct  1 09:37:10 rack043-xen ntpd[838]: synchronized to LOCAL(0), stratum 13
Oct  1 09:37:10 rack043-xen ntpd[838]: kernel time sync disabled 0041
Oct  1 09:38:01 rack043-xen /USR/SBIN/CRON[955]: (mail) CMD (  if [ -x /usr/lib/ exim/exim3 -a -f /etc/exim/exim.conf ]; then /usr/lib/exim/exim3 -q ; fi)
Oct  1 09:38:16 rack043-xen ntpd[838]: synchronized to 172.16.4.1, stratum 3
Oct  1 09:38:32 rack043-xen kernel: device vif1.0 left promiscuous mode
Oct  1 09:38:32 rack043-xen kernel: xen-br0: port 2(vif1.0) entering disabled st
ate
Oct  1 10:50:05 rack043-xen kernel: xen-br0: port 2(vif1.0) entering disabled st
ate
Oct  1 10:50:06 rack043-xen kernel: Clamp time 1096642206 1096642206
Oct  1 10:50:06 rack043-xen last message repeated 529 times
Oct  1 10:50:06 rack043-xen kernel: Clamp 206
Oct  1 10:50:06 rack043-xen kernel: Clamp time 1096642206 1096642206
Oct  1 10:50:06 rack043-xen last message repeated 112 times
Oct  1 10:50:06 rack043-xen kernel: Clamp time 109664220206
Oct  1 10:50:06 rack043-xen kernel: Clamp time 1096642206 1096642206
Oct  1 10:50:06 rack043-xen last message repeated 112 times
Oct  1 10:50:06 rack043-xen kernel: Clamp time 109664220206
Oct  1 10:50:06 rack043-xen kernel: Clamp time 1096642206 1096642206
Oct  1 10:50:06 rack043-xen last message repeated 112 times
Oct  1 10:50:06 rack043-xen kernel: Clamp time 109664220206
Oct  1 10:50:06 rack043-xen kernel: Clamp time 1096642206 1096642206
Oct  1 10:50:06 rack043-xen last message repeated 112 times
Oct  1 10:50:06 rack043-xen kernel: Clamp time 109664220206
Oct  1 10:50:06 rack043-xen kernel: Clamp time 1096642206 1096642206
Oct  1 10:50:06 rack043-xen last message repeated 112 times
Oct  1 10:50:06 rack043-xen kernel: Clamp time 109664220206
Oct  1 10:50:06 rack043-xen kernel: Clamp time 1096642206 1096642206



If I try xm dmesg at this point, xm hangs.  Looks like it is waiting for
xend to say sometime. After ctrl-C xm says:

rack043-xen:~# xm dmesg
Traceback (most recent call last):
  File "/usr/sbin/xm", line 6, in ?
    main.main(sys.argv)
  File
"/usr/research/playground/becker/xen/obj-unstable/xeno-unstable.bk/install/lib/python/xen/xm/main.py",
line 786, in main
    xm.main(args)
  File
"/usr/research/playground/becker/xen/obj-unstable/xeno-unstable.bk/install/lib/python/xen/xm/main.py",
line 105, in main
    self.main_call(args)
  File
"/usr/research/playground/becker/xen/obj-unstable/xeno-unstable.bk/install/lib/python/xen/xm/main.py",
line 123, in main_call
    p.main(args[1:])
  File
"/usr/research/playground/becker/xen/obj-unstable/xeno-unstable.bk/install/lib/python/xen/xm/main.py",
line 684, in main
    print server.xend_node_dmesg()
  File
"/usr/research/playground/becker/xen/obj-unstable/xeno-unstable.bk/install/lib/python/xen/xend/XendClient.py",
line 183, in xend_node_dmesg
    return self.xendGet(self.nodeurl('dmesg'))
  File
"/usr/research/playground/becker/xen/obj-unstable/xeno-unstable.bk/install/lib/python/xen/xend/XendClient.py",
line 145, in xendGet
    return self.client.xendGet(url, args)
  File
"/usr/research/playground/becker/xen/obj-unstable/xeno-unstable.bk/install/lib/python/xen/xend/XendProtocol.py",
line 68, in xendGet
    return self.xendRequest(url, "GET", args)
  File
"/usr/research/playground/becker/xen/obj-unstable/xeno-unstable.bk/install/lib/python/xen/xend/XendProtocol.py",
line 143, in xendRequest
    resp = conn.getresponse()
  File "/usr/lib/python2.3/httplib.py", line 778, in getresponse
    response.begin()
  File "/usr/lib/python2.3/httplib.py", line 273, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python2.3/httplib.py", line 231, in _read_status
    line = self.fp.readline()
  File "/usr/lib/python2.3/socket.py", line 323, in readline
    data = recv(1)
KeyboardInterrupt



-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[Ian Pratt]

> 
> " linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c and see what
> " comes out when you run your test. It's also interesting to see
> " what output comes out after the time skip whenever you run date. 
> 
> OK, I pulled and patched.   I ran date in a loop as xenU was shutdown
> and time jumped 4293 secs from 1096637912.846396000 to 1096642205.961018000
> ntpd was running in xen0.

David, Peri:

I suspect you guys are seeing manifestations of the same
bug. It's odd that you only see it on some machines, but it might
be due to the relative error between the RTC and CPU clocks or
such like.

Please can you try the new patch which may give a little more
information.

Thanks,
Ian


--- /usr/groups/xeno/BK/xeno.bk/linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c    2004-10-01 16:01:03.000000000 +0100
+++ arch/xen/i386/kernel/time.c 2004-10-01 16:10:06.000000000 +0100
@@ -114,28 +114,34 @@
 
 #define NS_PER_TICK (1000000000ULL/HZ)
 
-#define HANDLE_USEC_UNDERFLOW(_tv) do {                \
+#define HANDLE_USEC_UNDERFLOW(_tv) do {        int i=0;        \
        while ((_tv).tv_usec < 0) {             \
                (_tv).tv_usec += USEC_PER_SEC;  \
                (_tv).tv_sec--;                 \
-       }                                       \
+       }if(i>100)printk(KERN_ALERT"USEC_UNDER %d\n",i);        \
 } while (0)
-#define HANDLE_USEC_OVERFLOW(_tv) do {         \
+#define HANDLE_USEC_OVERFLOW(_tv) do { int i=0;        \
        while ((_tv).tv_usec >= USEC_PER_SEC) { \
                (_tv).tv_usec -= USEC_PER_SEC;  \
-               (_tv).tv_sec++;                 \
-       }                                       \
+               (_tv).tv_sec++; i++;            \
+       }if(i>100)printk(KERN_ALERT"USEC_OVER %d\n",i); \
 } while (0)
 static inline void __normalize_time(time_t *sec, s64 *nsec)
 {
+int i=0,j=0;
        while (*nsec >= NSEC_PER_SEC) {
                (*nsec) -= NSEC_PER_SEC;
                (*sec)++;
+               i++;
        }
        while (*nsec < 0) {
                (*nsec) += NSEC_PER_SEC;
                (*sec)--;
+               j++;
        }
+
+if( i>100 || j>100 ) printk(KERN_ALERT"normalize time %d %d\n",i,j);
+
 }
 
 /* Does this guest OS track Xen time, or set its wall clock independently? */
@@ -155,6 +161,8 @@
  */
 static void __get_time_values_from_xen(void)
 {
+long last = shadow_tv.tv_sec;
+
        shared_info_t *s = HYPERVISOR_shared_info;
 
        do {
@@ -169,6 +177,7 @@
        while (shadow_time_version != s->time_version1);
 
        cur_timer->mark_offset();
+if( shadow_tv.tv_sec-last > 600 ) printk(KERN_ALERT"**** __get_time_values_from_xen(void) JUPMED!\n");
 }
 
 #define TIME_VALUES_UP_TO_DATE \
@@ -227,18 +236,26 @@
                        write_seqlock_irqsave(&xtime_lock, flags);
                        __get_time_values_from_xen();
                        write_sequnlock_irqrestore(&xtime_lock, flags);
+printk(KERN_ALERT"GTOD Try again %ld %lld\n", shadow_tv.tv_sec,
+       shadow_system_time);
                        continue;
                }
        } while (read_seqretry(&xtime_lock, seq));
 
+{
+int z=0;
        while (usec >= USEC_PER_SEC) {
                usec -= USEC_PER_SEC;
                sec++;
+               z++;
        }
+if(z>100) printk(KERN_ALERT"GTOD JUMP %d\n",z);
+}
 
        /* Ensure that time-of-day is monotonically increasing. */
        if ((sec < last_seen_tv.tv_sec) ||
            ((sec == last_seen_tv.tv_sec) && (usec < last_seen_tv.tv_usec))) {
+printk(KERN_ALERT"Clamp time %ld %ld\n",sec,last_seen_tv.tv_sec); 
                sec = last_seen_tv.tv_sec;
                usec = last_seen_tv.tv_usec;
        } else {
@@ -364,6 +381,7 @@
                                        struct pt_regs *regs)
 {
        s64 delta;
+       unsigned int ticks = 0;
        long sec_diff;
 
        __get_time_values_from_xen();
@@ -378,9 +396,14 @@
 
        /* Process elapsed jiffies since last call. */
        while (delta >= NS_PER_TICK) {
+               ticks++;
                delta -= NS_PER_TICK;
                processed_system_time += NS_PER_TICK;
-               do_timer_interrupt_hook(regs);
+       }
+
+       if (ticks != 0) {
+               jiffies_64 += ticks - 1;
+               do_timer_interrupt_hook(regs); /* implicit 'jiffies_64++' */
        }
 
        /*


-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[David Becker]

Here is the syslog entries from xen0 running the last patch.
First I set the date with ntpdate, then I created and shutdown xenU.
There is a set of Clamp messages farther down as the next second ticks by.

Oct  1 12:45:22 rack043-xen ntpdate[1041]: step time server 172.16.4.1 offset 17.868210 sec
Oct  1 12:45:25 rack043-xen kernel: GTOD Try again 1096649125 860080000000
Oct  1 12:45:25 rack043-xen kernel: GTOD Try again 1096649125 860130000000
Oct  1 12:46:15 rack043-xen kernel: GTOD Try again 1096649175 910420000000
Oct  1 12:46:16 rack043-xen kernel: device vif2.0 entered promiscuous mode
Oct  1 12:46:16 rack043-xen kernel: GTOD Try again 1096649176 911530000000
Oct  1 12:46:17 rack043-xen kernel: xen-br0: port 2(vif2.0) entering learning state
Oct  1 12:46:17 rack043-xen kernel: xen-br0: topology change detected, propagating
Oct  1 12:46:17 rack043-xen kernel: xen-br0: port 2(vif2.0) entering forwarding state
Oct  1 12:46:47 rack043-xen kernel: GTOD Try again 1096649207 942060000000
Oct  1 12:47:20 rack043-xen kernel: device vif2.0 left promiscuous mode
Oct  1 12:47:20 rack043-xen kernel: xen-br0: port 2(vif2.0) entering disabled state
Oct  1 12:47:20 rack043-xen kernel: xen-br0: port 2(vif2.0) entering disabled state
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 294 times
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096653534 1096653534
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 310 times
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096653534 1096653534
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 210 times
Oct  1 13:58:54 rack043-xen kernel: >GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 59 times
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096653534 1096653534
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 50 times
Oct  1 13:58:54 rack043-xen kernel: GTOD Try again 1096649243 977970000000
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 110 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 54 times
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096653534 1096653534
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 168 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 206 times
Oct  1 13:58:54 rack043-xen kernel: GTOD Try again 1096649243 978020000000
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 16 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 203 times
Oct  1 13:58:54 rack043-xen kernel: GTOD Try again 1096649243 978070000000
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 19 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 219 times
Oct  1 13:58:54 rack043-xen kernel: GTOD Try again 1096649243 978120000000
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 3 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GTJUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 154 times
Oct  1 13:58:54 rack043-xen kernel: GTOD Try again 1096649243 978520000000
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 68 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 169 times
Oct  1 13:58:54 rack043-xen kernel: GTOD Try again 1096649243 978570000000
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 53 times
Oct  1 13:58:54 rack043-xen kernel: GT294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 226 times
Oct  1 13:58:54 rack043-xen kernel: GT>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 225 times
Oct  1 13:58:54 rack043-xen kernel: GTOD JUM>GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 98 times
Oct  1 13:58:54 rack043-xen kernel: GTOD Try again 1096649244 978620000000
Oct  1 13:58:54 rack043-xen kernel: GTOD JUMP 4294
Oct  1 13:58:54 rack043-xen last message repeated 124 times
Oct  1 13:58:54 rack043-xen kernel: GT534
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096649240 1096653534
Oct  1 13:58:54 rack043-xen last message repeated 112 times
Oct  1 13:58:54 rack043-xen kernel: Clamp time 109664924534
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096649240 1096653534
Oct  1 13:58:54 rack043-xen last message repeated 112 times
Oct  1 13:58:54 rack043-xen kernel: Clamp time 109664924>Clamp time 1096649240 1096653534
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096649240 1096653534
Oct  1 13:58:54 rack043-xen last message repeated 111 times
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096649240 1096>Clamp time 1096649240 1096653534
Oct  1 13:58:54 rack043-xen kernel: Clamp time 1096649240 1096653534
Oct  1 13:58:54 rack043-xen last message repeated 111 times


-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[Adam Heath]

yOn Fri, 1 Oct 2004, Ian Pratt wrote:

> --- /usr/groups/xeno/BK/xeno.bk/linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c    2004-10-01 16:01:03.000000000 +0100
> +++ arch/xen/i386/kernel/time.c 2004-10-01 16:10:06.000000000 +0100
> @@ -114,28 +114,34 @@
>
>  #define NS_PER_TICK (1000000000ULL/HZ)
>
> -#define HANDLE_USEC_UNDERFLOW(_tv) do {                \
> +#define HANDLE_USEC_UNDERFLOW(_tv) do {        int i=0;        \
>         while ((_tv).tv_usec < 0) {             \
>                 (_tv).tv_usec += USEC_PER_SEC;  \
>                 (_tv).tv_sec--;                 \
> -       }                                       \
> +       }if(i>100)printk(KERN_ALERT"USEC_UNDER %d\n",i);        \
>  } while (0)

How can i>100?  i is never incremented.


-------------------------------------------------------
This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
Use IT products in your business? Tell us what you think of them. Give us
Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
http://productguide.itmanagersjournal.com/guidepromo.tmpl

Re: repeatable time jump

[Peri Hankey]

[-- Attachment #1: Type: text/plain, Size: 6053 bytes --]

Ian

I think your patch was against an intermediate state - it doesn't patch 
cleanly against xen-unstable-src-20041001 (yesterday's snapshot) - I 
tried the patchwork jigsaw business but was getting confused. The 
version I have corresponds to

    21 hours iap10 1.1349.1.4 
<http://xen.bkbits.net:8080/xeno-unstable.bk/cset@1.1349.1.4?nav=index.html%7CChangeSet@-4d> 
Tiny time fix

in the BK changeset listing.

I made a minimal patch to time.c to ensure that it doesn't return 
successive time values that are identical, which is what was causing the 
rpm crashes that have been plaguing me, and attach it as a stopgap if 
anyone else (Flavio?) is having touble with that.

With this patch, your test program shows that the problem has occured by 
producing reams of 'gtod 1' messages, but at least rpm, yum, poldek, 
urpmi etc remain usable.

This merely a stopgap, does nothing to advance progress towards a 
rational understanding of time in the xenU domain, and may for all I 
know have other damaging effects.

Thanks
Peri





Ian Pratt wrote:

>>" linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c and see what
>>" comes out when you run your test. It's also interesting to see
>>" what output comes out after the time skip whenever you run date. 
>>
>>OK, I pulled and patched.   I ran date in a loop as xenU was shutdown
>>and time jumped 4293 secs from 1096637912.846396000 to 1096642205.961018000
>>ntpd was running in xen0.
>>    
>>
>
>David, Peri:
>
>I suspect you guys are seeing manifestations of the same
>bug. It's odd that you only see it on some machines, but it might
>be due to the relative error between the RTC and CPU clocks or
>such like.
>
>Please can you try the new patch which may give a little more
>information.
>
>Thanks,
>Ian
>
>
>--- /usr/groups/xeno/BK/xeno.bk/linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c    2004-10-01 16:01:03.000000000 +0100
>+++ arch/xen/i386/kernel/time.c 2004-10-01 16:10:06.000000000 +0100
>@@ -114,28 +114,34 @@
> 
> #define NS_PER_TICK (1000000000ULL/HZ)
> 
>-#define HANDLE_USEC_UNDERFLOW(_tv) do {                \
>+#define HANDLE_USEC_UNDERFLOW(_tv) do {        int i=0;        \
>        while ((_tv).tv_usec < 0) {             \
>                (_tv).tv_usec += USEC_PER_SEC;  \
>                (_tv).tv_sec--;                 \
>-       }                                       \
>+       }if(i>100)printk(KERN_ALERT"USEC_UNDER %d\n",i);        \
> } while (0)
>-#define HANDLE_USEC_OVERFLOW(_tv) do {         \
>+#define HANDLE_USEC_OVERFLOW(_tv) do { int i=0;        \
>        while ((_tv).tv_usec >= USEC_PER_SEC) { \
>                (_tv).tv_usec -= USEC_PER_SEC;  \
>-               (_tv).tv_sec++;                 \
>-       }                                       \
>+               (_tv).tv_sec++; i++;            \
>+       }if(i>100)printk(KERN_ALERT"USEC_OVER %d\n",i); \
> } while (0)
> static inline void __normalize_time(time_t *sec, s64 *nsec)
> {
>+int i=0,j=0;
>        while (*nsec >= NSEC_PER_SEC) {
>                (*nsec) -= NSEC_PER_SEC;
>                (*sec)++;
>+               i++;
>        }
>        while (*nsec < 0) {
>                (*nsec) += NSEC_PER_SEC;
>                (*sec)--;
>+               j++;
>        }
>+
>+if( i>100 || j>100 ) printk(KERN_ALERT"normalize time %d %d\n",i,j);
>+
> }
> 
> /* Does this guest OS track Xen time, or set its wall clock independently? */
>@@ -155,6 +161,8 @@
>  */
> static void __get_time_values_from_xen(void)
> {
>+long last = shadow_tv.tv_sec;
>+
>        shared_info_t *s = HYPERVISOR_shared_info;
> 
>        do {
>@@ -169,6 +177,7 @@
>        while (shadow_time_version != s->time_version1);
> 
>        cur_timer->mark_offset();
>+if( shadow_tv.tv_sec-last > 600 ) printk(KERN_ALERT"**** __get_time_values_from_xen(void) JUPMED!\n");
> }
> 
> #define TIME_VALUES_UP_TO_DATE \
>@@ -227,18 +236,26 @@
>                        write_seqlock_irqsave(&xtime_lock, flags);
>                        __get_time_values_from_xen();
>                        write_sequnlock_irqrestore(&xtime_lock, flags);
>+printk(KERN_ALERT"GTOD Try again %ld %lld\n", shadow_tv.tv_sec,
>+       shadow_system_time);
>                        continue;
>                }
>        } while (read_seqretry(&xtime_lock, seq));
> 
>+{
>+int z=0;
>        while (usec >= USEC_PER_SEC) {
>                usec -= USEC_PER_SEC;
>                sec++;
>+               z++;
>        }
>+if(z>100) printk(KERN_ALERT"GTOD JUMP %d\n",z);
>+}
> 
>        /* Ensure that time-of-day is monotonically increasing. */
>        if ((sec < last_seen_tv.tv_sec) ||
>            ((sec == last_seen_tv.tv_sec) && (usec < last_seen_tv.tv_usec))) {
>+printk(KERN_ALERT"Clamp time %ld %ld\n",sec,last_seen_tv.tv_sec); 
>                sec = last_seen_tv.tv_sec;
>                usec = last_seen_tv.tv_usec;
>        } else {
>@@ -364,6 +381,7 @@
>                                        struct pt_regs *regs)
> {
>        s64 delta;
>+       unsigned int ticks = 0;
>        long sec_diff;
> 
>        __get_time_values_from_xen();
>@@ -378,9 +396,14 @@
> 
>        /* Process elapsed jiffies since last call. */
>        while (delta >= NS_PER_TICK) {
>+               ticks++;
>                delta -= NS_PER_TICK;
>                processed_system_time += NS_PER_TICK;
>-               do_timer_interrupt_hook(regs);
>+       }
>+
>+       if (ticks != 0) {
>+               jiffies_64 += ticks - 1;
>+               do_timer_interrupt_hook(regs); /* implicit 'jiffies_64++' */
>        }
> 
>        /*
>
>
>-------------------------------------------------------
>This SF.net email is sponsored by: IT Product Guide on ITManagersJournal
>Use IT products in your business? Tell us what you think of them. Give us
>Your Opinions, Get Free ThinkGeek Gift Certificates! Click to find out more
>http://productguide.itmanagersjournal.com/guidepromo.tmpl
>_______________________________________________
>Xen-devel mailing list
>Xen-devel@lists.sourceforge.net
>https://lists.sourceforge.net/lists/listinfo/xen-devel
>
>
>  
>


[-- Attachment #2: mini-time-fix-20041001.diff --]
[-- Type: text/x-patch, Size: 568 bytes --]

--- xeno-unstable/linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c	2004-10-01 04:00:16.000000000 +0100
+++ xeno-unstable-20041001/linux-2.6.8.1-xen-sparse/arch/xen/i386/kernel/time.c	2004-10-02 08:49:16.000000000 +0100
@@ -241,6 +241,10 @@
 	    ((sec == last_seen_tv.tv_sec) && (usec < last_seen_tv.tv_usec))) {
 		sec = last_seen_tv.tv_sec;
 		usec = last_seen_tv.tv_usec;
+		if((last_seen_tv.tv_usec += 1) >= USEC_PER_SEC) {
+			last_seen_tv.tv_sec+= 1;
+			last_seen_tv.tv_usec= 0;
+		}
 	} else {
 		last_seen_tv.tv_sec = sec;
 		last_seen_tv.tv_usec = usec;