A couple of TSC questions

A couple of TSC questions

[Paul E. McKenney]

Hello, Feng!

I hope that things are going well for you and yours!

First, given that the kernel can now kick out HPET instea of TSC in
response to clock skew, does it make sense to permit recalibration of
the still used TSC against the marked-unstable HPET?

Second, we are very occasionally running into console messages like this:

Measured 2 cycles TSC warp between CPUs, turning off TSC clock.

This comes from check_tsc_sync_source() and indicates that one CPU's
TSC read produced a later time than a later read from some other CPU.
I am beginning to suspect that these can be caused by unscheduled delays
in the TSC synchronization code, but figured I should ask you if you have
ever seen these.  And of course, if so, what the usual causes might be.

Thoughts?

							Thanx, Paul

Re: A couple of TSC questions

[Feng Tang]

Hi, Paul

On Tue, Mar 21, 2023 at 04:23:28PM -0700, Paul E. McKenney wrote:
> Hello, Feng!
> 
> I hope that things are going well for you and yours!

Thanks!

> First, given that the kernel can now kick out HPET instea of TSC in
> response to clock skew, does it make sense to permit recalibration of
> the still used TSC against the marked-unstable HPET?

Yes, it makes sense to me. I don't know the detail of the case, if
the TSC frequency comes from CPUID info, a recalibration against a
third party HW timer like ACPI_PM should help here. 

A further thought is if there are really quite some case that the
CPUID-provided TSC frequency info is not accurate, then we may need
to enable the recalibration by default, and give a warning message
when detecting any mismatch. 

> Second, we are very occasionally running into console messages like this:
> 
> Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
> 
> This comes from check_tsc_sync_source() and indicates that one CPU's
> TSC read produced a later time than a later read from some other CPU.
> I am beginning to suspect that these can be caused by unscheduled delays
> in the TSC synchronization code, but figured I should ask you if you have
> ever seen these.  And of course, if so, what the usual causes might be.

I haven't seen this error myself or got similar reports. Usually it
should be easy to detect once happened, as falling back to HPET
will trigger obvious performance degradation.

Could you give more detail about when and how it happens, and the
HW info like how many sockets the platform has. 

CC Thomas, Waiman, as they discussed simliar case here:
https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f

Thanks,
Feng

> Thoughts?
> 
> 							Thanx, Paul

Re: A couple of TSC questions

[Paul E. McKenney]

On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:
> Hi, Paul
> 
> On Tue, Mar 21, 2023 at 04:23:28PM -0700, Paul E. McKenney wrote:
> > Hello, Feng!
> > 
> > I hope that things are going well for you and yours!
> 
> Thanks!
> 
> > First, given that the kernel can now kick out HPET instea of TSC in
> > response to clock skew, does it make sense to permit recalibration of
> > the still used TSC against the marked-unstable HPET?
> 
> Yes, it makes sense to me. I don't know the detail of the case, if
> the TSC frequency comes from CPUID info, a recalibration against a
> third party HW timer like ACPI_PM should help here. 
> 
> A further thought is if there are really quite some case that the
> CPUID-provided TSC frequency info is not accurate, then we may need
> to enable the recalibration by default, and give a warning message
> when detecting any mismatch. 

Now that you mention it, it is quite hard to choose correctly within
the kernel.  To do it right seems to require that NTP information be
pushed into the kernel.

> > Second, we are very occasionally running into console messages like this:
> > 
> > Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
> > 
> > This comes from check_tsc_sync_source() and indicates that one CPU's
> > TSC read produced a later time than a later read from some other CPU.
> > I am beginning to suspect that these can be caused by unscheduled delays
> > in the TSC synchronization code, but figured I should ask you if you have
> > ever seen these.  And of course, if so, what the usual causes might be.
> 
> I haven't seen this error myself or got similar reports. Usually it
> should be easy to detect once happened, as falling back to HPET
> will trigger obvious performance degradation.

And that is exactly what happened.  ;-)

> Could you give more detail about when and how it happens, and the
> HW info like how many sockets the platform has. 

We are in early days, so I am checking for other experiences.

> CC Thomas, Waiman, as they discussed simliar case here:
> https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f

Fun!  ;-)

							Thanx, Paul

Re: A couple of TSC questions

