Xen project Mailing List

AW: [Xen-devel] Occasional "Time went backwards" mesages, was: Clocksources and other mysteries

To: Carsten Schiers <carsten@xxxxxxxxxx>, Keir Fraser <keir.fraser@xxxxxxxxxxxxx>, xen-devel@xxxxxxxxxxxxxxxxxxx, bastian@xxxxxxxxxxxx

From: Carsten Schiers <carsten@xxxxxxxxxx>

Date: Wed, 4 Mar 2009 10:07:41 +0100

Cc:

Delivery-date: Wed, 04 Mar 2009 01:08:12 -0800

List-id: Xen developer discussion <xen-devel.lists.xensource.com>

Hi, did a lot of different testings with Xen 3.2-1 Debian and 3.3.1 homemade. I was able to reduce "Time went backwards" messages to a few occurences per day. Delta is always negative, between 10ms (logically) and hust below 40ms. Best combination so far: 3.3.1 with waldi 3.3 Kernel (few per day), worst combination is Xen 3.3.1 with current Lenny kernel (few per minute). All occurences still seem to be bound to cpu frequency changes. Not real evidence though, just that it happens when shutting down/booting DomUs or when munin computes nifty grapics. I will try unstable with latest 2.6.18.8 the next days, but as it doesn't happen very often now, it takes some time. Unfortunately I have no idea at what exact changeset level waldi kernels are. Any interest in more reports on that or is it known and tollerable? BTW: any hint how to change the 10ms limit in case I shouldn't worry too much about it? BR, Carsten. ____________________________________________________________________ Carsten Schiers, Henseweg 23h, 22359 Hamburg, Tel. (040) 6044 9717, carsten@xxxxxxxxxx ----- Originalnachricht ----- Von: Carsten Schiers <carsten@xxxxxxxxxx> Gesendet: Mon, 12.1.2009 12:48 An: Keir Fraser <keir.fraser@xxxxxxxxxxxxx> ; xen-devel@xxxxxxxxxxxxxxxxxxx Betreff: AW: [Xen-devel] Clocksources and other mysteries It's everytime when cpufreq_ondemand or cpufreq-set changes the frequency, aprox. 3 messages per event. Is that occasional? I tend to say: no. Please see an excerpt below. And if it's not occasional, what could I do? And by the way: I found no code that TSC will get adjusted, so I think it will get worse over the time... Thanks, Carsten. messages.0:Jan 9 12:25:15 data kernel: Timer ISR/1: Time went backwards: delta=-12018171 delta_cpu=115981829 shadow=75780489375160 off=410607630 processed=75780912000000 cpu_processed=75780784000000 messages.0:Jan 9 12:25:16 data kernel: Timer ISR/1: Time went backwards: delta=-16026092 delta_cpu=75973908 shadow=75780489375160 off=806599392 processed=75781312000000 cpu_processed=75781220000000 messages.0:Jan 9 12:25:17 data kernel: Timer ISR/0: Time went backwards: delta=-740021307 delta_cpu=39978693 shadow=75780512149240 off=999830312 processed=75782252000000 cpu_processed=75781472000000 messages.0:Jan 9 12:30:14 data kernel: Timer ISR/0: Time went backwards: delta=-88031200 delta_cpu=39968800 shadow=76078328190440 off=999778806 processed=76079416000000 cpu_processed=76079288000000 messages.0:Jan 9 12:30:16 data kernel: Timer ISR/0: Time went backwards: delta=-785869130 delta_cpu=6130870 shadow=76079431383280 off=998748426 processed=76081216000000 cpu_processed=76080424000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/0: Time went backwards: delta=-308640982 delta_cpu=7359018 shadow=76678234607036 off=976752607 processed=76679520000000 cpu_processed=76679204000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/0: Time went backwards: delta=-311783977 delta_cpu=8216023 shadow=76678234607036 off=981609505 processed=76679528000000 cpu_processed=76679208000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/1: Time went backwards: delta=-12010703 delta_cpu=7989297 shadow=76679516186720 off=51803565 processed=76679580000000 cpu_processed=76679560000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/1: Time went backwards: delta=-16804204 delta_cpu=31195796 shadow=76679516186720 off=79009670 processed=76679612000000 cpu_processed=76679564000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/1: Time went backwards: delta=-12015144 delta_cpu=23984856 shadow=76679516186720 off=99798703 processed=76679628000000 cpu_processed=76679592000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/1: Time went backwards: delta=-16002390 delta_cpu=47997610 shadow=76679516186720 off=143812049 processed=76679676000000 cpu_processed=76679612000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/1: Time went backwards: delta=-16002306 delta_cpu=99997694 shadow=76679516186720 off=311812214 processed=76679844000000 cpu_processed=76679728000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/1: Time went backwards: delta=-20009989 delta_cpu=119990011 shadow=76679516186720 off=427804685 processed=76679964000000 cpu_processed=76679824000000 messages.0:Jan 9 12:40:14 data kernel: Timer ISR/1: Time went backwards: delta=-20003075 delta_cpu=51996925 shadow=76679516186720 off=475811309 processed=76680012000000 cpu_processed=76679940000000 messages.0:Jan 9 12:40:15 data kernel: Timer ISR/1: Time went backwards: delta=-20022020 delta_cpu=3977980 shadow=76679516186720 off=663792405 processed=76680200000000 cpu_processed=76680176000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-19489274 delta_cpu=4510726 shadow=76977914783244 off=441746174 processed=76978376000000 cpu_processed=76978352000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-18731547 delta_cpu=25268453 shadow=76977914783244 off=594486759 processed=76978528000000 cpu_processed=76978484000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-29511790 delta_cpu=10488210 shadow=76977914783244 off=731707417 processed=76978676000000 cpu_processed=76978636000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-36343330 delta_cpu=67656670 shadow=76977914783244 off=796875850 processed=76978748000000 cpu_processed=76978644000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-25173167 delta_cpu=22826833 shadow=76977914783244 off=816046030 processed=76978756000000 cpu_processed=76978708000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-16590822 delta_cpu=35409178 shadow=76977914783244 off=848626988 processed=76978780000000 cpu_processed=76978728000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-11911350 delta_cpu=8088650 shadow=76977914783244 off=853307168 processed=76978780000000 cpu_processed=76978760000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-36157180 delta_cpu=19842820 shadow=76977914783244 off=929060430 processed=76978880000000 cpu_processed=76978824000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-51943502 delta_cpu=20056498 shadow=76978916907554 off=11149402 processed=76978980000000 cpu_processed=76978908000000 messages.0:Jan 9 12:45:13 data kernel: Timer ISR/0: Time went backwards: delta=-47941739 delta_cpu=4058261 shadow=76978916907554 off=15150923 processed=76978980000000 cpu_processed=76978928000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/1: Time went backwards: delta=-11693183 delta_cpu=104306817 shadow=77277628116247 off=532206689 processed=77278172000000 cpu_processed=77278056000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/1: Time went backwards: delta=-19598845 delta_cpu=116401155 shadow=77277628116247 off=644286629 processed=77278292000000 cpu_processed=77278156000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/1: Time went backwards: delta=-23368732 delta_cpu=124631268 shadow=77277628116247 off=764516809 processed=77278416000000 cpu_processed=77278268000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/1: Time went backwards: delta=-35459200 delta_cpu=48540800 shadow=77277628116247 off=808424847 processed=77278472000000 cpu_processed=77278388000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/1: Time went backwards: delta=-43213786 delta_cpu=16786214 shadow=77277628116247 off=820670725 processed=77278492000000 cpu_processed=77278432000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/1: Time went backwards: delta=-27893067 delta_cpu=68106933 shadow=77277628116247 off=887992064 processed=77278544000000 cpu_processed=77278448000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/1: Time went backwards: delta=-15504501 delta_cpu=48495499 shadow=77277628116247 off=936380582 processed=77278580000000 cpu_processed=77278516000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/0: Time went backwards: delta=-18471272 delta_cpu=5528728 shadow=77278556697207 off=284832106 processed=77278860000000 cpu_processed=77278836000000 messages.0:Jan 9 12:50:13 data kernel: Timer ISR/0: Time went backwards: delta=-20029777 delta_cpu=35970223 shadow=77278556697207 off=359273478 processed=77278936000000 cpu_processed=77278880000000 messages.0:Jan 9 12:50:14 data kernel: Timer ISR/0: Time went backwards: delta=-28038759 delta_cpu=15961241 shadow=77278556697207 off=875264595 processed=77279460000000 cpu_processed=77279416000000 messages.0:Jan 9 12:55:14 data kernel: Timer ISR/1: Time went backwards: delta=-23993106 delta_cpu=100006894 shadow=77578619176253 off=868843079 processed=77579512000000 cpu_processed=77579388000000 messages.0:Jan 9 12:55:14 data kernel: Timer ISR/1: Time went backwards: delta=-15993587 delta_cpu=64006413 shadow=77578619176253 off=932831052 processed=77579568000000 cpu_processed=77579488000000 messages.0:Jan 9 12:55:15 data kernel: Timer ISR/0: Time went backwards: delta=-20019563 delta_cpu=11980437 shadow=77579572937147 off=823043738 processed=77580416000000 cpu_processed=77580384000000 messages.0:Jan 9 12:55:15 data kernel: Timer ISR/0: Time went backwards: delta=-13777491 delta_cpu=10222509 shadow=77579572937147 off=829285587 processed=77580416000000 cpu_processed=77580392000000 messages.0:Jan 9 12:55:15 data kernel: Timer ISR/0: Time went backwards: delta=-24449294 delta_cpu=19550706 shadow=77579572937147 off=878613859 processed=77580476000000 cpu_processed=77580432000000 messages.0:Jan 9 12:55:15 data kernel: Timer ISR/0: Time went backwards: delta=-18397840 delta_cpu=9602160 shadow=77579572937147 off=884665174 processed=77580476000000 cpu_processed=77580448000000 messages.0:Jan 9 12:55:15 data kernel: Timer ISR/0: Time went backwards: delta=-20040885 delta_cpu=19959115 shadow=77579572937147 off=975022465 processed=77580568000000 cpu_processed=77580528000000 messages.0:Jan 9 12:55:15 data kernel: Timer ISR/1: Time went backwards: delta=-164032408 delta_cpu=39967592 shadow=77579619178732 off=996789362 processed=77580780000000 cpu_processed=77580576000000 messages.0:Jan 9 12:55:15 data kernel: Timer ISR/0: Time went backwards: delta=-16015520 delta_cpu=47984480 shadow=77580769972800 off=94012230 processed=77580880000000 cpu_processed=77580816000000 messages.0:Jan 9 12:55:16 data kernel: Timer ISR/0: Time went backwards: delta=-16020854 delta_cpu=31979146 shadow=77580769972800 off=494006895 processed=77581280000000 cpu_processed=77581232000000 messages.0:Jan 9 13:00:13 data kernel: Timer ISR/1: Time went backwards: delta=-14462502 delta_cpu=81537498 shadow=77877559766287 off=881791414 processed=77878456000000 cpu_processed=77878360000000 messages.0:Jan 9 13:00:13 data kernel: Timer ISR/1: Time went backwards: delta=-11934544 delta_cpu=28065456 shadow=77877559766287 off=908301089 processed=77878480000000 cpu_processed=77878440000000 messages.0:Jan 9 13:00:13 data kernel: Timer ISR/1: Time went backwards: delta=-11697161 delta_cpu=16302839 shadow=77877559766287 off=924537397 processed=77878496000000 cpu_processed=77878468000000 messages.0:Jan 9 13:00:16 data kernel: Timer ISR/1: Time went backwards: delta=-1018449317 delta_cpu=57550683 shadow=77879559836710 off=977714939 processed=77881556000000 cpu_processed=77880480000000 messages.0:Jan 9 13:00:16 data kernel: Timer ISR/1: Time went backwards: delta=-1022454873 delta_cpu=5545127 shadow=77879559836710 off=981709100 processed=77881564000000 cpu_processed=77880536000000 messages.0:Jan 9 13:00:17 data kernel: Timer ISR/0: Time went backwards: delta=-11993711 delta_cpu=28006289 shadow=77881558973360 off=985033887 processed=77882556000000 cpu_processed=77882516000000 ----- Originalnachricht ----- Von: Keir Fraser <keir.fraser@xxxxxxxxxxxxx> Gesendet: Mon, 12.1.2009 10:52 An: Carsten Schiers <carsten@xxxxxxxxxx> ; xen-devel@xxxxxxxxxxxxxxxxxxx Betreff: Re: [Xen-devel] Clocksources and other mysteries On 12/01/2009 09:43, "Carsten Schiers" <carsten@xxxxxxxxxx> wrote: > First mystery: when jiffies is used as clocksource, why is the system checking > and complaining about deltas in TSC? Can I thus ignore them? > > Second mystery: when Xen reports:(XEN) Platform timer is 25.000MHz HPET, why > isn't Xen using it? Shouldn't it? Wouldn't be the HPET the best choice for my > non-TSC-invariant CPU? Fine-grained system time is computed from TSC, calibrated periodically to the platform timesource (HPET). Xen kernels compute jiffies from Xen system time, hence computed from TSC. If the time went backwards messages are occasional you can ignore them, or even disable them. -- Keir _______________________________________________ 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

©2013 Xen Project, A Linux Foundation Collaborative Project. All Rights Reserved.
Linux Foundation is a registered trademark of The Linux Foundation.
Xen Project is a trademark of The Linux Foundation.