rc5+tip/master: Marking clocksource 'tsc' as unstable because the skew is too large:

DISCUSSION Borislav Petkov 4 participants 17 messages Jun 27, 2016 – Jun 30, 2016 High-resolution timers, timer wheel, clockevents

lore

Share & tools

lore

Borislav Petkov

author

2016-06-27 20:06 UTC #0 lore raw

Hey Thomas,

Just started seeing this now during testing of Rafael's s/r fix:

[   24.973955] clocksource: timekeeping watchdog on CPU3: Marking clocksource 'tsc' as unstable because the skew is too large:
[   24.987744] clocksource:                       'acpi_pm' wd_now: 2df835 wd_last: a6bb64 mask: ffffff
[   24.999587] clocksource:                       'tsc' cs_now: 2bbe793d1e cs_last: 296e28763c mask: ffffffffffffffff
[   25.013400] clocksource: Switched to clocksource acpi_pm

In the previous boot it was CPU1.

And kernel is rc5+tip/master.

Any suggestions are always welcome.

Signature · 4 lines

Regards/Gruss,
    Boris.

ECO tip #101: Trim your mails when you reply.

Borislav Petkov

author

2016-06-29 17:16 UTC #1 lore raw

Quoted 10 lines · Borislav Petkov

Hey Thomas,

Just started seeing this now during testing of Rafael's s/r fix:

[   24.973955] clocksource: timekeeping watchdog on CPU3: Marking clocksource 'tsc' as unstable because the skew is too large:
[   24.987744] clocksource:                       'acpi_pm' wd_now: 2df835 wd_last: a6bb64 mask: ffffff
[   24.999587] clocksource:                       'tsc' cs_now: 2bbe793d1e cs_last: 296e28763c mask: ffffffffffffffff
[   25.013400] clocksource: Switched to clocksource acpi_pm

In the previous boot it was CPU1.

And here it is again:

...

[   15.720833] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   32.883077] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[   32.896986] clocksource:                       'acpi_pm' wd_now: 8e147 wd_last: 531b43 mask: ffffff
[   32.908834] clocksource:                       'tsc' cs_now: 385f4b6d1e cs_last: 354328bcea mask: ffffffffffffffff
[   32.922293] clocksource: Switched to clocksource acpi_pm

Signature · 4 lines

Regards/Gruss,
    Boris.

ECO tip #101: Trim your mails when you reply.

Mike Galbraith

2016-06-30 07:57 UTC #2 lore raw

Quoted 8 lines · Borislav Petkov

And here it is again:

...

[   15.720833] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   32.883077] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[   32.896986] clocksource:                       'acpi_pm' wd_now: 8e147 wd_last: 531b43 mask: ffffff
[   32.908834] clocksource:                       'tsc' cs_now: 385f4b6d1e cs_last: 354328bcea mask: ffffffffffffffff
[   32.922293] clocksource: Switched to clocksource acpi_pm

I met that too when testing, but only on my 8 socket box for whatever reason. Putting tip back on the box and poking a bit while I beat up rt kernels elsewhere, cs_nsec: 167001172874 wd_nsec: 0. (poke++)

-Mike

Thomas Gleixner

2016-06-30 08:44 UTC #3 lore raw

Quoted 11 lines · Mike Galbraith

Quoted 8 lines · Borislav Petkov

And here it is again:

...

[   15.720833] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   32.883077] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[   32.896986] clocksource:                       'acpi_pm' wd_now: 8e147 wd_last: 531b43 mask: ffffff
[   32.908834] clocksource:                       'tsc' cs_now: 385f4b6d1e cs_last: 354328bcea mask: ffffffffffffffff
[   32.922293] clocksource: Switched to clocksource acpi_pm

Quoted 3 lines

I met that too when testing, but only on my 8 socket box for whatever reason. Putting tip back on the box and poking a bit while I beat up rt kernels elsewhere, cs_nsec: 167001172874 wd_nsec: 0. (poke++)

can i get the full data please including tsc frequency?

Mike Galbraith

2016-06-30 09:15 UTC #4 lore raw

Quoted 17 lines · Thomas Gleixner