[Feng Tang]

On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
> On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:
> > Hi, Paul
> > 
> > On Tue, Mar 21, 2023 at 04:23:28PM -0700, Paul E. McKenney wrote:
> > > Hello, Feng!
> > > 
> > > I hope that things are going well for you and yours!
> > 
> > Thanks!
> > 
> > > First, given that the kernel can now kick out HPET instea of TSC in
> > > response to clock skew, does it make sense to permit recalibration of
> > > the still used TSC against the marked-unstable HPET?
> > 
> > Yes, it makes sense to me. I don't know the detail of the case, if
> > the TSC frequency comes from CPUID info, a recalibration against a
> > third party HW timer like ACPI_PM should help here. 
> > 
> > A further thought is if there are really quite some case that the
> > CPUID-provided TSC frequency info is not accurate, then we may need
> > to enable the recalibration by default, and give a warning message
> > when detecting any mismatch. 
> 
> Now that you mention it, it is quite hard to choose correctly within
> the kernel.  To do it right seems to require that NTP information be
> pushed into the kernel.

Yes, we need a 'always-right' reference, but the system have to has
network access.

I know there have been many different problems related to TSC, but
the real HW/FW related problems are only about the accuracy of
TSC frequency's calibration/calculation.

Before commit b50db7095fe0 ("x86/tsc: Disable clocksource watchdog
for TSC on qualified platorms"), if the TSC freq is calculated
from CPUID or MSR, the HPET/ACPI_PM_TIMER can detect the possible
calculation problem during clocksource watchdog check. For this
case, we may need to force the recalibration by HPET/ACPI_PM_TIMER.

Thanks,
Feng

> 
> > > Second, we are very occasionally running into console messages like this:
> > > 
> > > Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
> > > 
> > > This comes from check_tsc_sync_source() and indicates that one CPU's
> > > TSC read produced a later time than a later read from some other CPU.
> > > I am beginning to suspect that these can be caused by unscheduled delays
> > > in the TSC synchronization code, but figured I should ask you if you have
> > > ever seen these.  And of course, if so, what the usual causes might be.
> > 
> > I haven't seen this error myself or got similar reports. Usually it
> > should be easy to detect once happened, as falling back to HPET
> > will trigger obvious performance degradation.
> 
> And that is exactly what happened.  ;-)
> 
> > Could you give more detail about when and how it happens, and the
> > HW info like how many sockets the platform has. 
> 
> We are in early days, so I am checking for other experiences.
> 
> > CC Thomas, Waiman, as they discussed simliar case here:
> > https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f
> 
> Fun!  ;-)
> 
> 							Thanx, Paul

Re: A couple of TSC questions

[Paul E. McKenney]

On Mon, Mar 27, 2023 at 10:19:54AM +0800, Feng Tang wrote:
> On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
> > On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:
> > > Hi, Paul
> > > 
> > > On Tue, Mar 21, 2023 at 04:23:28PM -0700, Paul E. McKenney wrote:
> > > > Hello, Feng!
> > > > 
> > > > I hope that things are going well for you and yours!
> > > 
> > > Thanks!
> > > 
> > > > First, given that the kernel can now kick out HPET instea of TSC in
> > > > response to clock skew, does it make sense to permit recalibration of
> > > > the still used TSC against the marked-unstable HPET?
> > > 
> > > Yes, it makes sense to me. I don't know the detail of the case, if
> > > the TSC frequency comes from CPUID info, a recalibration against a
> > > third party HW timer like ACPI_PM should help here. 
> > > 
> > > A further thought is if there are really quite some case that the
> > > CPUID-provided TSC frequency info is not accurate, then we may need
> > > to enable the recalibration by default, and give a warning message
> > > when detecting any mismatch. 
> > 
> > Now that you mention it, it is quite hard to choose correctly within
> > the kernel.  To do it right seems to require that NTP information be
> > pushed into the kernel.
> 
> Yes, we need a 'always-right' reference, but the system have to has
> network access.
> 
> I know there have been many different problems related to TSC, but
> the real HW/FW related problems are only about the accuracy of
> TSC frequency's calibration/calculation.
> 
> Before commit b50db7095fe0 ("x86/tsc: Disable clocksource watchdog
> for TSC on qualified platorms"), if the TSC freq is calculated
> from CPUID or MSR, the HPET/ACPI_PM_TIMER can detect the possible
> calculation problem during clocksource watchdog check. For this
> case, we may need to force the recalibration by HPET/ACPI_PM_TIMER.

Agreed, one possible assumption is that TSC, HPET, and ACPI_PM_TIMER
are very unlikely to be in error in exactly the same way.

> > > > Second, we are very occasionally running into console messages like this:
> > > > 
> > > > Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
> > > > 
> > > > This comes from check_tsc_sync_source() and indicates that one CPU's
> > > > TSC read produced a later time than a later read from some other CPU.
> > > > I am beginning to suspect that these can be caused by unscheduled delays
> > > > in the TSC synchronization code, but figured I should ask you if you have
> > > > ever seen these.  And of course, if so, what the usual causes might be.
> > > 
> > > I haven't seen this error myself or got similar reports. Usually it
> > > should be easy to detect once happened, as falling back to HPET
> > > will trigger obvious performance degradation.
> > 
> > And that is exactly what happened.  ;-)
> > 
> > > Could you give more detail about when and how it happens, and the
> > > HW info like how many sockets the platform has. 
> > 
> > We are in early days, so I am checking for other experiences.
> > 
> > > CC Thomas, Waiman, as they discussed simliar case here:
> > > https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f
> > 
> > Fun!  ;-)

