AW: RE: [Xen-devel] Time went backwards 885 ms

["Carsten Schiers" <carsten@xxxxxxxxxx>]

Hi,

I see a major difference, although it might be wise to let the machine 
run a bit and repeat
the exercise. Here the output for current xen-unstable:

(XEN) Synced stime skew: max=638ns avg=123ns samples=4487 current=236ns
(XEN) Synced cycles skew: max=832 avg=226 samples=4487 current=692
(XEN) Synced stime skew: max=638ns avg=123ns samples=4488 current=62ns
(XEN) Synced cycles skew: max=832 avg=226 samples=4488 current=172
(XEN) Synced stime skew: max=638ns avg=123ns samples=4489 current=67ns
(XEN) Synced cycles skew: max=832 avg=226 samples=4489 current=193

BR,
Carsten.

-----Ursprüngliche Nachricht-----
Von: Carsten Schiers 
Gesendet: Samstag, 28. März 2009 11:23
An: dan.magenheimer; xen-devel
Betreff: AW: RE: [Xen-devel] Time went backwards 885 ms

Here e.g. the last entries for Xen 3.3.1:

(XEN) Synced cycles skew: max=1142 avg=315 samples=12670 current=256
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12671 
current=36ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12671 current=449
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12672 
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12672 current=257
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12673 
current=19ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12673 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12674 
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12674 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12675 
current=54ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12675 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12676 
current=16ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12676 current=445
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12677 
current=49ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12677 current=508
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12678 
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12678 current=62
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12679 
current=14ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12679 current=292
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12680 
current=21ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12680 current=193
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12681 
current=88ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12681 current=143
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12682 
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12682 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12683 
current=1ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12683 current=33
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12684 
current=18ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12684 current=4
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12685 
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12685 current=370
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12686 
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12686 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12687 
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12687 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12688 
current=44ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12688 current=366
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12689 
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12689 current=369
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12690 
current=75ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12690 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12691 
current=31ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12691 current=78
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12692 
current=124ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12692 current=289
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12693 
current=80ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12693 current=330
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12694 
current=22ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12694 current=256
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12695 
current=79ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12695 current=373
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12696 
current=97ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12696 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12697 
current=119ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12697 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12698 
current=140ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12698 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12699 
current=164ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12699 current=334
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12700 
current=160ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12700 current=370
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12701 
current=122ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12701 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12702 
current=74ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12702 current=175
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12703 
current=65ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12703 current=102
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12704 
current=89ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12704 current=62
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12705 
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12705 current=116
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12706 
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12706 current=188
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12707 
current=10ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12707 current=31
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12708 
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12708 current=65
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12709 
current=54ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12709 current=295
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12710 
current=119ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12710 current=77
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12711 
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12711 current=47
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12712 
current=78ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12712 current=52
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12713 
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12713 current=49
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12714 
current=26ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12714 current=42
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12715 
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12715 current=62
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12716 
current=9ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12716 current=53
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12717 
current=10ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12717 current=52
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12718 
current=1ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12718 current=33
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12719 
current=109ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12719 current=175
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12720 
current=0ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12720 current=36
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12721 
current=17ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12721 current=256
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12722 
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12722 current=422
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12723 
current=92ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12723 current=492
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12724 
current=50ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12724 current=387
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12725 
current=94ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12725 current=490
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12726 
current=43ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12726 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12727 
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12727 current=57
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12728 
current=48ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12728 current=287
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12729 
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12729 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12730 
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12730 current=251
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12731 
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12731 current=169
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12732 
current=38ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12732 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12733 
current=189ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12733 current=345
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12734 
current=6ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12734 current=256
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12735 
current=52ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12735 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12736 
current=46ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12736 current=294
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12737 
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12737 current=465
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12738 
current=50ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12738 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12739 
current=51ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12739 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12740 
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12740 current=330
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12741 
current=62ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12741 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12742 
current=47ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12742 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12743 
current=4ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12743 current=292
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12744 
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12744 current=330
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12745 
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12745 current=48
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12746 
current=87ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12746 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12747 
current=93ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12747 current=328
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12748 
current=28ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12748 current=98
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12749 
current=29ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12749 current=102
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12750 
current=112ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12750 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12751 
current=138ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12751 current=372
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12752 
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12752 current=339
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12753 
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12753 current=335
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12754 
current=61ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12754 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12755 
current=18ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12755 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12756 
current=3ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12756 current=170
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12757 
current=122ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12757 current=22
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12758 
current=150ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12758 current=285
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12759 
current=269ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12759 current=408
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12760 
current=246ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12760 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12761 
current=179ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12761 current=52
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12762 
current=165ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12762 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12763 
current=149ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12763 current=490
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12764 
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12764 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12765 
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12765 current=193
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12766 
current=33ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12766 current=545
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12767 
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12767 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12768 
current=25ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12768 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12769 
current=51ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12769 current=285
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12770 
current=88ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12770 current=103
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12771 
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12771 current=373
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12772 
current=94ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12772 current=134
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12773 
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12773 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12774 
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12774 current=217
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12775 
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12775 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12776 
current=21ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12776 current=297
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12777 
current=11ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12777 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12778 
current=20ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12778 current=47
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12779 
current=15ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12779 current=48
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12780 
current=9ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12780 current=251
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12781 
current=48ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12781 current=79
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12782 
current=70ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12782 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12783 
current=65ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12783 current=330

