Re: PROBLEM: skew message does not handle negative ns skew

Re: PROBLEM: skew message does not handle negative ns skew

[Feng Tang]

Hi,

Could you share more info about the hardware, like which generation,
how many sockets or numa nodes (output of lscpu, 'numactl -h') ?

Thanks,
Feng

On Tue, Jun 06, 2023 at 11:33:50AM +0100, Chris Bainbridge wrote:
> Hi,
> 
> I noticed this message in the log (booting latest linux master
> v6.4-rc5-2-gf8dba31b0a82):
> 
> [    1.416270] clocksource: tsc: mask: 0xffffffffffffffff max_cycles:
> 0x36c4175520f, ma
> x_idle_ns: 881590509340 ns
> [    2.087102] clocksource: timekeeping watchdog on CPU3: Marking
> clocksource 'tsc' as unstable because the skew is too large:
> [    2.087105] clocksource:                       'hpet' wd_nsec: 512006134
> wd_now: 1c0c752 wd_last: 150ea9e mask: ffffffff
> [    2.087107] clocksource:                       'tsc' cs_nsec: 511127975
> cs_now: 65279672b cs_last: 618995074 mask: ffffffffffffffff
> [    2.087108] clocksource:                       Clocksource 'tsc' skewed
> -878159 ns (18446744073708 ms) over watchdog 'hpet' interval of 512006134
> ns (512 ms)
> [    2.087110] clocksource:                       'tsc-early' (not 'tsc')
> is current clocksource.
> 
> Note: Clocksource 'tsc' skewed -878159 ns (18446744073708 ms)
> 
> It looks like this message was introduced in December 2022, in commit
> dd029269947a

Re: PROBLEM: skew message does not handle negative ns skew

[Chris Bainbridge]

On Tue, 6 Jun 2023 at 12:35, Feng Tang <feng.tang@intel.com> wrote:
>
> Hi,
>
> Could you share more info about the hardware, like which generation,
> how many sockets or numa nodes (output of lscpu, 'numactl -h') ?
>
> Thanks,
> Feng

The hardware is a HP Pavilion Aero 13 laptop.

$ lscpu
Architecture:            x86_64
  CPU op-mode(s):        32-bit, 64-bit
  Address sizes:         48 bits physical, 48 bits virtual
  Byte Order:            Little Endian
CPU(s):                  16
  On-line CPU(s) list:   0-15
Vendor ID:               AuthenticAMD
  Model name:            AMD Ryzen 7 5800U with Radeon Graphics
    CPU family:          25
    Model:               80
    Thread(s) per core:  2
    Core(s) per socket:  8
    Socket(s):           1
    Stepping:            0
    Frequency boost:     enabled
    CPU(s) scaling MHz:  35%
    CPU max MHz:         4505.0781
    CPU min MHz:         1600.0000
    BogoMIPS:            3792.93
    Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep
mtrr pge mca cmov
                         pat pse36 clflush mmx fxsr sse sse2 ht
syscall nx mmxext fxsr_
                         opt pdpe1gb rdtscp lm constant_tsc rep_good
nopl nonstop_tsc c
                         puid extd_apicid aperfmperf rapl pni
pclmulqdq monitor ssse3 f
                         ma cx16 sse4_1 sse4_2 movbe popcnt aes xsave
avx f16c rdrand l
                         ahf_lm cmp_legacy svm extapic cr8_legacy abm
sse4a misalignsse
                          3dnowprefetch osvw ibs skinit wdt tce
topoext perfctr_core pe
                         rfctr_nb bpext perfctr_llc mwaitx cpb cat_l3
cdp_l3 hw_pstate
                         ssbd mba ibrs ibpb stibp vmmcall fsgsbase
bmi1 avx2 smep bmi2
                         erms invpcid cqm rdt_a rdseed adx smap
clflushopt clwb sha_ni
                         xsaveopt xsavec xgetbv1 xsaves cqm_llc
cqm_occup_llc cqm_mbm_t
                         otal cqm_mbm_local clzero irperf xsaveerptr