Waiman, do you recall what fraction of the benefit was provided by the
first patch, that is, the one that grouped the sync_lock, last_tsc,
max_warp, nr_warps, and random_warps global variables into a single
struct?

							Thanx, Paul

Re: A couple of TSC questions

[Paul E. McKenney]

On Tue, Mar 28, 2023 at 02:58:54PM -0700, Paul E. McKenney wrote:
> On Mon, Mar 27, 2023 at 10:19:54AM +0800, Feng Tang wrote:
> > On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
> > > On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:

[ . . . ]

> > > > > Second, we are very occasionally running into console messages like this:
> > > > > 
> > > > > Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
> > > > > 
> > > > > This comes from check_tsc_sync_source() and indicates that one CPU's
> > > > > TSC read produced a later time than a later read from some other CPU.
> > > > > I am beginning to suspect that these can be caused by unscheduled delays
> > > > > in the TSC synchronization code, but figured I should ask you if you have
> > > > > ever seen these.  And of course, if so, what the usual causes might be.
> > > > 
> > > > I haven't seen this error myself or got similar reports. Usually it
> > > > should be easy to detect once happened, as falling back to HPET
> > > > will trigger obvious performance degradation.
> > > 
> > > And that is exactly what happened.  ;-)
> > > 
> > > > Could you give more detail about when and how it happens, and the
> > > > HW info like how many sockets the platform has. 
> > > 
> > > We are in early days, so I am checking for other experiences.
> > > 
> > > > CC Thomas, Waiman, as they discussed simliar case here:
> > > > https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f
> > > 
> > > Fun!  ;-)
> 
> Waiman, do you recall what fraction of the benefit was provided by the
> first patch, that is, the one that grouped the sync_lock, last_tsc,
> max_warp, nr_warps, and random_warps global variables into a single
> struct?

And what we are seeing is unlikely to be due to cache-latency-induced
delays.  We see a very precise warp, for example, one system always
has 182 cycles of TSC warp, another 273 cycles, and a third 469 cycles.
Another is at the insanely large value of about 2^64/10, and shows some
variation, but that variation is only about 0.1%.

But any given system only sees warp on about half of its reboots.
Perhaps due to the automation sometimes power cycling?

There are few enough affected systems that investigation will take
some time.

							Thanx, Paul

Re: A couple of TSC questions

[Waiman Long]