Quoted 6 lines · Mike Galbraith
Quoted 4 lines · Borislav Petkov
And here it is again:
...
[   15.720833] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes
ready
Quoted 1 line
Quoted 1 line
[   32.883077] clocksource: timekeeping watchdog on CPU1: Marking
clocksource 'tsc' as unstable because the skew is too large:
Quoted 1 line
Quoted 1 line
[   32.896986] clocksource:                       'acpi_pm'
wd_now: 8e147 wd_last: 531b43 mask: ffffff
Quoted 1 line
Quoted 1 line
[   32.908834] clocksource:                       'tsc' cs_now:
385f4b6d1e cs_last: 354328bcea mask: ffffffffffffffff
Quoted 2 lines
Quoted 1 line
[   32.922293] clocksource: Switched to clocksource acpi_pm

Quoted 7 lines

Quoted 1 line
I met that too when testing, but only on my 8 socket box for
whatever
Quoted 1 line
reason. Putting tip back on the box and poking a bit while I beat
up
Quoted 1 line
rt kernels elsewhere, cs_nsec: 167001172874 wd_nsec: 0. (poke++)
can i get the full data please including tsc frequency?

[    0.000000] tsc: Fast TSC calibration using PIT
[    0.000000] tsc: Detected 2260.928 MHz processor
[   13.205453] tsc: Refined TSC clocksource calibration: 2260.999 MHz
[   13.205457] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x20974a4d8bb, max_idle_ns: 440795246623 ns
[   14.592866] clocksource: Switched to clocksource tsc
[  575.781329] clocksource: timekeeping watchdog on CPU23: Marking clocksource 'tsc' as unstable because the skew is too large:
[  575.998835] clocksource:                       'tsc' cs_now: 1c1effead80 cs_last: 139efdabfa5 mask: ffffffffffffffff

trace_printk() leading to splat (hm, mask).

          <idle>-0     [023] ..s.    25.233237: clocksource_watchdog: cs_nsec: 511311920 wd_nsec: 511311599 delta: 321 wdnow: 362266206  cs->wd_last: 354945155 watchdog->mask: ffffffff
          <idle>-0     [023] ..s.    57.234242: clocksource_watchdog: cs_nsec: 511999944 wd_nsec: 511999396 delta: 548 wdnow: 820447848  cs->wd_last: 813116949 watchdog->mask: ffffffff
          <idle>-0     [023] ..s.   575.781321: clocksource_watchdog: cs_nsec: 258345057292 wd_nsec: 0 delta: 258345057292 wdnow: 3949895484  cs->wd_last: 250865676 watchdog->mask: ffffffff

Thomas Gleixner

2016-06-30 10:10 UTC #5 lore raw

Quoted 34 lines · Mike Galbraith

Quoted 17 lines · Thomas Gleixner
Quoted 6 lines · Mike Galbraith
Quoted 4 lines · Borislav Petkov
And here it is again:
...
[   15.720833] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes
ready
Quoted 1 line
Quoted 1 line
[   32.883077] clocksource: timekeeping watchdog on CPU1: Marking
clocksource 'tsc' as unstable because the skew is too large:
Quoted 1 line
Quoted 1 line
[   32.896986] clocksource:                       'acpi_pm'
wd_now: 8e147 wd_last: 531b43 mask: ffffff
Quoted 1 line
Quoted 1 line
[   32.908834] clocksource:                       'tsc' cs_now:
385f4b6d1e cs_last: 354328bcea mask: ffffffffffffffff
Quoted 2 lines
Quoted 1 line
[   32.922293] clocksource: Switched to clocksource acpi_pm
Quoted 7 lines
Quoted 1 line
I met that too when testing, but only on my 8 socket box for
whatever
Quoted 1 line
reason. Putting tip back on the box and poking a bit while I beat
up
Quoted 1 line
rt kernels elsewhere, cs_nsec: 167001172874 wd_nsec: 0. (poke++)
can i get the full data please including tsc frequency?
[    0.000000] tsc: Fast TSC calibration using PIT
[    0.000000] tsc: Detected 2260.928 MHz processor
[   13.205453] tsc: Refined TSC clocksource calibration: 2260.999 MHz
[   13.205457] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x20974a4d8bb, max_idle_ns: 440795246623 ns
[   14.592866] clocksource: Switched to clocksource tsc
[  575.781329] clocksource: timekeeping watchdog on CPU23: Marking clocksource 'tsc' as unstable because the skew is too large:
[  575.998835] clocksource:                       'tsc' cs_now: 1c1effead80 cs_last: 139efdabfa5 mask: ffffffffffffffff