-----Ursprüngliche Nachricht-----
Von: Carsten Schiers 
Gesendet: Samstag, 28. März 2009 10:53
An: dan.magenheimer; xen-devel
Betreff: AW: RE: [Xen-devel] Time went backwards 885 ms

Oh, I didn't know that...

I started to do so. But not all lines will show up in xm dmesg. Is there 



any trick to have a bigger buffer to capture it or are only the last 
lines
of interest?

BR,
Carsten.

-----Ursprüngliche Nachricht-----
Von: Dan Magenheimer [mailto:dan.magenheimer@xxxxxxxxxx] 
Gesendet: Freitag, 27. März 2009 21:20
An: Carsten Schiers; xen-devel
Betreff: RE: [Xen-devel] Time went backwards 885 ms

Two possibilities... many power management features
have gone into Xen and there are many bug fixes post-3.3
to improve time sync in the presence of power management.

However if power management is NOT happening on your system,
it's possible that your processors have bad TSC skew
that Xen's TSC synchronization mechanism is unable to
handle.  (This seems unlikely with a dual core... AMD
might have information otherwise.)

A nice feature that went into Xen 3.3 is the ability to
measure the skew between physical processors.  The
"xm debug-key t" takes only one sample, but it can
be repeated many times and will retain max and avg
for all of the samples.

Can you do:

# for j in $(seq -w 10000); do xm debug-key t; done
 
in dom0, then send the output from "xm dmesg | tail"

If you can do this both with Xen 3.3 and 3.4 (when it
is released, or xen-unstable now), that would be great!

-----Original Message-----
From: Carsten Schiers [mailto:carsten@xxxxxxxxxx]
Sent: Friday, March 27, 2009 3:19 AM
To: xen-devel
Subject: [Xen-devel] Time went backwards 885 ms


Dear all,

I thought this might be worth again to report:

After rebooting a 3.3.1/2.6.18.8 environment on my AMD 4050e, I received 


a 885ms delta just
after powernow-k8 loaded:


Mar 26 21:28:37 data kernel: powernow-k8: Found 2 AMD Athlon(tm) Dual 
Core Processor 4050e processors (version 2.20.00)
Mar 26 21:28:37 data kernel: powernow-k8:    0 : fid 0xd (2100 MHz), vid 


0xe
Mar 26 21:28:37 data kernel: powernow-k8:    1 : fid 0xc (2000 MHz), vid 


0xf
Mar 26 21:28:37 data kernel: powernow-k8:    2 : fid 0xa (1800 MHz), vid 


0x11
Mar 26 21:28:37 data kernel: powernow-k8:    3 : fid 0x2 (1000 MHz), vid 


0x16
Mar 26 21:28:37 data kernel: Timer ISR/1: Time went backwards: 
delta=-885437842 delta_cpu=6562158 shadow=11822142480 off=436198 
processed=12708016520 cpu_p
rocessed=11816016520
Mar 26 21:28:37 data kernel:  0: 12704016520
Mar 26 21:28:37 data kernel:  1: 11816016520


Find full xm dmesg, xm info, and syslog of boot attached.

Otherwise, the environment is more stable; Time went backwards appear 
roughly every 2-3 days,
mostly when there is a 1,0->2,1GHz jump when munin asks for CPU. It is 
reduced in addition by a
4 sec sampling time of the ondemand govenor.

Will test 3.4 as soon as released.

BR,
Carsten.



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



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



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