On 3/31/23 13:16, Paul E. McKenney wrote:
> On Tue, Mar 28, 2023 at 02:58:54PM -0700, Paul E. McKenney wrote:
>> On Mon, Mar 27, 2023 at 10:19:54AM +0800, Feng Tang wrote:
>>> On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
>>>> On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:
> [ . . . ]
>
>>>>>> Second, we are very occasionally running into console messages like this:
>>>>>>
>>>>>> Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
>>>>>>
>>>>>> This comes from check_tsc_sync_source() and indicates that one CPU's
>>>>>> TSC read produced a later time than a later read from some other CPU.
>>>>>> I am beginning to suspect that these can be caused by unscheduled delays
>>>>>> in the TSC synchronization code, but figured I should ask you if you have
>>>>>> ever seen these.  And of course, if so, what the usual causes might be.
>>>>> I haven't seen this error myself or got similar reports. Usually it
>>>>> should be easy to detect once happened, as falling back to HPET
>>>>> will trigger obvious performance degradation.
>>>> And that is exactly what happened.  ;-)
>>>>
>>>>> Could you give more detail about when and how it happens, and the
>>>>> HW info like how many sockets the platform has.
>>>> We are in early days, so I am checking for other experiences.
>>>>
>>>>> CC Thomas, Waiman, as they discussed simliar case here:
>>>>> https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f
>>>> Fun!  ;-)
>> Waiman, do you recall what fraction of the benefit was provided by the
>> first patch, that is, the one that grouped the sync_lock, last_tsc,
>> max_warp, nr_warps, and random_warps global variables into a single
>> struct?

The purpose of the first patch is just to avoid false cacheline sharing 
between the watchdog cpu and another cpu that happens to access a nearby 
data in the same cacheline.

Now I realize that I should have followed up with this patch series. The 
problem reported in that patch series happen on one system only, I believe.

> And what we are seeing is unlikely to be due to cache-latency-induced
> delays.  We see a very precise warp, for example, one system always
> has 182 cycles of TSC warp, another 273 cycles, and a third 469 cycles.
> Another is at the insanely large value of about 2^64/10, and shows some
> variation, but that variation is only about 0.1%.
>
> But any given system only sees warp on about half of its reboots.
> Perhaps due to the automation sometimes power cycling?
>
> There are few enough affected systems that investigation will take
> some time.

Maybe the difference in wrap is due to NUMA distance of the running cpu 
from the node where the data reside. It will be interesting to see if my 
patch helps.

Cheers,
Longman

Re: A couple of TSC questions

[Paul E. McKenney]

On Sun, Apr 02, 2023 at 09:04:04PM -0400, Waiman Long wrote:
> 
> On 3/31/23 13:16, Paul E. McKenney wrote:
> > On Tue, Mar 28, 2023 at 02:58:54PM -0700, Paul E. McKenney wrote:
> > > On Mon, Mar 27, 2023 at 10:19:54AM +0800, Feng Tang wrote:
> > > > On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
> > > > > On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:
> > [ . . . ]
> > 
> > > > > > > Second, we are very occasionally running into console messages like this:
> > > > > > > 
> > > > > > > Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
> > > > > > > 
> > > > > > > This comes from check_tsc_sync_source() and indicates that one CPU's
> > > > > > > TSC read produced a later time than a later read from some other CPU.
> > > > > > > I am beginning to suspect that these can be caused by unscheduled delays
> > > > > > > in the TSC synchronization code, but figured I should ask you if you have
> > > > > > > ever seen these.  And of course, if so, what the usual causes might be.
> > > > > > I haven't seen this error myself or got similar reports. Usually it
> > > > > > should be easy to detect once happened, as falling back to HPET
> > > > > > will trigger obvious performance degradation.
> > > > > And that is exactly what happened.  ;-)
> > > > > 
> > > > > > Could you give more detail about when and how it happens, and the
> > > > > > HW info like how many sockets the platform has.
> > > > > We are in early days, so I am checking for other experiences.
> > > > > 
> > > > > > CC Thomas, Waiman, as they discussed simliar case here:
> > > > > > https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f
> > > > > Fun!  ;-)
> > > Waiman, do you recall what fraction of the benefit was provided by the
> > > first patch, that is, the one that grouped the sync_lock, last_tsc,
> > > max_warp, nr_warps, and random_warps global variables into a single
> > > struct?
> 
> The purpose of the first patch is just to avoid false cacheline sharing
> between the watchdog cpu and another cpu that happens to access a nearby
> data in the same cacheline.
> 
> Now I realize that I should have followed up with this patch series. The
> problem reported in that patch series happen on one system only, I believe.

Thus far I am seeing eight systems, but out of a large number.  So this
is very much preliminary.