Quoted 5 lines

trace_printk() leading to splat (hm, mask).

          <idle>-0     [023] ..s.    25.233237: clocksource_watchdog: cs_nsec: 511311920 wd_nsec: 511311599 delta: 321 wdnow: 362266206  cs->wd_last: 354945155 watchdog->mask: ffffffff
          <idle>-0     [023] ..s.    57.234242: clocksource_watchdog: cs_nsec: 511999944 wd_nsec: 511999396 delta: 548 wdnow: 820447848  cs->wd_last: 813116949 watchdog->mask: ffffffff
          <idle>-0     [023] ..s.   575.781321: clocksource_watchdog: cs_nsec: 258345057292 wd_nsec: 0 delta: 258345057292 wdnow: 3949895484  cs->wd_last: 250865676 watchdog->mask: ffffffff

So there was no watchdog firing for 525 seconds ????

Mike Galbraith

2016-06-30 09:55 UTC #6 lore raw

Quoted 1 line · Thomas Gleixner

So there was no watchdog firing for 525 seconds ????

Yup, seems so.

-Mike

Mike Galbraith

2016-06-30 10:29 UTC #7 lore raw

Quoted 5 lines · Mike Galbraith

Quoted 1 line · Thomas Gleixner
So there was no watchdog firing for 525 seconds ????
Yup, seems so.

"fired" at the top, the other above if (atomic_read(&watchdog_reset...

vogelweide:/sys/kernel/debug/tracing/:[0]# tail trace
          <idle>-0     [055] ..s.   324.428369: clocksource_watchdog: fired
          <idle>-0     [055] ..s.   324.428374: clocksource_watchdog: cs_nsec: 16032486 wd_nsec: 16032765 delta: 279 wdnow: 351147182  wdlast: 350917622 watchdog->mask: ffffffff
             nis-5876  [056] ..s.   324.428403: clocksource_watchdog: fired
             nis-5876  [056] ..s.   324.428412: clocksource_watchdog: cs_nsec: 37227 wd_nsec: 37574 delta: 347 wdnow: 351147720  wdlast: 351147182 watchdog->mask: ffffffff
          <idle>-0     [057] ..s.   324.428428: clocksource_watchdog: fired
          <idle>-0     [057] ..s.   324.428433: clocksource_watchdog: cs_nsec: 21938 wd_nsec: 21301 delta: 637 wdnow: 351148025  wdlast: 351147720 watchdog->mask: ffffffff
       automount-5406  [059] ..s.   394.446498: clocksource_watchdog: fired
       automount-5406  [059] ..s.   394.446503: clocksource_watchdog: cs_nsec: 26670906785 wd_nsec: 26670888107 delta: 18678 wdnow: 1353664854  wdlast: 971786304 watchdog->mask: ffffffff
          ypbind-5385  [060] ..s.   561.325932: clocksource_watchdog: fired
          ypbind-5385  [060] ..s.   561.325937: clocksource_watchdog: cs_nsec: 166877142176 wd_nsec: 0 delta: 166877142176 wdnow: 3743040056  wdlast: 1353664854 watchdog->mask: ffffffff
vogelweide:/sys/kernel/debug/tracing/:[0]#

Thomas Gleixner

2016-06-30 10:35 UTC #8 lore raw

Quoted 4 lines · Mike Galbraith

       automount-5406  [059] ..s.   394.446498: clocksource_watchdog: fired
       automount-5406  [059] ..s.   394.446503: clocksource_watchdog: cs_nsec: 26670906785 wd_nsec: 26670888107 delta: 18678 wdnow: 1353664854  wdlast: 971786304 watchdog->mask: ffffffff
          ypbind-5385  [060] ..s.   561.325932: clocksource_watchdog: fired
          ypbind-5385  [060] ..s.   561.325937: clocksource_watchdog: cs_nsec: 166877142176 wd_nsec: 0 delta: 166877142176 wdnow: 3743040056  wdlast: 1353664854 watchdog->mask: ffffffff

So this is a remote enqueue on cpu60. /me goes digging

Thomas Gleixner

2016-06-30 11:09 UTC #9 lore raw

In reply to Mike Galbraith

Quoted 5 lines · Mike Galbraith

Quoted 1 line · Thomas Gleixner
So there was no watchdog firing for 525 seconds ????
Yup, seems so.

if that's fully reproducible can you please enable the timer and softirq tracepoints along with your trace printks and stop the trace when that watchdog triggers?

extra trace printk below.

thanks

tglx

kernel/time/timer.c +1 -0

index 3e0c4e60bf6a..418c45ab5ad5 100644
@@ -1438,6 +1438,7 @@ static unsigned long __next_timer_interrupt(struct timer_base *base)
 		clk >>= LVL_CLK_SHIFT;
 		clk += adj;
 	}
+	trace_printk("next %lu\n", next);
 	return next;
 }

