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@oracle.com] 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@schiers.de] 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@lists.xensource.com http://lists.xensource.com/xen-devel _______________________________________________ Xen-devel mailing list Xen-devel@lists.xensource.com http://lists.xensource.com/xen-devel _______________________________________________ Xen-devel mailing list Xen-devel@lists.xensource.com http://lists.xensource.com/xen-devel