Ups sorry, missed the tail I guess you are only interested in the max
values...
BTW: during the measurement, there was a Time went Backwards in log:
Mar 28 10:47:15 data kernel: Timer ISR/0: Time went backwards:
delta=-67288961 delta_cpu=72711039 shadow=134369155097800 off=65631400
processed=134369288016520 cpu_processed=134369148016520
Mar 28 10:47:15 data kernel: 0: 134369148016520
Mar 28 10:47:15 data kernel: 1: 134369288016520
Will try to check on unstable soon...
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
|
Home