[linux-sunxi] Re: [PATCH 1/2] arm64: arch_timer: Workaround for Allwinner A64 timer instability

[André Przywara]

On 05/11/2018 03:27 AM, Samuel Holland wrote:
> The Allwinner A64 SoC is known [1] to have an unstable architectural
> timer, which manifests itself most obviously in the time jumping forward
> a multiple of 95 years [2][3]. This coincides with 2^56 cycles at a
> timer frequency of 24 MHz, implying that the time went slightly backward
> (and this was interpreted by the kernel as it jumping forward and
> wrapping around past the epoch).
> 
> Further investigation revealed instability in the low bits of CNTVCT at
> the point a high bit rolls over. This leads to power-of-two cycle
> forward and backward jumps. (Testing shows that forward jumps are about
> twice as likely as backward jumps.)
> 
> Without trapping reads to CNTVCT, a userspace program is able to read it
> in a loop faster than it changes. A test program running on all 4 CPU
> cores that reported jumps larger than 100 ms was run for 13.6 hours and
> reported the following:
> 
>  Count | Event
> ---+---
>   9940 | jumped backward  699ms
>268 | jumped backward 1398ms
>  1 | jumped backward 2097ms
>  16020 | jumped forward   175ms
>   6443 | jumped forward   699ms
>   2976 | jumped forward  1398ms
>  9 | jumped forward356516ms
>  9 | jumped forward357215ms
>  4 | jumped forward714430ms
>  1 | jumped forward   3578440ms
> 
> This works out to a jump larger than 100 ms about every 5.5 seconds on
> each CPU core.
> 
> The largest jump (almost an hour!) was the following sequence of reads:
>   0x007f → 0x0093feff → 0x0080
> 
> Note that the middle bits don't necessarily all read as all zeroes or
> all ones during the anomalous behavior; however the low 11 bits checked
> by the function in this patch have never been observed with any other
> value.
> 
> Also note that smaller jumps are much more common, with the smallest
> backward jumps of 2048 cycles observed over 400 times per second on each
> core. (Of course, this is partially due to lower bits rolling over more
> frequently.) Any one of these could have caused the 95 year time skip.
> 
> Similar anomalies were observed while reading CNTPCT (after patching the
> kernel to allow reads from userspace). However, the jumps are much less
> frequent, and only small jumps were observed. The same program as before
> (except now reading CNTPCT) observed after 72 hours:
> 
>  Count | Event
> ---+---
> 17 | jumped backward  699ms
> 52 | jumped forward   175ms
>   2831 | jumped forward   699ms
>  5 | jumped forward  1398ms
> 
> 
> 
> Because the CPU can read the CNTPCT/CNTVCT registers faster than they
> change, performing two reads of the register and comparing the high bits
> (like other workarounds) is not a workable solution. And because the
> timer can jump both forward and backward, no pair of reads can
> distinguish a good value from a bad one. The only way to guarantee a
> good value from consecutive reads would be to read _three_ times, and
> take the middle value iff the three values are 1) individually unique
> and 2) increasing. This takes at minimum 3 cycles (125 ns), or more if
> an anomaly is detected.
> 
> However, since there is a distinct pattern to the bad values, we can
> optimize the common case (2046/2048 of the time) to a single read by
> simply ignoring values that match the pattern. This still takes no more
> than 3 cycles in the worst case, and requires much less code.

Clever solution, and indeed much less costly than other workarounds.

FWIW, I tested this on a Pine64 and can confirm that it works.
I put a test program here:
https://github.com/apritzel/pine64/blob/master/tools/test_timer.c

This only checks for consecutive reads going backwards, but within a
split second yells on an unpatched kernel:
https://gist.github.com/apritzel/fc78ca6edb17be2024d5adfd35edb520

Applying the patch and adding the DT property fixed that for me.

I second Marc's request for an upper bound on the loop. Question is just
what we do when we reach the loop count limit?

But regardless, given that this fixes this nasty issue:

Tested-by: Andre Przywara 

Cheers,
Andre.

-- 
You received this message because you are subscribed to the Google Groups 
"linux-sunxi" group.
To unsubscribe from this group and stop receiving emails from it, send an email 
to linux-sunxi+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[linux-sunxi] Re: [PATCH 1/2] arm64: arch_timer: Workaround for Allwinner A64 timer instability

[Samuel Holland]

