AW: [Xen-devel] Clocksources and other mysteries

[Carsten Schiers <carsten@xxxxxxxxxx>]

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