Re: [PATCH] clocksource: Make clocksource watchdog check with WATCHDOG_INTERVAL period

[Waiman Long <longman@redhat.com>]

On 5/29/22 20:43, Michael Larabel wrote:
>
> On 5/29/22 19:16, Waiman Long wrote:
>> On 5/29/22 18:16, Michael Larabel wrote:
>>> On 5/27/22 21:07, Waiman Long wrote:
>>>> On 5/27/22 21:57, Waiman Long wrote:
>>>>> Since commit c86ff8c55b8a ("clocksource: Avoid accidental unstable
>>>>> marking of clocksource"), a new WD_READ_SKIP value was introduced
>>>>> as a possible return value of cs_watchdog_read() to skip the current
>>>>> check. However, this has an undesriable side effect of extending the
>>>>> time gap between csnow and cs_last to more than one WATCHDOG_INTERVAL
>>>>> (0.5s) in case of intermittent WD_READ_SKIP's.
>>>>>
>>>>> There was an instance of reported clocksource watchdog failure with
>>>>> the time skew of 485us where the uncertainly threshold is 400us. In
>>>>> that particular case, the (now - last) gap was about 2s. Looking at
>>>>> the dmesg log, it was clear there was a successful cs_watchdog_read()
>>>>> followed by 3 skips and then another successful cs_watchdog_read().
>>>>>
>>>>> If there is an existing skew between the hpet (watchdog) and tsc
>>>>> clocksource, enlarging the period by 4x will certainly increase the
>>>>> measured skew causing it to exceed the threshold in this case. Fix
>>>>> this variable period problem by resetting the 
>>>>> CLOCK_SOURCE_WATCHDOG bit
>>>>> after each WD_READ_SKIP to force the reloading of wd_last and cs_last
>>>>> in the next round. This ensures that we have two consecutive 
>>>>> successful
>>>>> cs_watchdog_read()'s before checking the clock skew.
>>>>>
>>>>> Fixes: c86ff8c55b8a ("clocksource: Avoid accidental unstable 
>>>>> marking of clocksource")
>>>>> Reported-by: Michael Larabel <Michael@phoronix.com>
>>>>> Signed-off-by: Waiman Long <longman@redhat.com>
>>>>> ---
>>>>>   kernel/time/clocksource.c | 11 ++++++++++-
>>>>>   1 file changed, 10 insertions(+), 1 deletion(-)
>>>>>
>>>>> diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
>>>>> index cee5da1e54c4..173e052c12b6 100644
>>>>> --- a/kernel/time/clocksource.c
>>>>> +++ b/kernel/time/clocksource.c
>>>>> @@ -411,9 +411,18 @@ static void clocksource_watchdog(struct 
>>>>> timer_list *unused)
>>>>>           read_ret = cs_watchdog_read(cs, &csnow, &wdnow);
>>>>>             if (read_ret != WD_READ_SUCCESS) {
>>>>> -            if (read_ret == WD_READ_UNSTABLE)
>>>>> +            if (read_ret == WD_READ_UNSTABLE) {
>>>>>                   /* Clock readout unreliable, so give it up. */
>>>>>                   __clocksource_unstable(cs);
>>>>> +            } else { /* WD_READ_SKIP */
>>>>> +                /*
>>>>> +                 * Watchdog clock unstable at the moment,
>>>>> +                 * discard the stored wd_last and cs_last to
>>>>> +                 * make sure the gap between now and last
>>>>> +                 * is always one WATCHDOG_INTERVAL.
>>>>> +                 */
>>>>> +                cs->flags &= ~CLOCK_SOURCE_WATCHDOG;
>>>>> +            }
>>>>>               continue;
>>>>>           }
>>>>
>>>> Sorry, I accidentally use the old email address for John.
>>>>
>>>> Cheers,
>>>> Longman
>>>
>>>
>>> I've tested this patch on the affected Daytona + Milan-X system and 
>>> can confirm it does fix the performance problem that led to this 
>>> issue. Though it is spamming the kernel log now every half-second 
>>> with clocksource messages,  not sure if that is intended/desirable 
>>> behavior?
>>>
>>>
>>> [    0.000000] tsc: Fast TSC calibration using PIT
>>> [    0.000000] tsc: Detected 2195.990 MHz processor
>>> [    1.238759] clocksource: tsc-early: mask: 0xffffffffffffffff 
>>> max_cycles: 0x1fa766bc6ba, max_idle_ns: 440795275714 ns
>>> [    2.769608] clocksource: Switched to clocksource tsc-early
>>> [    3.263925] clocksource: wd-tsc-early-wd read-back delay of 
>>> 292215ns, clock-skew test skipped!
>>> [    3.743804] clocksource: wd-tsc-early-wd read-back delay of 
>>> 268469ns, clock-skew test skipped!
>>> [    3.935663] tsc: Refined TSC clocksource calibration: 2195.274 MHz
>>> [    3.935844] clocksource: tsc: mask: 0xffffffffffffffff 
>>> max_cycles: 0x1fa4c255513, max_idle_ns: 440795289702 ns
>>> [    3.936449] clocksource: Switched to clocksource tsc
>>> [    4.255932] clocksource: wd-tsc-wd read-back delay of 260228ns, 
>>> clock-skew test skipped!
>>> [    4.767892] clocksource: wd-tsc-wd read-back delay of 272520ns, 
>>> clock-skew test skipped!
>>> [    5.247581] clocksource: wd-tsc-wd read-back delay of 200444ns, 
>>> clock-skew test skipped!
>>> [    5.759560] clocksource: wd-tsc-wd read-back delay of 165942ns, 
>>> clock-skew test skipped!
>>> [    6.239687] clocksource: wd-tsc-wd read-back delay of 232222ns, 
>>> clock-skew test skipped!
>>> [    7.264014] clocksource: wd-tsc-wd read-back delay of 282927ns, 
>>> clock-skew test skipped!
>>> [    7.743864] clocksource: wd-tsc-wd read-back delay of 288374ns, 
>>> clock-skew test skipped!
>>> [    8.255590] clocksource: wd-tsc-wd read-back delay of 206730ns, 
>>> clock-skew test skipped!
>>> [    8.767778] clocksource: wd-tsc-wd read-back delay of 267771ns, 
>>> clock-skew test skipped!
>>> [    9.247870] clocksource: wd-tsc-wd read-back delay of 224469ns, 
>>> clock-skew test skipped!
>>> [   10.239340] clocksource: wd-tsc-wd read-back delay of 109720ns, 
>>> clock-skew test skipped!
>>> [   12.255276] clocksource: wd-tsc-wd read-back delay of 104692ns, 
>>> clock-skew test skipped!
>>> [   16.255362] clocksource: wd-tsc-wd read-back delay of 122780ns, 
>>> clock-skew test skipped!
>>> [   17.759335] clocksource: wd-tsc-wd read-back delay of 155885ns, 
>>> clock-skew test skipped!
>>> [   18.239500] clocksource: wd-tsc-wd read-back delay of 176558ns, 
>>> clock-skew test skipped!
>>> [   18.751341] clocksource: wd-tsc-wd read-back delay of 157352ns, 
>>> clock-skew test skipped!
>>> [   19.263618] clocksource: wd-tsc-wd read-back delay of 177606ns, 
>>> clock-skew test skipped!
>>> [   19.743487] clocksource: wd-tsc-wd read-back delay of 157841ns, 
>>> clock-skew test skipped!
>>> [   20.255482] clocksource: wd-tsc-wd read-back delay of 157701ns, 
>>> clock-skew test skipped!
>>> [   20.767634] clocksource: wd-tsc-wd read-back delay of 173136ns, 
>>> clock-skew test skipped!
>>> [   21.247405] clocksource: wd-tsc-wd read-back delay of 175441ns, 
>>> clock-skew test skipped!
>>> ...
>>>
>>> Thanks,
>>> Michael
>>>
>> Thanks for the testing. Did the spamming stop after a while?
>>
>> It does show that your particular Milan-X CPU(s) have unreliable 
>> hpet. The only way to stop the spamming is to build a kernel with a 
>> larger CONFIG_CLOCKSOURCE_WATCHDOG_MAX_SKEW_US. By default, it is 
>> 100us. The allowable hpet-hpet delay is only half of that. In this 
>> particular case, it will have to be set to at least 500 or maybe even 
>> 600.
>>
>> Thanks,
>> Longman
>>
>
> No, the spamming hadn't stopped. At least as of one hour into the 
> uptime it was still spewing every half second. Can confirm tomorrow if 
> it ever stops after a longer duration but at least as of one hour of 
> running the benchmarks to verify the performance was back to 
> expectations, I had shut down that server to move onto other work.

With my past experience, hpet read will slow down significantly when the 
system is running a very cpu intensive workload leading to cpu being 
under thermal stress. Benchmarking is certainly an activity that may 
trigger this problem. However, they usually go away when the cpus are 
not at 100% load anymore and the system can cool down.

If this still happens at idle, there is definitely something wrong with 
the cpus. I don't think we have Milan system internally that can 
reproduce this problem at the moment. However Milan-X has HBM memory 
chiplets on top of the cpu chiplets. That may make heat dissipation 
harder and exacerbate this hpet problem.

Thanks,
Longman