On 05/11/18 03:48, Marc Zyngier wrote:
> [+Mark, who co-maintains the arch timer code with me]
> 
> Hi Samuel,
> 
> On 11/05/18 03:27, Samuel Holland wrote:
>> The Allwinner A64 SoC is known [1] to have an unstable architectural
>> timer, which manifests itself most obviously in the time jumping forward
>> a multiple of 95 years [2][3]. This coincides with 2^56 cycles at a
>> timer frequency of 24 MHz, implying that the time went slightly backward
>> (and this was interpreted by the kernel as it jumping forward and
>> wrapping around past the epoch).
>>
>> Further investigation revealed instability in the low bits of CNTVCT at
>> the point a high bit rolls over. This leads to power-of-two cycle
>> forward and backward jumps. (Testing shows that forward jumps are about
>> twice as likely as backward jumps.)
>>
>> Without trapping reads to CNTVCT, a userspace program is able to read it
>> in a loop faster than it changes. A test program running on all 4 CPU
>> cores that reported jumps larger than 100 ms was run for 13.6 hours and
>> reported the following:
>>
>>  Count | Event
>> ---+---
>>   9940 | jumped backward  699ms
>>268 | jumped backward 1398ms
>>  1 | jumped backward 2097ms
>>  16020 | jumped forward   175ms
>>   6443 | jumped forward   699ms
>>   2976 | jumped forward  1398ms
>>  9 | jumped forward356516ms
>>  9 | jumped forward357215ms
>>  4 | jumped forward714430ms
>>  1 | jumped forward   3578440ms
>>
>> This works out to a jump larger than 100 ms about every 5.5 seconds on
>> each CPU core.
>>
>> The largest jump (almost an hour!) was the following sequence of reads:
>>   0x007f → 0x0093feff → 0x0080
>>
>> Note that the middle bits don't necessarily all read as all zeroes or
>> all ones during the anomalous behavior; however the low 11 bits checked
>> by the function in this patch have never been observed with any other
>> value.
>>
>> Also note that smaller jumps are much more common, with the smallest
>> backward jumps of 2048 cycles observed over 400 times per second on each
>> core. (Of course, this is partially due to lower bits rolling over more
>> frequently.) Any one of these could have caused the 95 year time skip.
>>
>> Similar anomalies were observed while reading CNTPCT (after patching the
>> kernel to allow reads from userspace). However, the jumps are much less
>> frequent, and only small jumps were observed. The same program as before
>> (except now reading CNTPCT) observed after 72 hours:
>>
>>  Count | Event
>> ---+---
>> 17 | jumped backward  699ms
>> 52 | jumped forward   175ms
>>   2831 | jumped forward   699ms
>>  5 | jumped forward  1398ms
>>
>> 
>>
>> Because the CPU can read the CNTPCT/CNTVCT registers faster than they
>> change, performing two reads of the register and comparing the high bits
>> (like other workarounds) is not a workable solution. And because the
>> timer can jump both forward and backward, no pair of reads can
>> distinguish a good value from a bad one. The only way to guarantee a
>> good value from consecutive reads would be to read _three_ times, and
>> take the middle value iff the three values are 1) individually unique
>> and 2) increasing. This takes at minimum 3 cycles (125 ns), or more if
>> an anomaly is detected.
>>
>> However, since there is a distinct pattern to the bad values, we can
>> optimize the common case (2046/2048 of the time) to a single read by
>> simply ignoring values that match the pattern. This still takes no more
>> than 3 cycles in the worst case, and requires much less code.
> 
> Thanks for the thorough description of the problem. A couple of questions:
> 
> - Have the 000/7ff values of the bottom bits only been experimentally
> found? Or do you have more concrete evidence of this is what happens in
> the HW?

Only experimentally found. Here's a sample of the larger jumps:

CPU 3: 0x00a5ebff → 0x00a5edff (retry = 0x00a5ec00)
CPU 1: 0x00a5ebff → 0x00a5edff (retry = 0x00a5ec00)
CPU 1: 0x00a5ecff > 0x00a5ec00 (retry = 0x00a5ed00)
CPU 0: 0x00a5eeff > 0x00a5ee00 (retry = 0x00a5ef00)
CPU 2: 0x00a5f0bf → 0x00a5f0ff (retry = 0x00a5f0c0)
CPU 0: 0x00a5f0ff > 0x00a5f000 (retry = 0x00a5f100)
CPU 2: 0x00a5f3ff > 0x00a5f200 (retry = 0x00a5f400)
CPU 0: 0x00a5f6ff > 0x00a5f600 (retry = 0x00a5f700)
CPU 1: 0x00a5fbbf → 0x00a5fbff (retry = 0x00a5fbc0)
CPU 0: 0x00a5fdff → 0x00a5feff (retry = 0x00a5fe00)
CPU 2: 0x00a5 → 0x00a7fe00 (retry = 0x00a6)
CPU 3: 0x00a5 → 0x00a7fe00 (retry = 0x00a6)
CPU 

[linux-sunxi] Re: [PATCH 1/2] arm64: arch_timer: Workaround for Allwinner A64 timer instability

[Marc Zyngier]