> > And what we are seeing is unlikely to be due to cache-latency-induced
> > delays.  We see a very precise warp, for example, one system always
> > has 182 cycles of TSC warp, another 273 cycles, and a third 469 cycles.
> > Another is at the insanely large value of about 2^64/10, and shows some
> > variation, but that variation is only about 0.1%.
> > 
> > But any given system only sees warp on about half of its reboots.
> > Perhaps due to the automation sometimes power cycling?
> > 
> > There are few enough affected systems that investigation will take
> > some time.
> 
> Maybe the difference in wrap is due to NUMA distance of the running cpu from
> the node where the data reside. It will be interesting to see if my patch
> helps.

Almost all of them are single-socket systems.

If the problem sticks with a few systems, I should be able to test
patches no problem.  If it is randomly distributed across the fleet, a
bit more prework analysis will be called for.  But what is life without
a challenge?  ;-)

							Thanx, Paul

Re: A couple of TSC questions

[Waiman Long]

On 4/2/23 22:00, Paul E. McKenney wrote:
> On Sun, Apr 02, 2023 at 09:04:04PM -0400, Waiman Long wrote:
>> On 3/31/23 13:16, Paul E. McKenney wrote:
>>> On Tue, Mar 28, 2023 at 02:58:54PM -0700, Paul E. McKenney wrote:
>>>> On Mon, Mar 27, 2023 at 10:19:54AM +0800, Feng Tang wrote:
>>>>> On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
>>>>>> On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:
>>> [ . . . ]
>>>
>>>>>>>> Second, we are very occasionally running into console messages like this:
>>>>>>>>
>>>>>>>> Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
>>>>>>>>
>>>>>>>> This comes from check_tsc_sync_source() and indicates that one CPU's
>>>>>>>> TSC read produced a later time than a later read from some other CPU.
>>>>>>>> I am beginning to suspect that these can be caused by unscheduled delays
>>>>>>>> in the TSC synchronization code, but figured I should ask you if you have
>>>>>>>> ever seen these.  And of course, if so, what the usual causes might be.
>>>>>>> I haven't seen this error myself or got similar reports. Usually it
>>>>>>> should be easy to detect once happened, as falling back to HPET
>>>>>>> will trigger obvious performance degradation.
>>>>>> And that is exactly what happened.  ;-)
>>>>>>
>>>>>>> Could you give more detail about when and how it happens, and the
>>>>>>> HW info like how many sockets the platform has.
>>>>>> We are in early days, so I am checking for other experiences.
>>>>>>
>>>>>>> CC Thomas, Waiman, as they discussed simliar case here:
>>>>>>> https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f
>>>>>> Fun!  ;-)
>>>> Waiman, do you recall what fraction of the benefit was provided by the
>>>> first patch, that is, the one that grouped the sync_lock, last_tsc,
>>>> max_warp, nr_warps, and random_warps global variables into a single
>>>> struct?
>> The purpose of the first patch is just to avoid false cacheline sharing
>> between the watchdog cpu and another cpu that happens to access a nearby
>> data in the same cacheline.
>>
>> Now I realize that I should have followed up with this patch series. The
>> problem reported in that patch series happen on one system only, I believe.
> Thus far I am seeing eight systems, but out of a large number.  So this
> is very much preliminary.
>
>>> And what we are seeing is unlikely to be due to cache-latency-induced
>>> delays.  We see a very precise warp, for example, one system always
>>> has 182 cycles of TSC warp, another 273 cycles, and a third 469 cycles.
>>> Another is at the insanely large value of about 2^64/10, and shows some
>>> variation, but that variation is only about 0.1%.
>>>
>>> But any given system only sees warp on about half of its reboots.
>>> Perhaps due to the automation sometimes power cycling?
>>>
>>> There are few enough affected systems that investigation will take
>>> some time.
>> Maybe the difference in wrap is due to NUMA distance of the running cpu from
>> the node where the data reside. It will be interesting to see if my patch
>> helps.
> Almost all of them are single-socket systems.
>
> If the problem sticks with a few systems, I should be able to test
> patches no problem.  If it is randomly distributed across the fleet, a
> bit more prework analysis will be called for.  But what is life without
> a challenge?  ;-)

If it is happening on a single socket system, maybe it is caused by 
false cacheline sharing. It is hard to tell unless we find a way to 
reproduce it.