rdpru wbnoinvd cpp
                         c arat npt lbrv svm_lock nrip_save tsc_scale
vmcb_clean flushb
                         yasid decodeassists pausefilter pfthreshold
avic v_vmsave_vmlo
                         ad vgif v_spec_ctrl umip pku ospke vaes
vpclmulqdq rdpid overf
                         low_recov succor smca fsrm
Virtualization features:
  Virtualization:        AMD-V
Caches (sum of all):
  L1d:                   256 KiB (8 instances)
  L1i:                   256 KiB (8 instances)
  L2:                    4 MiB (8 instances)
  L3:                    16 MiB (1 instance)
NUMA:
  NUMA node(s):          1
  NUMA node0 CPU(s):     0-15
Vulnerabilities:
  Itlb multihit:         Not affected
  L1tf:                  Not affected
  Mds:                   Not affected
  Meltdown:              Not affected
  Mmio stale data:       Not affected
  Retbleed:              Not affected
  Spec store bypass:     Mitigation; Speculative Store Bypass disabled via prctl
  Spectre v1:            Mitigation; usercopy/swapgs barriers and
__user pointer saniti
                         zation
  Spectre v2:            Mitigation; Retpolines, IBPB conditional,
IBRS_FW, STIBP alway
                         s-on, RSB filling, PBRSB-eIBRS Not affected
  Srbds:                 Not affected
  Tsx async abort:       Not affected

$ numactl -H
available: 1 nodes (0)
node 0 cpus: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
node 0 size: 15331 MB
node 0 free: 789 MB
node distances:
node   0
  0:  10

Re: PROBLEM: skew message does not handle negative ns skew

[Feng Tang]

On Tue, Jun 06, 2023 at 01:28:50PM +0100, Chris Bainbridge wrote:
> On Tue, 6 Jun 2023 at 12:35, Feng Tang <feng.tang@intel.com> wrote:
> >
> > Hi,
> >
> > Could you share more info about the hardware, like which generation,
> > how many sockets or numa nodes (output of lscpu, 'numactl -h') ?
> >
> > Thanks,
> > Feng
> 
> The hardware is a HP Pavilion Aero 13 laptop.
> 
> $ lscpu
> Architecture:            x86_64
>   CPU op-mode(s):        32-bit, 64-bit
>   Address sizes:         48 bits physical, 48 bits virtual
>   Byte Order:            Little Endian
> CPU(s):                  16
>   On-line CPU(s) list:   0-15
> Vendor ID:               AuthenticAMD
>   Model name:            AMD Ryzen 7 5800U with Radeon Graphics
>     CPU family:          25
>     Model:               80
>     Thread(s) per core:  2
>     Core(s) per socket:  8
>     Socket(s):           1
>     Stepping:            0
>     Frequency boost:     enabled
>     CPU(s) scaling MHz:  35%
>     CPU max MHz:         4505.0781
>     CPU min MHz:         1600.0000
>     BogoMIPS:            3792.93
>     Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep
> mtrr pge mca cmov
>                          pat pse36 clflush mmx fxsr sse sse2 ht
> syscall nx mmxext fxsr_
>                          opt pdpe1gb rdtscp lm constant_tsc rep_good
> nopl nonstop_tsc c
>                          puid extd_apicid aperfmperf rapl pni
> pclmulqdq monitor ssse3 f
>                          ma cx16 sse4_1 sse4_2 movbe popcnt aes xsave
> avx f16c rdrand l
>                          ahf_lm cmp_legacy svm extapic cr8_legacy abm
> sse4a misalignsse
>                           3dnowprefetch osvw ibs skinit wdt tce
> topoext perfctr_core pe
>                          rfctr_nb bpext perfctr_llc mwaitx cpb cat_l3
> cdp_l3 hw_pstate
>                          ssbd mba ibrs ibpb stibp vmmcall fsgsbase
> bmi1 avx2 smep bmi2
>                          erms invpcid cqm rdt_a rdseed adx smap
> clflushopt clwb sha_ni
>                          xsaveopt xsavec xgetbv1 xsaves cqm_llc
> cqm_occup_llc cqm_mbm_t
>                          otal cqm_mbm_local clzero irperf xsaveerptr
> rdpru wbnoinvd cpp
>                          c arat npt lbrv svm_lock nrip_save tsc_scale
> vmcb_clean flushb
>                          yasid decodeassists pausefilter pfthreshold
> avic v_vmsave_vmlo
>                          ad vgif v_spec_ctrl umip pku ospke vaes
> vpclmulqdq rdpid overf
>                          low_recov succor smca fsrm