Mike Galbraith

2016-06-30 13:39 UTC #10 lore raw

Quoted 10 lines · Thomas Gleixner

Quoted 5 lines · Mike Galbraith
Quoted 1 line · Thomas Gleixner
So there was no watchdog firing for 525 seconds ????
Yup, seems so.
if that's fully reproducible can you please enable the timer and softirq tracepoints along with your trace printks and stop the trace when that watchdog triggers?

Lunch rendered me (yawn) comatose, so I'm a bit late, but sent.

-Mike

Thomas Gleixner

2016-06-30 13:45 UTC #11 lore raw

Quoted 2 lines · Mike Galbraith

Lunch rendered me (yawn) comatose, so I'm a bit late, but sent.

Patch below should fix the issue - the timer one, not yours :)

Thanks,

tglx

8<------------

kernel/time/timer.c +18 -9

index 3e0c4e60bf6a..2b72eda3dc79 100644
@@ -531,28 +531,37 @@ __internal_add_timer(struct timer_base *base, struct timer_list *timer)
 static void
 trigger_dyntick_cpu(struct timer_base *base, struct timer_list *timer)
 {
+	if (!IS_ENABLED(CONFIG_NO_HZ_COMMON) || !base->nohz_active)
+		return;
+
+	/*
+	 * This wants some optimizing similar to the below, but we do that
+	 * when we switch from push to pull for deferrable timers.
+	 */
+	if (timer->flags & TIMER_DEFERRABLE) {
+		if (tick_nohz_full_cpu(base->cpu))
+			wake_up_nohz_cpu(base->cpu);
+		return;
+	}
+
 	/*
 	 * We might have to IPI the remote CPU if the base is idle and the
 	 * timer is not deferrable. If the other cpu is on the way to idle
 	 * then it can't set base->is_idle as we hold base lock.
 	 */
-	if (!IS_ENABLED(CONFIG_NO_HZ_COMMON) || !base->is_idle ||
-	    (timer->flags & TIMER_DEFERRABLE))
+	if (!base->is_idle)
 		return;
 
 	/* Check whether this is the new first expiring timer */
 	if (time_after_eq(timer->expires, base->next_expiry))
 		return;
-	base->next_expiry = timer->expires;
 
 	/*
-	 * Check whether the other CPU is in dynticks mode and needs to be
-	 * triggered to reevaluate the timer wheel.  We are protected against
-	 * the other CPU fiddling with the timer by holding the timer base
-	 * lock.
+	 * Set the next expiry time and kick the cpu so it can reevaluate the
+	 * wheel
 	 */
-	if (tick_nohz_full_cpu(base->cpu))
-		wake_up_nohz_cpu(base->cpu);
+	base->next_expiry = timer->expires;
+	wake_up_nohz_cpu(base->cpu);
 }
 
 static void

Borislav Petkov

author

2016-06-30 14:29 UTC #12 lore raw

Quoted 5 lines · Thomas Gleixner

Quoted 2 lines · Mike Galbraith
Lunch rendered me (yawn) comatose, so I'm a bit late, but sent.
Patch below should fix the issue - the timer one, not yours :)

Reported-and-tested-by Borislav Petkov <[email protected]>

Signature · 4 lines

Regards/Gruss,
    Boris.

ECO tip #101: Trim your mails when you reply.

Mike Galbraith

2016-06-30 14:30 UTC #13 lore raw