Cheers,
Longman

Re: A couple of TSC questions

[Paul E. McKenney]

On Sun, Apr 02, 2023 at 10:05:51PM -0400, Waiman Long wrote:
> On 4/2/23 22:00, Paul E. McKenney wrote:
> > On Sun, Apr 02, 2023 at 09:04:04PM -0400, Waiman Long wrote:
> > > On 3/31/23 13:16, Paul E. McKenney wrote:
> > > > On Tue, Mar 28, 2023 at 02:58:54PM -0700, Paul E. McKenney wrote:
> > > > > On Mon, Mar 27, 2023 at 10:19:54AM +0800, Feng Tang wrote:
> > > > > > On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
> > > > > > > On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:
> > > > [ . . . ]
> > > > 
> > > > > > > > > Second, we are very occasionally running into console messages like this:
> > > > > > > > > 
> > > > > > > > > Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
> > > > > > > > > 
> > > > > > > > > This comes from check_tsc_sync_source() and indicates that one CPU's
> > > > > > > > > TSC read produced a later time than a later read from some other CPU.
> > > > > > > > > I am beginning to suspect that these can be caused by unscheduled delays
> > > > > > > > > in the TSC synchronization code, but figured I should ask you if you have
> > > > > > > > > ever seen these.  And of course, if so, what the usual causes might be.
> > > > > > > > I haven't seen this error myself or got similar reports. Usually it
> > > > > > > > should be easy to detect once happened, as falling back to HPET
> > > > > > > > will trigger obvious performance degradation.
> > > > > > > And that is exactly what happened.  ;-)
> > > > > > > 
> > > > > > > > Could you give more detail about when and how it happens, and the
> > > > > > > > HW info like how many sockets the platform has.
> > > > > > > We are in early days, so I am checking for other experiences.
> > > > > > > 
> > > > > > > > CC Thomas, Waiman, as they discussed simliar case here:
> > > > > > > > https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f
> > > > > > > Fun!  ;-)
> > > > > Waiman, do you recall what fraction of the benefit was provided by the
> > > > > first patch, that is, the one that grouped the sync_lock, last_tsc,
> > > > > max_warp, nr_warps, and random_warps global variables into a single
> > > > > struct?
> > > The purpose of the first patch is just to avoid false cacheline sharing
> > > between the watchdog cpu and another cpu that happens to access a nearby
> > > data in the same cacheline.
> > > 
> > > Now I realize that I should have followed up with this patch series. The
> > > problem reported in that patch series happen on one system only, I believe.
> > Thus far I am seeing eight systems, but out of a large number.  So this
> > is very much preliminary.
> > 
> > > > And what we are seeing is unlikely to be due to cache-latency-induced
> > > > delays.  We see a very precise warp, for example, one system always
> > > > has 182 cycles of TSC warp, another 273 cycles, and a third 469 cycles.
> > > > Another is at the insanely large value of about 2^64/10, and shows some
> > > > variation, but that variation is only about 0.1%.
> > > > 
> > > > But any given system only sees warp on about half of its reboots.
> > > > Perhaps due to the automation sometimes power cycling?
> > > > 
> > > > There are few enough affected systems that investigation will take
> > > > some time.
> > > Maybe the difference in wrap is due to NUMA distance of the running cpu from
> > > the node where the data reside. It will be interesting to see if my patch
> > > helps.
> > Almost all of them are single-socket systems.
> > 
> > If the problem sticks with a few systems, I should be able to test
> > patches no problem.  If it is randomly distributed across the fleet, a
> > bit more prework analysis will be called for.  But what is life without
> > a challenge?  ;-)
> 
> If it is happening on a single socket system, maybe it is caused by false
> cacheline sharing. It is hard to tell unless we find a way to reproduce it.

But multiple times on a given system with exactly the same number of
clock cycles of warp each time?  It should be entertaining tracking this
one down.  ;-)

I will take a few scans of the fleet over the coming week and see if
there is any consistency.  Here is hoping...

							Thanx, Paul

Re: A couple of TSC questions

[Feng Tang]

