* Timer on i.MX28 moving backwards @ 2018-09-06 20:02 Uwe Kleine-König 2018-09-06 21:39 ` Russell King - ARM Linux 0 siblings, 1 reply; 6+ messages in thread From: Uwe Kleine-König @ 2018-09-06 20:02 UTC (permalink / raw) To: linux-arm-kernel Hello, on an i.MX28 based machine running Linux 4.9.y-rt I added the following patch: diff --git a/drivers/clocksource/mmio.c b/drivers/clocksource/mmio.c index c4f7d7a9b689..557e555e95b7 100644 --- a/drivers/clocksource/mmio.c +++ b/drivers/clocksource/mmio.c @@ -25,6 +25,13 @@ cycle_t clocksource_mmio_readl_up(struct clocksource *c) return (cycle_t)readl_relaxed(to_mmio_clksrc(c)->reg); } +cycle_t mxs_clocksource_mmio_readl_down(struct clocksource *c) +{ + cycle_t ret = ~(cycle_t)readl_relaxed(to_mmio_clksrc(c)->reg) & c->mask; + trace_printk("time = %llx\n", ret); + return ret; +} + cycle_t clocksource_mmio_readl_down(struct clocksource *c) { return ~(cycle_t)readl_relaxed(to_mmio_clksrc(c)->reg) & c->mask; diff --git a/drivers/clocksource/mxs_timer.c b/drivers/clocksource/mxs_timer.c index 0ba0a913b41d..d78edf9345b2 100644 --- a/drivers/clocksource/mxs_timer.c +++ b/drivers/clocksource/mxs_timer.c @@ -217,7 +217,7 @@ static int __init mxs_clocksource_init(struct clk *timer_clk) clocksource_register_hz(&clocksource_mxs, c); else { clocksource_mmio_init(mxs_timrot_base + HW_TIMROT_RUNNING_COUNTn(1), - "mxs_timer", c, 200, 32, clocksource_mmio_readl_down); + "mxs_timer", c, 200, 32, mxs_clocksource_mmio_readl_down); sched_clock_register(mxs_read_sched_clock_v2, 32, c); } diff --git a/include/linux/clocksource.h b/include/linux/clocksource.h index 08398182f56e..dead82c9b19c 100644 --- a/include/linux/clocksource.h +++ b/include/linux/clocksource.h @@ -234,6 +234,7 @@ static inline void __clocksource_update_freq_khz(struct clocksource *cs, u32 khz extern int timekeeping_notify(struct clocksource *clock); extern cycle_t clocksource_mmio_readl_up(struct clocksource *); +extern cycle_t mxs_clocksource_mmio_readl_down(struct clocksource *); extern cycle_t clocksource_mmio_readl_down(struct clocksource *); extern cycle_t clocksource_mmio_readw_up(struct clocksource *); extern cycle_t clocksource_mmio_readw_down(struct clocksource *); And with this I got the following trace: $ grep mxs_clocksource_mmio_readl_down trace ... <idle>-0 [000] d...1.. 1647.391949: mxs_clocksource_mmio_readl_down: time = 349cfe51 <idle>-0 [000] d...1.. 1647.397639: mxs_clocksource_mmio_readl_down: time = 349f1436 <idle>-0 [000] d..h2.. 1647.397672: mxs_clocksource_mmio_readl_down: time = 349f1731 <idle>-0 [000] dn.h1.. 1647.397705: mxs_clocksource_mmio_readl_down: time = 349f1a2b profinet-250 [000] ....... 1647.397821: mxs_clocksource_mmio_readl_down: time = 349f24e8 <idle>-0 [000] d...1.. 1647.398181: mxs_clocksource_mmio_readl_down: time = 349f466f <idle>-0 [000] d...1.. 1647.399452: mxs_clocksource_mmio_readl_down: time = 349fbe0e <idle>-0 [000] d..h2.. 1647.399488: mxs_clocksource_mmio_readl_down: time = 349fc16e <idle>-0 [000] dn.h1.. 1647.399524: mxs_clocksource_mmio_readl_down: time = 349fc4b8 mrp62439d-221 [000] ....... 1647.400062: mxs_clocksource_mmio_readl_down: time = 349ff658 mrp62439d-221 [000] ....... 1647.400858: mxs_clocksource_mmio_readl_down: time = 34a04125 mrp62439d-221 [000] d..h1.. 1647.401013: mxs_clocksource_mmio_readl_down: time = 34a04f0f mrp62439d-221 [000] d..h... 1647.401059: mxs_clocksource_mmio_readl_down: time = 34a05484 mrp62439d-221 [000] d..h3.. 1647.401263: mxs_clocksource_mmio_readl_down: time = 34a06981 mrp62439d-221 [000] d..h3.. 1647.401263: mxs_clocksource_mmio_readl_down: time = 34a06ac3 mrp62439d-221 [000] d..h3.. 1647.401263: mxs_clocksource_mmio_readl_down: time = 34a06c39 mrp62439d-221 [000] ....... 1647.401263: mxs_clocksource_mmio_readl_down: time = 34a064ca The interesting fact here is, that the values returned by mxs_clocksource_mmio_readl_down are not completely monotonic: The last value is smaller than the previous value. Given that the jump backwards is that small, I think we can rule out an overflow. (The input clk for the mx28 timer runs with 24 MHz, so one complete turnaround takes 0x100000000 / 24000000 Hz = 178.95697 s.) And this happens often: $ awk '/mxs_clocksource_mmio_readl_down/ { gsub(".*time = ", "0x"); time = strtonum($0); if (time - prev < 0) { printf "%x: %d\n", time, time - prev; } prev = time }' trace | wc -l 106 (There is one false positive where the counter overflows, the trace covers a time span of ~48 s. The 5 biggest backwards jumps are: -183784, -79486, -38294, -6552, -5471; minimum: -1332) Checking the Errata for i.MX28 there isn't anything documented affecting TIMROT. Reading the Reference Manual I didn't find anything that would explain a jump in the counter register. I didn't try yet to reproduce this on another machine or with a newer non-rt kernel, but I'd expect the same to happen there. Does this ring a bell for someone? Does someone see an explanation that doesn't include a hardware fault? Best regards Uwe -- Pengutronix e.K. | Uwe Kleine-K?nig | Industrial Linux Solutions | http://www.pengutronix.de/ | ^ permalink raw reply related [flat|nested] 6+ messages in thread
* Timer on i.MX28 moving backwards 2018-09-06 20:02 Timer on i.MX28 moving backwards Uwe Kleine-König @ 2018-09-06 21:39 ` Russell King - ARM Linux 2018-09-07 7:21 ` Uwe Kleine-König 0 siblings, 1 reply; 6+ messages in thread From: Russell King - ARM Linux @ 2018-09-06 21:39 UTC (permalink / raw) To: linux-arm-kernel On Thu, Sep 06, 2018 at 10:02:02PM +0200, Uwe Kleine-K?nig wrote: > +cycle_t mxs_clocksource_mmio_readl_down(struct clocksource *c) > +{ > + cycle_t ret = ~(cycle_t)readl_relaxed(to_mmio_clksrc(c)->reg) & c->mask; > + trace_printk("time = %llx\n", ret); I think it may be worth re-running your test with: u32 one, two; one = readl_relaxed(to_mmio_clksrc(c)->reg); two = readl_relaxed(to_mmio_clksrc(c)->reg); trace_printk("time=0x%08x:0x%08x\n", one, two); return ~(cycle_t)two & c->mask; and compare the values not only between each call but also between each read of the register. It could be a synchronisation issue when reading the timer register, in which case you may find just one read is incorrect. -- RMK's Patch system: http://www.armlinux.org.uk/developer/patches/ FTTC broadband for 0.8mile line in suburbia: sync at 13.8Mbps down 630kbps up According to speedtest.net: 13Mbps down 490kbps up ^ permalink raw reply [flat|nested] 6+ messages in thread
* Timer on i.MX28 moving backwards 2018-09-06 21:39 ` Russell King - ARM Linux @ 2018-09-07 7:21 ` Uwe Kleine-König 2018-09-07 8:38 ` Uwe Kleine-König 0 siblings, 1 reply; 6+ messages in thread From: Uwe Kleine-König @ 2018-09-07 7:21 UTC (permalink / raw) To: linux-arm-kernel On Thu, Sep 06, 2018 at 10:39:25PM +0100, Russell King - ARM Linux wrote: > On Thu, Sep 06, 2018 at 10:02:02PM +0200, Uwe Kleine-K?nig wrote: > > +cycle_t mxs_clocksource_mmio_readl_down(struct clocksource *c) > > +{ > > + cycle_t ret = ~(cycle_t)readl_relaxed(to_mmio_clksrc(c)->reg) & c->mask; > > + trace_printk("time = %llx\n", ret); > > I think it may be worth re-running your test with: > > u32 one, two; > > one = readl_relaxed(to_mmio_clksrc(c)->reg); > two = readl_relaxed(to_mmio_clksrc(c)->reg); > trace_printk("time=0x%08x:0x%08x\n", one, two); > > return ~(cycle_t)two & c->mask; > > and compare the values not only between each call but also between > each read of the register. It could be a synchronisation issue when > reading the timer register, in which case you may find just one read > is incorrect. Good idea, this is a part of a trace I captured with this implemented: mrp62439d-224 [000] d..h2.. 790.936689: mxs_clocksource_mmio_readl_down: time = 0x948e3d1a:0x948e3d14 mrp62439d-224 [000] ....... 790.936689: mxs_clocksource_mmio_readl_down: time = 0x948e4d26:0x948e4d20 mrp62439d-224 [000] ....... 790.936904: mxs_clocksource_mmio_readl_down: time = 0x948e3690:0x948e368a hmm, I'm unsure what to think now. Uwe -- Pengutronix e.K. | Uwe Kleine-K?nig | Industrial Linux Solutions | http://www.pengutronix.de/ | ^ permalink raw reply [flat|nested] 6+ messages in thread
* Timer on i.MX28 moving backwards 2018-09-07 7:21 ` Uwe Kleine-König @ 2018-09-07 8:38 ` Uwe Kleine-König 2018-09-07 9:08 ` Russell King - ARM Linux 0 siblings, 1 reply; 6+ messages in thread From: Uwe Kleine-König @ 2018-09-07 8:38 UTC (permalink / raw) To: linux-arm-kernel On Fri, Sep 07, 2018 at 09:21:05AM +0200, Uwe Kleine-K?nig wrote: > On Thu, Sep 06, 2018 at 10:39:25PM +0100, Russell King - ARM Linux wrote: > > On Thu, Sep 06, 2018 at 10:02:02PM +0200, Uwe Kleine-K?nig wrote: > > > +cycle_t mxs_clocksource_mmio_readl_down(struct clocksource *c) > > > +{ > > > + cycle_t ret = ~(cycle_t)readl_relaxed(to_mmio_clksrc(c)->reg) & c->mask; > > > + trace_printk("time = %llx\n", ret); > > > > I think it may be worth re-running your test with: > > > > u32 one, two; > > > > one = readl_relaxed(to_mmio_clksrc(c)->reg); > > two = readl_relaxed(to_mmio_clksrc(c)->reg); > > trace_printk("time=0x%08x:0x%08x\n", one, two); > > > > return ~(cycle_t)two & c->mask; > > > > and compare the values not only between each call but also between > > each read of the register. It could be a synchronisation issue when > > reading the timer register, in which case you may find just one read > > is incorrect. > > Good idea, this is a part of a trace I captured with this implemented: > > mrp62439d-224 [000] d..h2.. 790.936689: mxs_clocksource_mmio_readl_down: time = 0x948e3d1a:0x948e3d14 > mrp62439d-224 [000] ....... 790.936689: mxs_clocksource_mmio_readl_down: time = 0x948e4d26:0x948e4d20 > mrp62439d-224 [000] ....... 790.936904: mxs_clocksource_mmio_readl_down: time = 0x948e3690:0x948e368a > > hmm, I'm unsure what to think now. To clearify my (obviously too short) mail: Judging form a trace over 43s the two consecutive reads always correctly yield a decrementing counter as expected. But there is not always the expected monotonicity between consecutive calls to clocksource_mmio_readl_down. Best regards Uwe -- Pengutronix e.K. | Uwe Kleine-K?nig | Industrial Linux Solutions | http://www.pengutronix.de/ | ^ permalink raw reply [flat|nested] 6+ messages in thread
* Timer on i.MX28 moving backwards 2018-09-07 8:38 ` Uwe Kleine-König @ 2018-09-07 9:08 ` Russell King - ARM Linux 2018-09-07 10:00 ` Uwe Kleine-König 0 siblings, 1 reply; 6+ messages in thread From: Russell King - ARM Linux @ 2018-09-07 9:08 UTC (permalink / raw) To: linux-arm-kernel On Fri, Sep 07, 2018 at 10:38:04AM +0200, Uwe Kleine-K?nig wrote: > On Fri, Sep 07, 2018 at 09:21:05AM +0200, Uwe Kleine-K?nig wrote: > > On Thu, Sep 06, 2018 at 10:39:25PM +0100, Russell King - ARM Linux wrote: > > > On Thu, Sep 06, 2018 at 10:02:02PM +0200, Uwe Kleine-K?nig wrote: > > > > +cycle_t mxs_clocksource_mmio_readl_down(struct clocksource *c) > > > > +{ > > > > + cycle_t ret = ~(cycle_t)readl_relaxed(to_mmio_clksrc(c)->reg) & c->mask; > > > > + trace_printk("time = %llx\n", ret); > > > > > > I think it may be worth re-running your test with: > > > > > > u32 one, two; > > > > > > one = readl_relaxed(to_mmio_clksrc(c)->reg); > > > two = readl_relaxed(to_mmio_clksrc(c)->reg); > > > trace_printk("time=0x%08x:0x%08x\n", one, two); > > > > > > return ~(cycle_t)two & c->mask; > > > > > > and compare the values not only between each call but also between > > > each read of the register. It could be a synchronisation issue when > > > reading the timer register, in which case you may find just one read > > > is incorrect. > > > > Good idea, this is a part of a trace I captured with this implemented: > > > > mrp62439d-224 [000] d..h2.. 790.936689: mxs_clocksource_mmio_readl_down: time = 0x948e3d1a:0x948e3d14 > > mrp62439d-224 [000] ....... 790.936689: mxs_clocksource_mmio_readl_down: time = 0x948e4d26:0x948e4d20 > > mrp62439d-224 [000] ....... 790.936904: mxs_clocksource_mmio_readl_down: time = 0x948e3690:0x948e368a > > > > hmm, I'm unsure what to think now. > > To clearify my (obviously too short) mail: > > Judging form a trace over 43s the two consecutive reads always correctly > yield a decrementing counter as expected. But there is not always the > expected monotonicity between consecutive calls to > clocksource_mmio_readl_down. Hmm, there is another explanation - maybe the order of the trace entries are not strictly ordered. What happens with this: static atomic_t order; u32 one, two; int o; one = readl_relaxed(to_mmio_clksrc(c)->reg); o = atomic_add_return(1, &order); two = readl_relaxed(to_mmio_clksrc(c)->reg); trace_printk("time=0x%08x:0x%08x:%u\n", one, two, o); return ~(cycle_t)two & c->mask; -- RMK's Patch system: http://www.armlinux.org.uk/developer/patches/ FTTC broadband for 0.8mile line in suburbia: sync at 13.8Mbps down 630kbps up According to speedtest.net: 13Mbps down 490kbps up ^ permalink raw reply [flat|nested] 6+ messages in thread
* Timer on i.MX28 moving backwards 2018-09-07 9:08 ` Russell King - ARM Linux @ 2018-09-07 10:00 ` Uwe Kleine-König 0 siblings, 0 replies; 6+ messages in thread From: Uwe Kleine-König @ 2018-09-07 10:00 UTC (permalink / raw) To: linux-arm-kernel Hello Russel, On Fri, Sep 07, 2018 at 10:08:36AM +0100, Russell King - ARM Linux wrote: > On Fri, Sep 07, 2018 at 10:38:04AM +0200, Uwe Kleine-K?nig wrote: > > On Fri, Sep 07, 2018 at 09:21:05AM +0200, Uwe Kleine-K?nig wrote: > > > Good idea, this is a part of a trace I captured with this implemented: > > > > > > mrp62439d-224 [000] d..h2.. 790.936689: mxs_clocksource_mmio_readl_down: time = 0x948e3d1a:0x948e3d14 > > > mrp62439d-224 [000] ....... 790.936689: mxs_clocksource_mmio_readl_down: time = 0x948e4d26:0x948e4d20 > > > mrp62439d-224 [000] ....... 790.936904: mxs_clocksource_mmio_readl_down: time = 0x948e3690:0x948e368a > > > > > > hmm, I'm unsure what to think now. > > > > To clearify my (obviously too short) mail: > > > > Judging form a trace over 43s the two consecutive reads always correctly > > yield a decrementing counter as expected. But there is not always the > > expected monotonicity between consecutive calls to > > clocksource_mmio_readl_down. > > Hmm, there is another explanation - maybe the order of the trace > entries are not strictly ordered. What happens with this: > > static atomic_t order; > u32 one, two; > int o; > > one = readl_relaxed(to_mmio_clksrc(c)->reg); > o = atomic_add_return(1, &order); > two = readl_relaxed(to_mmio_clksrc(c)->reg); > trace_printk("time=0x%08x:0x%08x:%u\n", one, two, o); > > return ~(cycle_t)two & c->mask; I choosed a slightly different approach and printed just one time entry and o per line to simplify the awk script to check the output: cycle_t mxs_clocksource_mmio_readl_down(struct clocksource *c) { static atomic_t order; int o; u32 one; one = readl_relaxed(to_mmio_clksrc(c)->reg); o = atomic_add_return(1, &order); trace_printk("%d: time = 0x%08x, o=%d\n", __LINE__, one, o); one = readl_relaxed(to_mmio_clksrc(c)->reg); o = atomic_add_return(1, &order); trace_printk("%d: time = 0x%08x, o=%d\n", __LINE__, one, o); return ~(cycle_t)one & c->mask; } And indeed I see: mrp62439d-219 [000] ....... 126.832393: mxs_clocksource_mmio_readl_down: 36: time = 0x4a908d19, o=480635 mrp62439d-219 [000] ....... 126.832408: mxs_clocksource_mmio_readl_down: 39: time = 0x4a908afb, o=480636 mrp62439d-219 [000] d..h2.. 126.832883: mxs_clocksource_mmio_readl_down: 36: time = 0x4a905e4b, o=480638 mrp62439d-219 [000] d..h2.. 126.832890: mxs_clocksource_mmio_readl_down: 39: time = 0x4a905d9f, o=480639 mrp62439d-219 [000] d..h1.. 126.832908: mxs_clocksource_mmio_readl_down: 36: time = 0x4a905c05, o=480640 mrp62439d-219 [000] d..h1.. 126.832915: mxs_clocksource_mmio_readl_down: 39: time = 0x4a905b3a, o=480641 mrp62439d-219 [000] d..h2.. 126.832929: mxs_clocksource_mmio_readl_down: 36: time = 0x4a9059f6, o=480642 mrp62439d-219 [000] d..h2.. 126.832937: mxs_clocksource_mmio_readl_down: 39: time = 0x4a905927, o=480643 mrp62439d-219 [000] d..h1.. 126.833031: mxs_clocksource_mmio_readl_down: 36: time = 0x4a9050ee, o=480644 mrp62439d-219 [000] d..h1.. 126.833043: mxs_clocksource_mmio_readl_down: 39: time = 0x4a904f73, o=480645 mrp62439d-219 [000] ....... 126.833114: mxs_clocksource_mmio_readl_down: 36: time = 0x4a906479, o=480637 mrp62439d-219 [000] ....... 126.833124: mxs_clocksource_mmio_readl_down: 39: time = 0x4a9047ba, o=480646 But this can be explained by the hard irq interrupting between "o = .." and "trace_printk(..." above. Will retry with irq disabling, i.e. twice raw_local_irq_save(flags); one = readl_relaxed(to_mmio_clksrc(c)->reg); o = atomic_add_return(1, &mxs_order); trace_printk("%d: time = 0x%08x, o=%d\n", __LINE__, one, o); raw_local_irq_restore(flags); and report when I'm done. Thanks for your very valuable input, Uwe -- Pengutronix e.K. | Uwe Kleine-K?nig | Industrial Linux Solutions | http://www.pengutronix.de/ | ^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2018-09-07 10:00 UTC | newest] Thread overview: 6+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2018-09-06 20:02 Timer on i.MX28 moving backwards Uwe Kleine-König 2018-09-06 21:39 ` Russell King - ARM Linux 2018-09-07 7:21 ` Uwe Kleine-König 2018-09-07 8:38 ` Uwe Kleine-König 2018-09-07 9:08 ` Russell King - ARM Linux 2018-09-07 10:00 ` Uwe Kleine-König
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).