In reply to Thomas Gleixner

Quoted 5 lines · Thomas Gleixner

Quoted 2 lines · Mike Galbraith
Lunch rendered me (yawn) comatose, so I'm a bit late, but sent.
Patch below should fix the issue - the timer one, not yours :)

Box should have griped by now.. yup, all better.

-Mike

(mine isn't a wart, it's a.. somewhat noisy [90 dB] beauty mark)

Richard Cochran

2016-06-30 20:11 UTC #14 lore raw

In reply to Thomas Gleixner

Thomas,

Quoted 1 line · Thomas Gleixner

Patch below should fix the issue - the timer one, not yours :)

This patch also fixes the occasionally delayed timers I reported on the [email protected] list.

Thanks,
Richard

Thomas Gleixner

2016-06-30 08:43 UTC #15 lore raw

In reply to Borislav Petkov

Quoted 12 lines · Borislav Petkov

Quoted 10 lines · Borislav Petkov

Hey Thomas,

Just started seeing this now during testing of Rafael's s/r fix:

[   24.973955] clocksource: timekeeping watchdog on CPU3: Marking clocksource 'tsc' as unstable because the skew is too large:
[   24.987744] clocksource:                       'acpi_pm' wd_now: 2df835 wd_last: a6bb64 mask: ffffff
[   24.999587] clocksource:                       'tsc' cs_now: 2bbe793d1e cs_last: 296e28763c mask: ffffffffffffffff
[   25.013400] clocksource: Switched to clocksource acpi_pm

In the previous boot it was CPU1.

Quoted 8 lines

And here it is again:

...

[   15.720833] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   32.883077] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[   32.896986] clocksource:                       'acpi_pm' wd_now: 8e147 wd_last: 531b43 mask: ffffff
[   32.908834] clocksource:                       'tsc' cs_now: 385f4b6d1e cs_last: 354328bcea mask: ffffffffffffffff
[   32.922293] clocksource: Switched to clocksource acpi_pm

What's the tsc freqeuency on your machine?

Borislav Petkov

author

2016-06-30 09:57 UTC #16 lore raw

Quoted 15 lines · Thomas Gleixner

Quoted 14 lines · Borislav Petkov
Quoted 10 lines · Borislav Petkov
Hey Thomas,
Just started seeing this now during testing of Rafael's s/r fix:
[   24.973955] clocksource: timekeeping watchdog on CPU3: Marking clocksource 'tsc' as unstable because the skew is too large:
[   24.987744] clocksource:                       'acpi_pm' wd_now: 2df835 wd_last: a6bb64 mask: ffffff
[   24.999587] clocksource:                       'tsc' cs_now: 2bbe793d1e cs_last: 296e28763c mask: ffffffffffffffff
[   25.013400] clocksource: Switched to clocksource acpi_pm
In the previous boot it was CPU1.
And here it is again:

Quoted 8 lines

Quoted 6 lines

...

[   15.720833] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   32.883077] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[   32.896986] clocksource:                       'acpi_pm' wd_now: 8e147 wd_last: 531b43 mask: ffffff
[   32.908834] clocksource:                       'tsc' cs_now: 385f4b6d1e cs_last: 354328bcea mask: ffffffffffffffff
[   32.922293] clocksource: Switched to clocksource acpi_pm

What's the tsc freqeuency on your machine?

$ dmesg | grep -i tsc
[    0.000000] tsc: Fast TSC calibration using PIT
[    0.000000] tsc: Detected 4013.406 MHz processor
[    5.034357] tsc: Refined TSC clocksource calibration: 4013.511 MHz
[    5.034359] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x39da38233dd, max_idle_ns: 440795253361 ns
[    6.068153] clocksource: Switched to clocksource tsc
[   32.883077] clocksource: timekeeping watchdog on CPU1: Marking clocksource 'tsc' as unstable because the skew is too large:
[   32.908834] clocksource:                       'tsc' cs_now: 385f4b6d1e cs_last: 354328bcea mask: ffffffffffffffff

P0 is 4Ghz and TSC is ticking at P0 so 4GHz too. 4-ish, it seems :)

Signature · 4 lines

Regards/Gruss,
    Boris.

ECO tip #101: Trim your mails when you reply.