On Sun, Apr 02, 2023 at 08:38:37PM -0700, Paul E. McKenney wrote:
> On Sun, Apr 02, 2023 at 10:05:51PM -0400, Waiman Long wrote:
> > On 4/2/23 22:00, Paul E. McKenney wrote:
> > > On Sun, Apr 02, 2023 at 09:04:04PM -0400, Waiman Long wrote:
> > > > On 3/31/23 13:16, Paul E. McKenney wrote:
> > > > > On Tue, Mar 28, 2023 at 02:58:54PM -0700, Paul E. McKenney wrote:
> > > > > > On Mon, Mar 27, 2023 at 10:19:54AM +0800, Feng Tang wrote:
> > > > > > > On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
> > > > > > > > On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:
> > > > > [ . . . ]
> > > > > 
> > > > > > > > > > Second, we are very occasionally running into console messages like this:
> > > > > > > > > > 
> > > > > > > > > > Measured 2 cycles TSC warp between CPUs, turning off TSC clock.
> > > > > > > > > > 
> > > > > > > > > > This comes from check_tsc_sync_source() and indicates that one CPU's
> > > > > > > > > > TSC read produced a later time than a later read from some other CPU.
> > > > > > > > > > I am beginning to suspect that these can be caused by unscheduled delays
> > > > > > > > > > in the TSC synchronization code, but figured I should ask you if you have
> > > > > > > > > > ever seen these.  And of course, if so, what the usual causes might be.
> > > > > > > > > I haven't seen this error myself or got similar reports. Usually it
> > > > > > > > > should be easy to detect once happened, as falling back to HPET
> > > > > > > > > will trigger obvious performance degradation.
> > > > > > > > And that is exactly what happened.  ;-)
> > > > > > > > 
> > > > > > > > > Could you give more detail about when and how it happens, and the
> > > > > > > > > HW info like how many sockets the platform has.
> > > > > > > > We are in early days, so I am checking for other experiences.
> > > > > > > > 
> > > > > > > > > CC Thomas, Waiman, as they discussed simliar case here:
> > > > > > > > > https://lore.kernel.org/lkml/87h76ew3sb.ffs@tglx/T/#md4d0a88fb708391654e78312ffa75b481690699f
> > > > > > > > Fun!  ;-)
> > > > > > Waiman, do you recall what fraction of the benefit was provided by the
> > > > > > first patch, that is, the one that grouped the sync_lock, last_tsc,
> > > > > > max_warp, nr_warps, and random_warps global variables into a single
> > > > > > struct?
> > > > The purpose of the first patch is just to avoid false cacheline sharing
> > > > between the watchdog cpu and another cpu that happens to access a nearby
> > > > data in the same cacheline.
> > > > 
> > > > Now I realize that I should have followed up with this patch series. The
> > > > problem reported in that patch series happen on one system only, I believe.
> > > Thus far I am seeing eight systems, but out of a large number.  So this
> > > is very much preliminary.
> > > 
> > > > > And what we are seeing is unlikely to be due to cache-latency-induced
> > > > > delays.  We see a very precise warp, for example, one system always
> > > > > has 182 cycles of TSC warp, another 273 cycles, and a third 469 cycles.
> > > > > Another is at the insanely large value of about 2^64/10, and shows some
> > > > > variation, but that variation is only about 0.1%.
> > > > > 
> > > > > But any given system only sees warp on about half of its reboots.
> > > > > Perhaps due to the automation sometimes power cycling?
> > > > > 
> > > > > There are few enough affected systems that investigation will take
> > > > > some time.
> > > > Maybe the difference in wrap is due to NUMA distance of the running cpu from
> > > > the node where the data reside. It will be interesting to see if my patch
> > > > helps.
> > > Almost all of them are single-socket systems.

Interesting to know. I thought most of the TSC sync problems happen
in multiple socket system. IIRC, Waiman mentioned his platform is a
Cooper Lake which is for 4S or 8S platform, also Thomas and Peter
mentioned tsc sync issue on 8S platforms in other threads.

And your consistent warp of 182 (91 * 2) and 273 (91 * 3) cycles sound
like 'artificial' :), maybe the TSC_ADJUST MSR was programmed by BIOS
or other firmware?

Thanks,
Feng

