Re: [patch 2/2] timekeeping: Always check for negative motion

[Guenter Roeck <linux@roeck-us.net>]

On 11/28/24 06:51, Thomas Gleixner wrote:
> On Wed, Nov 27 2024 at 15:02, Guenter Roeck wrote:
>> On 11/27/24 14:08, John Stultz wrote:
>> An example log is at [1]. It says
>>
>> clocksource: npcm7xx-timer1: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 597268854 ns
> 
> That's a 24bit counter. So negative motion happens when the readouts are
> more than (1 << 23) apart. AFAICT the counter runs with about 14MHz, but
> I'd like to have that confirmed.
> 
>> clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
>> ...
>> clocksource: Switched to clocksource npcm7xx-timer1
>>
>> I don't know where exactly it stalls; sometime after handover to userspace.
>> I'll be happy to do some more debugging, but you'll nee to let me know what
>> to look for.
> 
> On that platform max_idle_ns should correspond to 50% of the counter
> width. So if both CPUs go deep idle for max_idle_ns, then the next timer
> interrupt doing the timeeeping advancement sees a delta of > (1 << 23)
> and timekeeping stalls.
> 
> If my ssumption is correct, then the below should fix it.
> 
Unfortunately not, it just makes things worse and stalls earlier.

[    2.080000] Fusion MPT SAS Host driver 3.04.20
[    2.080000] npcm7xx-ehci f0806000.usb: EHCI Host Controller
[    2.080000] npcm7xx-ehci f0806000.usb: new USB bus registered, assigned bus number 1
[    2.080000] npcm7xx-ehci f0806000.usb: irq 39, io mem 0xf0806000
qemu-system-arm: terminating on signal 15 from pid 17184 (/bin/bash)

There is something else going on. I reverted the offending patch and
added

+       pr_warn("###### now: %llx last: %llx mask: %llx return: %llx", now, last, mask, (now - last) & mask);

into clocksource_delta(). Here is what I get:

...
[    3.310000] ###### now: f8c502 last: f6c964 mask: ffffff return: 1fb9e
[    3.320000] ###### now: fbc513 last: f8b1ac mask: ffffff return: 31367
[    3.330000] ###### now: fd368d last: fa99f4 mask: ffffff return: 29c99
[    3.340000] ###### now: ffe8b3 last: fc823c mask: ffffff return: 36677
[    3.350000] ###### now: 6c4f last: fe6a84 mask: ffffff return: 201cb      <---
[    3.360000] ###### now: 40427 last: 10052cc mask: ffffff return: 3b15b    <---
[    3.370000] ###### now: 43bfe last: 1023b14 mask: ffffff return: 200ea
[    3.380000] ###### now: 6f438 last: 104235c mask: ffffff return: 2d0dc
[    3.390000] ###### now: 8e9a3 last: 1060ba4 mask: ffffff return: 2ddff
[    3.400000] ###### now: ac9d3 last: 107f3ec mask: ffffff return: 2d5e7
[    3.410000] ###### now: cb9b4 last: 109dc34 mask: ffffff return: 2dd80
[    3.420000] ###### now: e9ba2 last: 10bc47c mask: ffffff return: 2d726
[    3.430000] ###### now: 108994 last: 10dacc4 mask: ffffff return: 2dcd0
[    3.440000] ###### now: 1200a0 last: 10f950c mask: ffffff return: 26b94
[    3.450000] ###### now: 14c55f last: 1117d54 mask: ffffff return: 3480b
[    3.460000] ###### now: 15d43a last: 113659c mask: ffffff return: 26e9e
...
[   18.100000] ###### now: f8c39f last: ceea990 mask: ffffff return: a1a0f
[   18.290000] ###### now: 1d01af last: cf832f8 mask: ffffff return: 24ceb7
[   18.500000] ###### now: 45b0a2 last: d1c7050 mask: ffffff return: 294052
[   19.090000] ###### now: b5ac62 last: d447e38 mask: ffffff return: 712e2a
[   19.110000] ###### now: b9ebc3 last: db506d0 mask: ffffff return: 4e4f3
[   19.120000] ###### now: bb842f last: db8d760 mask: ffffff return: 2accf
[   19.160000] ###### now: c43f2e last: dbabfa8 mask: ffffff return: 97f86

'last' advances beyond 'mask', and after that the result is always bad. The call to
clocksource_delta() is from timekeeping_advance().

Guenter