There is a commit to lift the watchdog check for morden qualified
platforms: b50db7095fe0 ("Disable clocksource watchdog for TSC on
qualified platorms"). But the patforms need to have 'tsc_adjust'
feature (has a TSC_ADJUST MSR), which can't be found in the above
lscpu info.

And I'm have no idea if there is a real hardware/firmware issue
or just a false alarm.

Thanks,
Feng

> Virtualization features:
>   Virtualization:        AMD-V
> Caches (sum of all):
>   L1d:                   256 KiB (8 instances)
>   L1i:                   256 KiB (8 instances)
>   L2:                    4 MiB (8 instances)
>   L3:                    16 MiB (1 instance)
> NUMA:
>   NUMA node(s):          1
>   NUMA node0 CPU(s):     0-15
> Vulnerabilities:
>   Itlb multihit:         Not affected
>   L1tf:                  Not affected
>   Mds:                   Not affected
>   Meltdown:              Not affected
>   Mmio stale data:       Not affected
>   Retbleed:              Not affected
>   Spec store bypass:     Mitigation; Speculative Store Bypass disabled via prctl
>   Spectre v1:            Mitigation; usercopy/swapgs barriers and
> __user pointer saniti
>                          zation
>   Spectre v2:            Mitigation; Retpolines, IBPB conditional,
> IBRS_FW, STIBP alway
>                          s-on, RSB filling, PBRSB-eIBRS Not affected
>   Srbds:                 Not affected
>   Tsx async abort:       Not affected
> 
> $ numactl -H
> available: 1 nodes (0)
> node 0 cpus: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
> node 0 size: 15331 MB
> node 0 free: 789 MB
> node distances:
> node   0
>   0:  10

Re: PROBLEM: skew message does not handle negative ns skew

[Chris Bainbridge]

On Tue, 6 Jun 2023 at 13:50, Feng Tang <feng.tang@intel.com> wrote:
>
> And I'm have no idea if there is a real hardware/firmware issue
> or just a false alarm.

Is a negative reported skew valid? I don't know, I had assumed so, so
the problem was the conversion from -878159 ns to 18446744073708 ms.

Re: PROBLEM: skew message does not handle negative ns skew

[Feng Tang]

On Tue, Jun 06, 2023 at 02:09:08PM +0100, Chris Bainbridge wrote:
> On Tue, 6 Jun 2023 at 13:50, Feng Tang <feng.tang@intel.com> wrote:
> >
> > And I'm have no idea if there is a real hardware/firmware issue
> > or just a false alarm.
> 
> Is a negative reported skew valid? I don't know, I had assumed so, so
> the problem was the conversion from -878159 ns to 18446744073708 ms.

I think it's valid. The related code is from kernel/time/clocksource.c: 

	"
	cs_wd_msec = div_u64_rem(cs_nsec - wd_nsec, 1000U * 1000U, &wd_rem);
	wd_msec = div_u64_rem(wd_nsec, 1000U * 1000U, &wd_rem);
	pr_warn("                      Clocksource '%s' skewed %lld ns (%lld ms) over watchdog '%s' interval of %lld ns (%lld ms)\n",
		cs->name, cs_nsec - wd_nsec, cs_wd_msec, watchdog->name, wd_nsec, wd_msec);
	"

The negative value just means the watchdog is running faster than
TSC in the 512 ms checking interval. The 18446744073708 ms is just
a conversion from s64 value in ns (-878159) to a u64 ns, then a
u64 ms. 

Thanks,
Feng

Re: PROBLEM: skew message does not handle negative ns skew

[Paul E. McKenney]

On Tue, Jun 06, 2023 at 09:52:11PM +0800, Feng Tang wrote:
> On Tue, Jun 06, 2023 at 02:09:08PM +0100, Chris Bainbridge wrote:
> > On Tue, 6 Jun 2023 at 13:50, Feng Tang <feng.tang@intel.com> wrote:
> > >
> > > And I'm have no idea if there is a real hardware/firmware issue
> > > or just a false alarm.
> > 
> > Is a negative reported skew valid? I don't know, I had assumed so, so
> > the problem was the conversion from -878159 ns to 18446744073708 ms.
> 
> I think it's valid. The related code is from kernel/time/clocksource.c: 
> 
> 	"
> 	cs_wd_msec = div_u64_rem(cs_nsec - wd_nsec, 1000U * 1000U, &wd_rem);
> 	wd_msec = div_u64_rem(wd_nsec, 1000U * 1000U, &wd_rem);
> 	pr_warn("                      Clocksource '%s' skewed %lld ns (%lld ms) over watchdog '%s' interval of %lld ns (%lld ms)\n",
> 		cs->name, cs_nsec - wd_nsec, cs_wd_msec, watchdog->name, wd_nsec, wd_msec);
> 	"
> 
> The negative value just means the watchdog is running faster than
> TSC in the 512 ms checking interval. The 18446744073708 ms is just
> a conversion from s64 value in ns (-878159) to a u64 ns, then a
> u64 ms. 

That is a bit user-unfriendly.  Does the following fix address this
issue at your end?

							Thanx, Paul

------------------------------------------------------------------------

commit 8eb836f2dd44cb1e80dfc603cf47c03603dadcdb
Author: Paul E. McKenney <paulmck@kernel.org>
Date:   Wed Jun 7 11:59:49 2023 -0700

    clocksource: Handle negative skews in "skew is too large" messages
    
    The nanosecond-to-millisecond skew computation uses unsigned arithmetic,
    which produces user-unfriendly large positive numbers for negative skews.
    Therefore, use signed arithmetic for this computation in order to preserve
    the negativity.
    
    Reported-by: Chris Bainbridge <chris.bainbridge@gmail.com>
    Reported-by: Feng Tang <feng.tang@intel.com>
    Fixes: dd029269947a ("clocksource: Improve "skew is too large" messages")
    Signed-off-by: Paul E. McKenney <paulmck@kernel.org>

diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
index 91836b727cef..0600e16dbafe 100644
--- a/kernel/time/clocksource.c
+++ b/kernel/time/clocksource.c
@@ -473,8 +473,8 @@ static void clocksource_watchdog(struct timer_list *unused)
 		/* Check the deviation from the watchdog clocksource. */
 		md = cs->uncertainty_margin + watchdog->uncertainty_margin;
 		if (abs(cs_nsec - wd_nsec) > md) {
-			u64 cs_wd_msec;
-			u64 wd_msec;
+			s64 cs_wd_msec;
+			s64 wd_msec;
 			u32 wd_rem;
 
 			pr_warn("timekeeping watchdog on CPU%d: Marking clocksource '%s' as unstable because the skew is too large:\n",
@@ -483,8 +483,8 @@ static void clocksource_watchdog(struct timer_list *unused)
 				watchdog->name, wd_nsec, wdnow, wdlast, watchdog->mask);
 			pr_warn("                      '%s' cs_nsec: %lld cs_now: %llx cs_last: %llx mask: %llx\n",
 				cs->name, cs_nsec, csnow, cslast, cs->mask);
-			cs_wd_msec = div_u64_rem(cs_nsec - wd_nsec, 1000U * 1000U, &wd_rem);
-			wd_msec = div_u64_rem(wd_nsec, 1000U * 1000U, &wd_rem);
+			cs_wd_msec = div_s64_rem(cs_nsec - wd_nsec, 1000 * 1000, &wd_rem);
+			wd_msec = div_s64_rem(wd_nsec, 1000 * 1000, &wd_rem);
 			pr_warn("                      Clocksource '%s' skewed %lld ns (%lld ms) over watchdog '%s' interval of %lld ns (%lld ms)\n",
 				cs->name, cs_nsec - wd_nsec, cs_wd_msec, watchdog->name, wd_nsec, wd_msec);
 			if (curr_clocksource == cs)

Re: PROBLEM: skew message does not handle negative ns skew

[Feng Tang]

On Wed, Jun 07, 2023 at 12:04:49PM -0700, Paul E. McKenney wrote:
> On Tue, Jun 06, 2023 at 09:52:11PM +0800, Feng Tang wrote:
> > On Tue, Jun 06, 2023 at 02:09:08PM +0100, Chris Bainbridge wrote:
> > > On Tue, 6 Jun 2023 at 13:50, Feng Tang <feng.tang@intel.com> wrote:
> > > >
> > > > And I'm have no idea if there is a real hardware/firmware issue
> > > > or just a false alarm.
> > > 
> > > Is a negative reported skew valid? I don't know, I had assumed so, so
> > > the problem was the conversion from -878159 ns to 18446744073708 ms.
> > 
> > I think it's valid. The related code is from kernel/time/clocksource.c: 
> > 
> > 	"
> > 	cs_wd_msec = div_u64_rem(cs_nsec - wd_nsec, 1000U * 1000U, &wd_rem);
> > 	wd_msec = div_u64_rem(wd_nsec, 1000U * 1000U, &wd_rem);
> > 	pr_warn("                      Clocksource '%s' skewed %lld ns (%lld ms) over watchdog '%s' interval of %lld ns (%lld ms)\n",
> > 		cs->name, cs_nsec - wd_nsec, cs_wd_msec, watchdog->name, wd_nsec, wd_msec);
> > 	"
> > 
> > The negative value just means the watchdog is running faster than
> > TSC in the 512 ms checking interval. The 18446744073708 ms is just
> > a conversion from s64 value in ns (-878159) to a u64 ns, then a
> > u64 ms. 
> 
> That is a bit user-unfriendly.  Does the following fix address this
> issue at your end?
> 
> 							Thanx, Paul
> 
> ------------------------------------------------------------------------
> 
> commit 8eb836f2dd44cb1e80dfc603cf47c03603dadcdb
> Author: Paul E. McKenney <paulmck@kernel.org>
> Date:   Wed Jun 7 11:59:49 2023 -0700
> 
>     clocksource: Handle negative skews in "skew is too large" messages
>     
>     The nanosecond-to-millisecond skew computation uses unsigned arithmetic,
>     which produces user-unfriendly large positive numbers for negative skews.
>     Therefore, use signed arithmetic for this computation in order to preserve
>     the negativity.

It does make the error message more consistent and less confusing. Thanks.

Reviewed-by: Feng Tang <feng.tang@intel.com>

>     
>     Reported-by: Chris Bainbridge <chris.bainbridge@gmail.com>
>     Reported-by: Feng Tang <feng.tang@intel.com>
>     Fixes: dd029269947a ("clocksource: Improve "skew is too large" messages")
>     Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
> 
> diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
> index 91836b727cef..0600e16dbafe 100644
> --- a/kernel/time/clocksource.c
> +++ b/kernel/time/clocksource.c
> @@ -473,8 +473,8 @@ static void clocksource_watchdog(struct timer_list *unused)
>  		/* Check the deviation from the watchdog clocksource. */
>  		md = cs->uncertainty_margin + watchdog->uncertainty_margin;
>  		if (abs(cs_nsec - wd_nsec) > md) {
> -			u64 cs_wd_msec;
> -			u64 wd_msec;
> +			s64 cs_wd_msec;
> +			s64 wd_msec;
>  			u32 wd_rem;
>  
>  			pr_warn("timekeeping watchdog on CPU%d: Marking clocksource '%s' as unstable because the skew is too large:\n",
> @@ -483,8 +483,8 @@ static void clocksource_watchdog(struct timer_list *unused)
>  				watchdog->name, wd_nsec, wdnow, wdlast, watchdog->mask);
>  			pr_warn("                      '%s' cs_nsec: %lld cs_now: %llx cs_last: %llx mask: %llx\n",
>  				cs->name, cs_nsec, csnow, cslast, cs->mask);
> -			cs_wd_msec = div_u64_rem(cs_nsec - wd_nsec, 1000U * 1000U, &wd_rem);
> -			wd_msec = div_u64_rem(wd_nsec, 1000U * 1000U, &wd_rem);
> +			cs_wd_msec = div_s64_rem(cs_nsec - wd_nsec, 1000 * 1000, &wd_rem);
> +			wd_msec = div_s64_rem(wd_nsec, 1000 * 1000, &wd_rem);
>  			pr_warn("                      Clocksource '%s' skewed %lld ns (%lld ms) over watchdog '%s' interval of %lld ns (%lld ms)\n",
>  				cs->name, cs_nsec - wd_nsec, cs_wd_msec, watchdog->name, wd_nsec, wd_msec);
>  			if (curr_clocksource == cs)

Re: PROBLEM: skew message does not handle negative ns skew

[Chris Bainbridge]

On Wed, 7 Jun 2023 at 20:04, Paul E. McKenney <paulmck@kernel.org> wrote:
>
> That is a bit user-unfriendly.  Does the following fix address this
> issue at your end?

[    2.095149] clocksource: timekeeping watchdog on CPU3: Marking
clocksource 'tsc' as unstable because the skew is too large:
[    2.095152] clocksource:                       'hpet' wd_nsec:
515998611 wd_now: 1c29fb9 wd_last: 151e3b8 mask: ffffffff
[    2.095154] clocksource:                       'tsc' cs_nsec:
515124524 cs_now: 8af4c89f9 cs_last: 874f8e80b mask: ffffffffffffffff
[    2.095155] clocksource:                       Clocksource 'tsc'
skewed -874087 ns (0 ms) over watchdog 'hpet' interval of 515998611 ns
(515 ms)

Re: PROBLEM: skew message does not handle negative ns skew

[Paul E. McKenney]

On Thu, Jun 08, 2023 at 10:41:51AM +0100, Chris Bainbridge wrote:
> On Wed, 7 Jun 2023 at 20:04, Paul E. McKenney <paulmck@kernel.org> wrote:
> >
> > That is a bit user-unfriendly.  Does the following fix address this
> > issue at your end?
> 
> [    2.095149] clocksource: timekeeping watchdog on CPU3: Marking
> clocksource 'tsc' as unstable because the skew is too large:
> [    2.095152] clocksource:                       'hpet' wd_nsec:
> 515998611 wd_now: 1c29fb9 wd_last: 151e3b8 mask: ffffffff
> [    2.095154] clocksource:                       'tsc' cs_nsec:
> 515124524 cs_now: 8af4c89f9 cs_last: 874f8e80b mask: ffffffffffffffff
> [    2.095155] clocksource:                       Clocksource 'tsc'
> skewed -874087 ns (0 ms) over watchdog 'hpet' interval of 515998611 ns
> (515 ms)

Very good, thank you!

May I please apply your Tested-by?

							Thanx, Paul

Re: PROBLEM: skew message does not handle negative ns skew

[Chris Bainbridge]

On Thu, 8 Jun 2023 at 17:25, Paul E. McKenney <paulmck@kernel.org> wrote:
>
> Very good, thank you!
>
> May I please apply your Tested-by?

Sure

Tested-by: Chris Bainbridge <chris.bainbridge@gmail.com>

Re: PROBLEM: skew message does not handle negative ns skew

[Paul E. McKenney]

On Thu, Jun 08, 2023 at 05:27:31PM +0100, Chris Bainbridge wrote:
> On Thu, 8 Jun 2023 at 17:25, Paul E. McKenney <paulmck@kernel.org> wrote:
> >
> > Very good, thank you!
> >
> > May I please apply your Tested-by?
> 
> Sure
> 
> Tested-by: Chris Bainbridge <chris.bainbridge@gmail.com>

Again, thank you!  I will apply this on my next rebase.

							Thanx, Paul