> > > 
> > > If the problem sticks with a few systems, I should be able to test
> > > patches no problem.  If it is randomly distributed across the fleet, a
> > > bit more prework analysis will be called for.  But what is life without
> > > a challenge?  ;-)
> > 
> > If it is happening on a single socket system, maybe it is caused by false
> > cacheline sharing. It is hard to tell unless we find a way to reproduce it.
> 
> But multiple times on a given system with exactly the same number of
> clock cycles of warp each time?  It should be entertaining tracking this
> one down.  ;-)
> 
> I will take a few scans of the fleet over the coming week and see if
> there is any consistency.  Here is hoping...
> 
> 							Thanx, Paul

Re: A couple of TSC questions

[Paul E. McKenney]

On Mon, Apr 03, 2023 at 11:11:40PM +0800, Feng Tang wrote:
> On Sun, Apr 02, 2023 at 08:38:37PM -0700, Paul E. McKenney wrote:
> > On Sun, Apr 02, 2023 at 10:05:51PM -0400, Waiman Long wrote:
> > > On 4/2/23 22:00, Paul E. McKenney wrote:
> > > > On Sun, Apr 02, 2023 at 09:04:04PM -0400, Waiman Long wrote:
> > > > > On 3/31/23 13:16, Paul E. McKenney wrote:
> > > > > > On Tue, Mar 28, 2023 at 02:58:54PM -0700, Paul E. McKenney wrote:
> > > > > > > On Mon, Mar 27, 2023 at 10:19:54AM +0800, Feng Tang wrote:
> > > > > > > > On Fri, Mar 24, 2023 at 05:47:33PM -0700, Paul E. McKenney wrote:
> > > > > > > > > On Wed, Mar 22, 2023 at 01:14:48PM +0800, Feng Tang wrote:

[ . . . ]

> > > > > > And what we are seeing is unlikely to be due to cache-latency-induced
> > > > > > delays.  We see a very precise warp, for example, one system always
> > > > > > has 182 cycles of TSC warp, another 273 cycles, and a third 469 cycles.
> > > > > > Another is at the insanely large value of about 2^64/10, and shows some
> > > > > > variation, but that variation is only about 0.1%.
> > > > > > 
> > > > > > But any given system only sees warp on about half of its reboots.
> > > > > > Perhaps due to the automation sometimes power cycling?
> > > > > > 
> > > > > > There are few enough affected systems that investigation will take
> > > > > > some time.
> > > > > Maybe the difference in wrap is due to NUMA distance of the running cpu from
> > > > > the node where the data reside. It will be interesting to see if my patch
> > > > > helps.
> > > > Almost all of them are single-socket systems.
> 
> Interesting to know. I thought most of the TSC sync problems happen
> in multiple socket system. IIRC, Waiman mentioned his platform is a
> Cooper Lake which is for 4S or 8S platform, also Thomas and Peter
> mentioned tsc sync issue on 8S platforms in other threads.
> 
> And your consistent warp of 182 (91 * 2) and 273 (91 * 3) cycles sound
> like 'artificial' :), maybe the TSC_ADJUST MSR was programmed by BIOS
> or other firmware?

And all but one of them is almost assuredly a firmware issue.  But not
an Intel firmware issue, so there is that.  And in that case, the kernel
is doing what it should, yelling about a real problem.

The other is an Intel system, but is a one-off, with other ostensibly
identical systems doing just fine.  So it is likely simply a case of
dying hardware.  I will look closer when I return.

I will be on travel this coming week starting tomorrow (Friday),
Pacific Time.  There may be substantial intervals when I am completely
off the grid.

Have a great week!!!

							Thanx, Paul

> Thanks,
> Feng
> 
> > > > 
> > > > If the problem sticks with a few systems, I should be able to test
> > > > patches no problem.  If it is randomly distributed across the fleet, a
> > > > bit more prework analysis will be called for.  But what is life without
> > > > a challenge?  ;-)
> > > 
> > > If it is happening on a single socket system, maybe it is caused by false
> > > cacheline sharing. It is hard to tell unless we find a way to reproduce it.
> > 
> > But multiple times on a given system with exactly the same number of
> > clock cycles of warp each time?  It should be entertaining tracking this
> > one down.  ;-)
> > 
> > I will take a few scans of the fleet over the coming week and see if
> > there is any consistency.  Here is hoping...
> > 
> > 							Thanx, Paul