[+Mark, who co-maintains the arch timer code with me]

Hi Samuel,

On 11/05/18 03:27, Samuel Holland wrote:
> The Allwinner A64 SoC is known [1] to have an unstable architectural
> timer, which manifests itself most obviously in the time jumping forward
> a multiple of 95 years [2][3]. This coincides with 2^56 cycles at a
> timer frequency of 24 MHz, implying that the time went slightly backward
> (and this was interpreted by the kernel as it jumping forward and
> wrapping around past the epoch).
> 
> Further investigation revealed instability in the low bits of CNTVCT at
> the point a high bit rolls over. This leads to power-of-two cycle
> forward and backward jumps. (Testing shows that forward jumps are about
> twice as likely as backward jumps.)
> 
> Without trapping reads to CNTVCT, a userspace program is able to read it
> in a loop faster than it changes. A test program running on all 4 CPU
> cores that reported jumps larger than 100 ms was run for 13.6 hours and
> reported the following:
> 
>  Count | Event
> ---+---
>   9940 | jumped backward  699ms
>268 | jumped backward 1398ms
>  1 | jumped backward 2097ms
>  16020 | jumped forward   175ms
>   6443 | jumped forward   699ms
>   2976 | jumped forward  1398ms
>  9 | jumped forward356516ms
>  9 | jumped forward357215ms
>  4 | jumped forward714430ms
>  1 | jumped forward   3578440ms
> 
> This works out to a jump larger than 100 ms about every 5.5 seconds on
> each CPU core.
> 
> The largest jump (almost an hour!) was the following sequence of reads:
>   0x007f → 0x0093feff → 0x0080
> 
> Note that the middle bits don't necessarily all read as all zeroes or
> all ones during the anomalous behavior; however the low 11 bits checked
> by the function in this patch have never been observed with any other
> value.
> 
> Also note that smaller jumps are much more common, with the smallest
> backward jumps of 2048 cycles observed over 400 times per second on each
> core. (Of course, this is partially due to lower bits rolling over more
> frequently.) Any one of these could have caused the 95 year time skip.
> 
> Similar anomalies were observed while reading CNTPCT (after patching the
> kernel to allow reads from userspace). However, the jumps are much less
> frequent, and only small jumps were observed. The same program as before
> (except now reading CNTPCT) observed after 72 hours:
> 
>  Count | Event
> ---+---
> 17 | jumped backward  699ms
> 52 | jumped forward   175ms
>   2831 | jumped forward   699ms
>  5 | jumped forward  1398ms
> 
> 
> 
> Because the CPU can read the CNTPCT/CNTVCT registers faster than they
> change, performing two reads of the register and comparing the high bits
> (like other workarounds) is not a workable solution. And because the
> timer can jump both forward and backward, no pair of reads can
> distinguish a good value from a bad one. The only way to guarantee a
> good value from consecutive reads would be to read _three_ times, and
> take the middle value iff the three values are 1) individually unique
> and 2) increasing. This takes at minimum 3 cycles (125 ns), or more if
> an anomaly is detected.
> 
> However, since there is a distinct pattern to the bad values, we can
> optimize the common case (2046/2048 of the time) to a single read by
> simply ignoring values that match the pattern. This still takes no more
> than 3 cycles in the worst case, and requires much less code.

Thanks for the thorough description of the problem. A couple of questions:

- Have the 000/7ff values of the bottom bits only been experimentally
found? Or do you have more concrete evidence of this is what happens in
the HW?

- Do you have an official erratum number from the silicon vendor, so
that Documentation/arm64/silicon-errata.txt can be kept up to date?

> 
> [1]: https://github.com/armbian/build/commit/a08cd6fe7ae9
> [2]: https://forum.armbian.com/topic/3458-a64-datetime-clock-issue/
> [3]: https://irclog.whitequark.org/linux-sunxi/2018-01-26
> 
> Signed-off-by: Samuel Holland 
> ---
>  drivers/clocksource/Kconfig  | 11 ++
>  drivers/clocksource/arm_arch_timer.c | 39 
> 
>  2 files changed, 50 insertions(+)
> 
> diff --git a/drivers/clocksource/Kconfig b/drivers/clocksource/Kconfig
> index 8e8a09755d10..7a5d434dd30b 100644
> --- a/drivers/clocksource/Kconfig
> +++ b/drivers/clocksource/Kconfig
> @@ -364,6 +364,17 @@ config ARM64_ERRATUM_858921
> The workaround will be dynamically enabled when an affected
> core is detected.
>  
> +config SUN50I_A64_UNSTABLE_TIMER
> + bool "Workaround for Allwinner A64 timer instability"
> + default y
> + depends on ARM_ARCH_TIMER && ARM64 && ARCH_SUNXI
> + select