clocksource: Skip watchdog check for large watchdog intervals
PATCH 1/1 clocksource: Skip watchdog check for large watchdog intervals
There have been reports of the watchdog marking clocksources unstable on machines with 8 NUMA nodes:
Quoted 9 lines
clocksource: timekeeping watchdog on CPU373: Marking clocksource 'tsc' as unstable because the skew is too large: clocksource: 'hpet' wd_nsec: 14523447520 wd_now: 5a749706 wd_last: 45adf1e0 mask: ffffffff clocksource: 'tsc' cs_nsec: 14524115132 cs_now: 515ce2c5a96caa cs_last: 515cd9a9d83918 mask: ffffffffffffffff clocksource: 'tsc' is current clocksource. tsc: Marking TSC unstable due to clocksource watchdogTSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
sched_clock: Marking unstable (1950347883333462, 79649632569)<-(1950428279338308, -745776594)
clocksource: Checking clocksource tsc synchronization from CPU 400 to CPUs 0,46,52,54,138,208,392,397.
clocksource: Switched to clocksource hpet
The measured clocksource skew - the absolute difference between cs_nsec and wd_nsec - was 668 microseconds:
Quoted 1 line
cs_nsec-wd_nsec= 14524115132 - 14523447520 = 667612
The kernel (based on 5.14.21) used 200 microseconds for the uncertainty_margin of both the clocksource and watchdog, resulting in a threshold of 400 microseconds. The discrepancy is that the measured clocksource skew was evaluated against a threshold suited for watchdog intervals of roughly WATCHDOG_INTERVAL, i.e. HZ >> 1, which is 0.5 second. Both the cs_nsec and the wd_nsec value indicate that the actual watchdog interval was circa 14.5 seconds. Since the watchdog is executed in softirq context the expiration of the watchdog timer can get severely delayed on account of a ksoftirqd thread not getting to run in a timely manner. Surely, a system with such belated softirq execution is not working well and the scheduling issue should be looked into but the clocksource watchdog should be able to deal with it accordingly.
The solution in this patch skips the current watchdog check if the watchdog interval exceeds 1.5 * WATCHDOG_INTERVAL. Considering the maximum watchdog interval of 1.5 * WATCHDOG_INTERVAL, the current default uncertainty margin (of the TSC and HPET) corresponds to a limit on clocksource skew of 333 ppm (microseconds of skew per second). To keep the limit imposed by NTP (500 microseconds of skew per second) for all possible watchdog intervals, the margins would have to be scaled so that the threshold value is proportional to the length of the actual watchdog interval.
--- kernel/time/clocksource.c | 28 ++++++++++++++++++++++++++-- 1 file changed, 26 insertions(+), 2 deletions(-)
kernel/time/clocksource.c +26 -2
@@ -98,7 +98,9 @@ static u64 suspend_start;/* * Interval: 0.5sec. */ -#define WATCHDOG_INTERVAL (HZ >> 1) +#define WATCHDOG_INTERVAL (HZ >> 1) +#define WATCHDOG_INTR_MAX_NS ((WATCHDOG_INTERVAL + (WATCHDOG_INTERVAL >> 1))\ + * NSEC_PER_SEC / HZ)/* * Threshold: 0.0312s, when doubled: 0.0625s.
@@ -134,6 +136,7 @@ static DECLARE_WORK(watchdog_work, clocksource_watchdog_work);static DEFINE_SPINLOCK (watchdog_lock);static int watchdog_running;static atomic_t watchdog_reset_pending; +static int64_t watchdog_max_intr;static inline void clocksource_watchdog_lock (unsigned long *flags) {
@@ -400,7 +403,7 @@ static void clocksource_watchdog(struct timer_list *unused) {u64 csnow, wdnow, cslast, wdlast, delta;int next_cpu, reset_pending; -int64_t wd_nsec, cs_nsec; +int64_t wd_nsec, cs_nsec, interval;struct clocksource *cs;enum wd_read_status read_ret;unsigned long extra_wait =0 ;
@@ -470,6 +473,27 @@ static void clocksource_watchdog(struct timer_list *unused)if (atomic_read (&watchdog_reset_pending))continue ; +/* +* The processing of timer softirqs can get delayed (usually +* on account of ksoftirqd not getting to run in a timely +* manner), which causes the watchdog interval to stretch. +* Some clocksources, e.g. acpi_pm, cannot tolerate +* watchdog intervals longer than a few seconds. +* Skew detection may fail for longer watchdog intervals +* on account of fixed margins being used. +*/ + interval =max (cs_nsec, wd_nsec); +if (unlikely (interval >WATCHDOG_INTR_MAX_NS )) { +if (system_state >SYSTEM_SCHEDULING && + interval >2 * watchdog_max_intr) { + watchdog_max_intr = interval; +pr_warn ("Skipping watchdog check: cs_nsec: %lld wd_nsec: %lld\n" , + cs_nsec, wd_nsec); + } + watchdog_timer.expires = jiffies; +continue ; + } +/* Check the deviation from the watchdog clocksource. */ md = cs->uncertainty_margin + watchdog->uncertainty_margin;if (abs (cs_nsec - wd_nsec) > md) {
Signature · 6 lines
2.35.3 -- Jiri Wiesner SUSE Labs
Quoted 39 lines · Jiri Wiesner
There have been reports of the watchdog marking clocksources unstable on machines with 8 NUMA nodes:
Quoted 9 lines
clocksource: timekeeping watchdog on CPU373: Marking clocksource 'tsc' as unstable because the skew is too large: clocksource: 'hpet' wd_nsec: 14523447520 wd_now: 5a749706 wd_last: 45adf1e0 mask: ffffffff clocksource: 'tsc' cs_nsec: 14524115132 cs_now: 515ce2c5a96caa cs_last: 515cd9a9d83918 mask: ffffffffffffffff clocksource: 'tsc' is current clocksource. tsc: Marking TSC unstable due to clocksource watchdogTSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
sched_clock: Marking unstable (1950347883333462, 79649632569)<-(1950428279338308, -745776594)
clocksource: Checking clocksource tsc synchronization from CPU 400 to CPUs 0,46,52,54,138,208,392,397.
clocksource: Switched to clocksource hpetThe measured clocksource skew - the absolute difference between
cs_nsecandwd_nsec- was 668 microseconds:Quoted 1 line
cs_nsec-wd_nsec= 14524115132 - 14523447520 = 667612The kernel (based on 5.14.21) used 200 microseconds for the
uncertainty_marginof both the clocksource and watchdog, resulting in a threshold of 400 microseconds. The discrepancy is that the measured clocksource skew was evaluated against a threshold suited for watchdog intervals of roughlyWATCHDOG_INTERVAL, i.e. HZ >> 1, which is 0.5 second. Both thecs_nsecand thewd_nsecvalue indicate that the actual watchdog interval was circa 14.5 seconds. Since the watchdog is executed in softirq context the expiration of the watchdog timer can get severely delayed on account of a ksoftirqd thread not getting to run in a timely manner. Surely, a system with such belated softirq execution is not working well and the scheduling issue should be looked into but the clocksource watchdog should be able to deal with it accordingly.The solution in this patch skips the current watchdog check if the watchdog interval exceeds 1.5 *
WATCHDOG_INTERVAL. Considering the maximum watchdog interval of 1.5 *WATCHDOG_INTERVAL, the current default uncertainty margin (of the TSC and HPET) corresponds to a limit on clocksource skew of 333 ppm (microseconds of skew per second). To keep the limit imposed by NTP (500 microseconds of skew per second) for all possible watchdog intervals, the margins would have to be scaled so that the threshold value is proportional to the length of the actual watchdog interval.
Quoted 3 lines
Fixes 2e27e793e280 ("clocksource: Reduce clocksource-skew threshold")Suggested-by Feng Tang <[email protected]>Signed-off-by Jiri Wiesner <[email protected]>
I believe that there were concerns about a similar approach in the case where the jiffies counter is the clocksource, but in the meantime:
Quoted 71 lines
--- kernel/time/clocksource.c | 28 ++++++++++++++++++++++++++-- 1 file changed, 26 insertions(+), 2 deletions(-)kernel/time/clocksource.c +26
-2@@ -98,7 +98,9 @@ static u64 suspend_start;/* * Interval: 0.5sec. */ -#define WATCHDOG_INTERVAL (HZ >> 1) +#define WATCHDOG_INTERVAL (HZ >> 1) +#define WATCHDOG_INTR_MAX_NS ((WATCHDOG_INTERVAL + (WATCHDOG_INTERVAL >> 1))\ + * NSEC_PER_SEC / HZ)/* * Threshold: 0.0312s, when doubled: 0.0625s. @@ -134,6 +136,7 @@ static DECLARE_WORK(watchdog_work, clocksource_watchdog_work);static DEFINE_SPINLOCK (watchdog_lock);static int watchdog_running;static atomic_t watchdog_reset_pending; +static int64_t watchdog_max_intr;static inline void clocksource_watchdog_lock (unsigned long *flags) {@@ -400,7 +403,7 @@ static void clocksource_watchdog(struct timer_list *unused) {u64 csnow, wdnow, cslast, wdlast, delta;int next_cpu, reset_pending; -int64_t wd_nsec, cs_nsec; +int64_t wd_nsec, cs_nsec, interval;struct clocksource *cs;enum wd_read_status read_ret;unsigned long extra_wait =0 ;@@ -470,6 +473,27 @@ static void clocksource_watchdog(struct timer_list *unused)if (atomic_read (&watchdog_reset_pending))continue ; +/* +* The processing of timer softirqs can get delayed (usually +* on account of ksoftirqd not getting to run in a timely +* manner), which causes the watchdog interval to stretch. +* Some clocksources, e.g. acpi_pm, cannot tolerate +* watchdog intervals longer than a few seconds. +* Skew detection may fail for longer watchdog intervals +* on account of fixed margins being used. +*/ + interval =max (cs_nsec, wd_nsec); +if (unlikely (interval >WATCHDOG_INTR_MAX_NS )) { +if (system_state >SYSTEM_SCHEDULING && + interval >2 * watchdog_max_intr) { + watchdog_max_intr = interval; +pr_warn ("Skipping watchdog check: cs_nsec: %lld wd_nsec: %lld\n" , + cs_nsec, wd_nsec); + } + watchdog_timer.expires = jiffies; +continue ; + } +/* Check the deviation from the watchdog clocksource. */ md = cs->uncertainty_margin + watchdog->uncertainty_margin;if (abs (cs_nsec - wd_nsec) > md) {Signature · 6 lines
2.35.3 -- Jiri Wiesner SUSE Labs
Quoted 2 lines · Paul E. McKenney
I believe that there were concerns about a similar approach in the case where the jiffies counter is the clocksource
I ran a few simple tests on a 2 NUMA node Intel machine and found nothing so far. I tried booting with clocksource=jiffies and I changed the "nr_online_nodes <= 4" check in tsc_clocksource_as_watchdog() to enable the watchdog on my machine. I have a debugging module that monitors clocksource and watchdog reads in clocksource_watchdog() with kprobes. I see the cs/wd reads executed roughly every 0.5 second, as expected. When the machine is idle the average watchdog interval is 501.61 milliseconds (+-15.57 ms, with a minimum of 477.07 ms and a maximum of 517.93 ms). The result is similar when the CPUs of the machine are fully saturated with netperf processes. I also tried booting with clocksource=jiffies and tsc=watchdog. The watchdog interval was similar to the previous test.
AFAIK, the jiffies clocksource does get checked by the watchdog itself. And with that, I have run out of ideas.
Signature · 2 lines
Jiri Wiesner SUSE Labs
Quoted 16 lines · Jiri Wiesner
Quoted 2 lines · Paul E. McKenney
I believe that there were concerns about a similar approach in the case where the jiffies counter is the clocksource
I ran a few simple tests on a 2 NUMA node Intel machine and found nothing so far. I tried booting with clocksource=jiffies and I changed the "
nr_online_nodes<= 4" check intsc_clocksource_as_watchdog()to enable the watchdog on my machine. I have a debugging module that monitors clocksource and watchdog reads inclocksource_watchdog()with kprobes. I see the cs/wd reads executed roughly every 0.5 second, as expected. When the machine is idle the average watchdog interval is 501.61 milliseconds (+-15.57 ms, with a minimum of 477.07 ms and a maximum of 517.93 ms). The result is similar when the CPUs of the machine are fully saturated with netperf processes. I also tried booting with clocksource=jiffies and tsc=watchdog. The watchdog interval was similar to the previous test.
Quoted 2 lines
AFAIK, the jiffies clocksource does get checked by the watchdog itself. And with that, I have run out of ideas.
If I recall correctly (ha!), the concern was that with the jiffies as clocksource, we would be using jiffies (via timers) to check jiffies (the clocksource), and that this could cause issues if the jiffies got behind, then suddenly updated while the clocksource watchdog was running.
Thoughts?
Thanx, Paul
Quoted 17 lines · Paul E. McKenney
Quoted 16 lines · Jiri Wiesner
Quoted 2 lines · Paul E. McKenney
I believe that there were concerns about a similar approach in the case where the jiffies counter is the clocksource
I ran a few simple tests on a 2 NUMA node Intel machine and found nothing so far. I tried booting with clocksource=jiffies and I changed the "
nr_online_nodes<= 4" check intsc_clocksource_as_watchdog()to enable the watchdog on my machine. I have a debugging module that monitors clocksource and watchdog reads inclocksource_watchdog()with kprobes. I see the cs/wd reads executed roughly every 0.5 second, as expected. When the machine is idle the average watchdog interval is 501.61 milliseconds (+-15.57 ms, with a minimum of 477.07 ms and a maximum of 517.93 ms). The result is similar when the CPUs of the machine are fully saturated with netperf processes. I also tried booting with clocksource=jiffies and tsc=watchdog. The watchdog interval was similar to the previous test.
Quoted 7 lines
Quoted 2 lines
AFAIK, the jiffies clocksource does get checked by the watchdog itself. And with that, I have run out of ideas.
If I recall correctly (ha!), the concern was that with the jiffies as clocksource, we would be using jiffies (via timers) to check jiffies (the clocksource), and that this could cause issues if the jiffies got behind, then suddenly updated while the clocksource watchdog was running.
Yes, we also met problem when 'jiffies' was used as clocksource/watchdog, but don't know if it's the same problem you mentioned. Our problem ('jiffies' as watchdog marks clocksource TSC as unstable) only happens in early boot phase with serial earlyprintk enabled, that the updating of 'jiffies' relies on HW timer's periodic interrupt, but early printk will disable interrupt during printing and cause some timer interrupts lost, and hence big lagging in 'jiffies'. Rui once proposed a patch to prevent 'jiffies' from being a watchdog due to it unreliability [1].
And I think skipping the watchdog check one time when detecting some abnormal condition won't hurt the overall check much.
[1]. https://lore.kernel.org/lkml/[email protected]/
Thanks,
Feng
Quoted 3 lines
Thoughts?
Thanx, Paul
Quoted 35 lines · Feng Tang
Quoted 17 lines · Paul E. McKenney
Quoted 16 lines · Jiri Wiesner
Quoted 2 lines · Paul E. McKenney
I believe that there were concerns about a similar approach in the case where the jiffies counter is the clocksource
I ran a few simple tests on a 2 NUMA node Intel machine and found nothing so far. I tried booting with clocksource=jiffies and I changed the "
nr_online_nodes<= 4" check intsc_clocksource_as_watchdog()to enable the watchdog on my machine. I have a debugging module that monitors clocksource and watchdog reads inclocksource_watchdog()with kprobes. I see the cs/wd reads executed roughly every 0.5 second, as expected. When the machine is idle the average watchdog interval is 501.61 milliseconds (+-15.57 ms, with a minimum of 477.07 ms and a maximum of 517.93 ms). The result is similar when the CPUs of the machine are fully saturated with netperf processes. I also tried booting with clocksource=jiffies and tsc=watchdog. The watchdog interval was similar to the previous test.Quoted 7 lines
Quoted 2 lines
AFAIK, the jiffies clocksource does get checked by the watchdog itself. And with that, I have run out of ideas.
If I recall correctly (ha!), the concern was that with the jiffies as clocksource, we would be using jiffies (via timers) to check jiffies (the clocksource), and that this could cause issues if the jiffies got behind, then suddenly updated while the clocksource watchdog was running.
Yes, we also met problem when 'jiffies' was used as clocksource/watchdog, but don't know if it's the same problem you mentioned. Our problem ('jiffies' as watchdog marks clocksource TSC as unstable) only happens in early boot phase with serial earlyprintk enabled, that the updating of 'jiffies' relies on HW timer's periodic interrupt, but early printk will disable interrupt during printing and cause some timer interrupts lost, and hence big lagging in 'jiffies'. Rui once proposed a patch to prevent 'jiffies' from being a watchdog due to it unreliability [1].
Quoted 2 lines
And I think skipping the watchdog check one time when detecting some abnormal condition won't hurt the overall check much.
Works for me!
Thanx, Paul
Quoted 8 lines
[1]. https://lore.kernel.org/lkml/[email protected]/
Thanks,
FengQuoted 3 lines
Thoughts?
Thanx, Paul
kernel test robot
build botkernel test robot noticed the following build warnings:
Hi Jiri,
kernel test robot noticed the following build warnings:
[auto build test WARNING on tip/timers/core]
[also build test WARNING on linus/master v6.7-rc8 next-20240103] [If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]
url: https://github.com/intel-lab-lkp/linux/commits/Jiri-Wiesner/clocksource-Skip-watchdog-check-for-large-watchdog-intervals/20240103-192257 base: tip/timers/core patch link: https://lore.kernel.org/r/20240103112113.GA6108%40incl patch subject: [PATCH] clocksource: Skip watchdog check for large watchdog intervals config: i386-buildonly-randconfig-001-20240104 (https://download.01.org/0day-ci/archive/20240104/[email protected]/config) compiler: gcc-7 (Ubuntu 7.5.0-6ubuntu2) 7.5.0 reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20240104/[email protected]/reproduce)
If you fix the issue in a separate patch/commit (i.e. not just a new version of the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <[email protected]>
| Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/
All warnings (new ones prefixed by >>):
In file included from include/linux/dev_printk.h:14:0,
from include/linux/device.h:15, from kernel/time/clocksource.c:10:
kernel/time/clocksource.c: In function 'clocksource_watchdog':
>> kernel/time/clocksource.c:103:6: warning: integer overflow in expression [-Woverflow]
* NSEC_PER_SEC / HZ)
^
include/linux/compiler.h:77:42: note: in definition of macro 'unlikely'
# define unlikely(x) __builtin_expect(!!(x), 0)
^
kernel/time/clocksource.c:486:27: note: in expansion of macro 'WATCHDOG_INTR_MAX_NS'
if (unlikely(interval > WATCHDOG_INTR_MAX_NS)) {
^~~~~~~~~~~~~~~~~~~~vim +103 kernel/time/clocksource.c
97
98 /*
99 * Interval: 0.5sec.
100 */
101 #define WATCHDOG_INTERVAL (HZ >> 1)
102 #define WATCHDOG_INTR_MAX_NS ((WATCHDOG_INTERVAL + (WATCHDOG_INTERVAL >> 1))\
> 103 * NSEC_PER_SEC / HZ)104
Signature · 2 lines
0-DAY CI Kernel Test Service https://github.com/intel/lkp-tests/wiki
kernel test robot
build botkernel test robot noticed the following build warnings:
Hi Jiri,
kernel test robot noticed the following build warnings:
[auto build test WARNING on tip/timers/core]
[also build test WARNING on linus/master v6.7-rc8 next-20240103] [If your patch is applied to the wrong git tree, kindly drop us a note. And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]
url: https://github.com/intel-lab-lkp/linux/commits/Jiri-Wiesner/clocksource-Skip-watchdog-check-for-large-watchdog-intervals/20240103-192257 base: tip/timers/core patch link: https://lore.kernel.org/r/20240103112113.GA6108%40incl patch subject: [PATCH] clocksource: Skip watchdog check for large watchdog intervals config: i386-randconfig-r071-20240104 (https://download.01.org/0day-ci/archive/20240104/[email protected]/config) compiler: ClangBuiltLinux clang version 17.0.6 (https://github.com/llvm/llvm-project 6009708b4367171ccdbf4b5905cb6a803753fe18) reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20240104/[email protected]/reproduce)
If you fix the issue in a separate patch/commit (i.e. not just a new version of the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <[email protected]>
| Closes: https://lore.kernel.org/oe-kbuild-all/[email protected]/
All warnings (new ones prefixed by >>):
>> kernel/time/clocksource.c:486:27: warning: overflow in expression; result is -1978561024 with type 'long' [-Winteger-overflow]
486 | if (unlikely(interval > WATCHDOG_INTR_MAX_NS)) {
| ^
kernel/time/clocksource.c:103:6: note: expanded from macro 'WATCHDOG_INTR_MAX_NS'
103 | * NSEC_PER_SEC / HZ)
| ^1 warning generated.
vim +/long +486 kernel/time/clocksource.c
400
401
402 static void clocksource_watchdog(struct timer_list *unused)
403 {
404 u64 csnow, wdnow, cslast, wdlast, delta;
405 int next_cpu, reset_pending;
406 int64_t wd_nsec, cs_nsec, interval;
407 struct clocksource *cs;
408 enum wd_read_status read_ret;
409 unsigned long extra_wait = 0;
410 u32 md;
411
412 spin_lock(&watchdog_lock);
413 if (!watchdog_running)
414 goto out;
415
416 reset_pending = atomic_read(&watchdog_reset_pending);
417
418 list_for_each_entry(cs, &watchdog_list, wd_list) {
419
420 /* Clocksource already marked unstable? */
421 if (cs->flags & CLOCK_SOURCE_UNSTABLE) {
422 if (finished_booting)
423 schedule_work(&watchdog_work);
424 continue;
425 }
426
427 read_ret = cs_watchdog_read(cs, &csnow, &wdnow);
428
429 if (read_ret == WD_READ_UNSTABLE) {
430 /* Clock readout unreliable, so give it up. */
431 __clocksource_unstable(cs);
432 continue;
433 }
434
435 /*
436 * When WD_READ_SKIP is returned, it means the system is likely
437 * under very heavy load, where the latency of reading
438 * watchdog/clocksource is very big, and affect the accuracy of
439 * watchdog check. So give system some space and suspend the
440 * watchdog check for 5 minutes.
441 */
442 if (read_ret == WD_READ_SKIP) {
443 /*
444 * As the watchdog timer will be suspended, and
445 * cs->last could keep unchanged for 5 minutes, reset
446 * the counters.
447 */
448 clocksource_reset_watchdog();
449 extra_wait = HZ * 300;
450 break;
451 }
452
453 /* Clocksource initialized ? */
454 if (!(cs->flags & CLOCK_SOURCE_WATCHDOG) ||
455 atomic_read(&watchdog_reset_pending)) {
456 cs->flags |= CLOCK_SOURCE_WATCHDOG;
457 cs->wd_last = wdnow;
458 cs->cs_last = csnow;
459 continue;
460 }
461
462 delta = clocksource_delta(wdnow, cs->wd_last, watchdog->mask);
463 wd_nsec = clocksource_cyc2ns(delta, watchdog->mult,
464 watchdog->shift);
465
466 delta = clocksource_delta(csnow, cs->cs_last, cs->mask);
467 cs_nsec = clocksource_cyc2ns(delta, cs->mult, cs->shift);
468 wdlast = cs->wd_last; /* save these in case we print them */
469 cslast = cs->cs_last;
470 cs->cs_last = csnow;
471 cs->wd_last = wdnow;
472
473 if (atomic_read(&watchdog_reset_pending))
474 continue;
475
476 /*
477 * The processing of timer softirqs can get delayed (usually
478 * on account of ksoftirqd not getting to run in a timely
479 * manner), which causes the watchdog interval to stretch.
480 * Some clocksources, e.g. acpi_pm, cannot tolerate
481 * watchdog intervals longer than a few seconds.
482 * Skew detection may fail for longer watchdog intervals
483 * on account of fixed margins being used.
484 */
485 interval = max(cs_nsec, wd_nsec);
> 486 if (unlikely(interval > WATCHDOG_INTR_MAX_NS)) { 487 if (system_state > SYSTEM_SCHEDULING &&
488 interval > 2 * watchdog_max_intr) {
489 watchdog_max_intr = interval;
490 pr_warn("Skipping watchdog check: cs_nsec: %lld wd_nsec: %lld\n",
491 cs_nsec, wd_nsec);
492 }
493 watchdog_timer.expires = jiffies;
494 continue;
495 }
496
497 /* Check the deviation from the watchdog clocksource. */
498 md = cs->uncertainty_margin + watchdog->uncertainty_margin;
499 if (abs(cs_nsec - wd_nsec) > md) {
500 s64 cs_wd_msec;
501 s64 wd_msec;
502 u32 wd_rem;
503
504 pr_warn("timekeeping watchdog on CPU%d: Marking clocksource '%s' as unstable because the skew is too large:\n",
505 smp_processor_id(), cs->name);
506 pr_warn(" '%s' wd_nsec: %lld wd_now: %llx wd_last: %llx mask: %llx\n",
507 watchdog->name, wd_nsec, wdnow, wdlast, watchdog->mask);
508 pr_warn(" '%s' cs_nsec: %lld cs_now: %llx cs_last: %llx mask: %llx\n",
509 cs->name, cs_nsec, csnow, cslast, cs->mask);
510 cs_wd_msec = div_s64_rem(cs_nsec - wd_nsec, 1000 * 1000, &wd_rem);
511 wd_msec = div_s64_rem(wd_nsec, 1000 * 1000, &wd_rem);
512 pr_warn(" Clocksource '%s' skewed %lld ns (%lld ms) over watchdog '%s' interval of %lld ns (%lld ms)\n",
513 cs->name, cs_nsec - wd_nsec, cs_wd_msec, watchdog->name, wd_nsec, wd_msec);
514 if (curr_clocksource == cs)
515 pr_warn(" '%s' is current clocksource.\n", cs->name);
516 else if (curr_clocksource)
517 pr_warn(" '%s' (not '%s') is current clocksource.\n", curr_clocksource->name, cs->name);
518 else
519 pr_warn(" No current clocksource.\n");
520 __clocksource_unstable(cs);
521 continue;
522 }
523
524 if (cs == curr_clocksource && cs->tick_stable)
525 cs->tick_stable(cs);
526
527 if (!(cs->flags & CLOCK_SOURCE_VALID_FOR_HRES) &&
528 (cs->flags & CLOCK_SOURCE_IS_CONTINUOUS) &&
529 (watchdog->flags & CLOCK_SOURCE_IS_CONTINUOUS)) {
530 /* Mark it valid for high-res. */
531 cs->flags |= CLOCK_SOURCE_VALID_FOR_HRES;
532
533 /*
534 * clocksource_done_booting() will sort it if
535 * finished_booting is not set yet.
536 */
537 if (!finished_booting)
538 continue;
539
540 /*
541 * If this is not the current clocksource let
542 * the watchdog thread reselect it. Due to the
543 * change to high res this clocksource might
544 * be preferred now. If it is the current
545 * clocksource let the tick code know about
546 * that change.
547 */
548 if (cs != curr_clocksource) {
549 cs->flags |= CLOCK_SOURCE_RESELECT;
550 schedule_work(&watchdog_work);
551 } else {
552 tick_clock_notify();
553 }
554 }
555 }
556
557 /*
558 * We only clear the watchdog_reset_pending, when we did a
559 * full cycle through all clocksources.
560 */
561 if (reset_pending)
562 atomic_dec(&watchdog_reset_pending);
563
564 /*
565 * Cycle through CPUs to check if the CPUs stay synchronized
566 * to each other.
567 */
568 next_cpu = cpumask_next(raw_smp_processor_id(), cpu_online_mask);
569 if (next_cpu >= nr_cpu_ids)
570 next_cpu = cpumask_first(cpu_online_mask);
571
572 /*
573 * Arm timer if not already pending: could race with concurrent
574 * pair clocksource_stop_watchdog() clocksource_start_watchdog().
575 */
576 if (!timer_pending(&watchdog_timer)) {
577 watchdog_timer.expires += WATCHDOG_INTERVAL + extra_wait;
578 add_timer_on(&watchdog_timer, next_cpu);
579 }
580 out:
581 spin_unlock(&watchdog_lock);
582 }
583
Signature · 2 lines
0-DAY CI Kernel Test Service https://github.com/intel/lkp-tests/wiki
Quoted 39 lines · Jiri Wiesner
There have been reports of the watchdog marking clocksources unstable on machines with 8 NUMA nodes:
Quoted 9 lines
clocksource: timekeeping watchdog on CPU373: Marking clocksource 'tsc' as unstable because the skew is too large: clocksource: 'hpet' wd_nsec: 14523447520 wd_now: 5a749706 wd_last: 45adf1e0 mask: ffffffff clocksource: 'tsc' cs_nsec: 14524115132 cs_now: 515ce2c5a96caa cs_last: 515cd9a9d83918 mask: ffffffffffffffff clocksource: 'tsc' is current clocksource. tsc: Marking TSC unstable due to clocksource watchdogTSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
sched_clock: Marking unstable (1950347883333462, 79649632569)<-(1950428279338308, -745776594)
clocksource: Checking clocksource tsc synchronization from CPU 400 to CPUs 0,46,52,54,138,208,392,397.
clocksource: Switched to clocksource hpetThe measured clocksource skew - the absolute difference between
cs_nsecandwd_nsec- was 668 microseconds:Quoted 1 line
cs_nsec-wd_nsec= 14524115132 - 14523447520 = 667612The kernel (based on 5.14.21) used 200 microseconds for the
uncertainty_marginof both the clocksource and watchdog, resulting in a threshold of 400 microseconds. The discrepancy is that the measured clocksource skew was evaluated against a threshold suited for watchdog intervals of roughlyWATCHDOG_INTERVAL, i.e. HZ >> 1, which is 0.5 second. Both thecs_nsecand thewd_nsecvalue indicate that the actual watchdog interval was circa 14.5 seconds. Since the watchdog is executed in softirq context the expiration of the watchdog timer can get severely delayed on account of a ksoftirqd thread not getting to run in a timely manner. Surely, a system with such belated softirq execution is not working well and the scheduling issue should be looked into but the clocksource watchdog should be able to deal with it accordingly.The solution in this patch skips the current watchdog check if the watchdog interval exceeds 1.5 *
WATCHDOG_INTERVAL. Considering the maximum watchdog interval of 1.5 *WATCHDOG_INTERVAL, the current default uncertainty margin (of the TSC and HPET) corresponds to a limit on clocksource skew of 333 ppm (microseconds of skew per second). To keep the limit imposed by NTP (500 microseconds of skew per second) for all possible watchdog intervals, the margins would have to be scaled so that the threshold value is proportional to the length of the actual watchdog interval.
Quoted 1 line
Fixes 2e27e793e280 ("clocksource: Reduce clocksource-skew threshold")
IIUC, the issue could happen even before this commit? Though I do think this is good stuff for stable kernel.
Quoted 2 lines
Suggested-by Feng Tang <[email protected]>Signed-off-by Jiri Wiesner <[email protected]>
0Day robot reported some compiling issue. Other than that, it looks good to me, thanks!
Quoted 72 lines
--- kernel/time/clocksource.c | 28 ++++++++++++++++++++++++++-- 1 file changed, 26 insertions(+), 2 deletions(-)kernel/time/clocksource.c +26
-2@@ -98,7 +98,9 @@ static u64 suspend_start;/* * Interval: 0.5sec. */ -#define WATCHDOG_INTERVAL (HZ >> 1) +#define WATCHDOG_INTERVAL (HZ >> 1) +#define WATCHDOG_INTR_MAX_NS ((WATCHDOG_INTERVAL + (WATCHDOG_INTERVAL >> 1))\ + * NSEC_PER_SEC / HZ)/* * Threshold: 0.0312s, when doubled: 0.0625s. @@ -134,6 +136,7 @@ static DECLARE_WORK(watchdog_work, clocksource_watchdog_work);static DEFINE_SPINLOCK (watchdog_lock);static int watchdog_running;static atomic_t watchdog_reset_pending; +static int64_t watchdog_max_intr;static inline void clocksource_watchdog_lock (unsigned long *flags) {@@ -400,7 +403,7 @@ static void clocksource_watchdog(struct timer_list *unused) {u64 csnow, wdnow, cslast, wdlast, delta;int next_cpu, reset_pending; -int64_t wd_nsec, cs_nsec; +int64_t wd_nsec, cs_nsec, interval;struct clocksource *cs;enum wd_read_status read_ret;unsigned long extra_wait =0 ;@@ -470,6 +473,27 @@ static void clocksource_watchdog(struct timer_list *unused)if (atomic_read (&watchdog_reset_pending))continue ; +/* +* The processing of timer softirqs can get delayed (usually +* on account of ksoftirqd not getting to run in a timely +* manner), which causes the watchdog interval to stretch. +* Some clocksources, e.g. acpi_pm, cannot tolerate +* watchdog intervals longer than a few seconds. +* Skew detection may fail for longer watchdog intervals +* on account of fixed margins being used. +*/ + interval =max (cs_nsec, wd_nsec); +if (unlikely (interval >WATCHDOG_INTR_MAX_NS )) { +if (system_state >SYSTEM_SCHEDULING && + interval >2 * watchdog_max_intr) { + watchdog_max_intr = interval; +pr_warn ("Skipping watchdog check: cs_nsec: %lld wd_nsec: %lld\n" , + cs_nsec, wd_nsec); + } + watchdog_timer.expires = jiffies; +continue ; + } +/* Check the deviation from the watchdog clocksource. */ md = cs->uncertainty_margin + watchdog->uncertainty_margin;if (abs (cs_nsec - wd_nsec) > md) {Signature · 6 lines
2.35.3 -- Jiri Wiesner SUSE Labs
Quoted 5 lines · Feng Tang
Quoted 1 line · Jiri Wiesner
Fixes 2e27e793e280 ("clocksource: Reduce clocksource-skew threshold")IIUC, the issue could happen even before this commit? Though I do think this is good stuff for stable kernel.
Yes, it could happen before 2e27e793e280 but the threshold was so loose that it probably was an extremely rare event. Commit 2e27e793e280 lowered the threshold and this significantly increased the likelihood of skew detection failing for large watchdog intervals. We got a report of a kernel with 2e27e793e280 switching to the HPET but there were no failures with a kernel without 2e27e793e280 on the same fleet of 8 NUMA node machines.
Quoted 1 line
0Day robot reported some compiling issue.
I am going to submit a v2 of the patch fixing the error after we clarify the jiffies concern.
Signature · 2 lines
Jiri Wiesner SUSE Labs
kernel test robot
build botkernel test robot noticed "WARNING:at_kernel/time/clocksource-wdtest.c:#wdtest_func" on:
Hello,
kernel test robot noticed "WARNING:at_kernel/time/clocksource-wdtest.c:#wdtest_func" on:
commit: ceacf0b27b5d9cdc574f8d0a0bcb11d3272e7b9f ("[PATCH] clocksource: Skip watchdog check for large watchdog intervals")
url: https://github.com/intel-lab-lkp/linux/commits/Jiri-Wiesner/clocksource-Skip-watchdog-check-for-large-watchdog-intervals/20240103-192257
base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git da65f29dada7f7cbbf0d6375b88a0316f5f7d6f5
patch link: https://lore.kernel.org/all/20240103112113.GA6108@incl/
patch subject: [PATCH] clocksource: Skip watchdog check for large watchdog intervals
in testcase: boot
compiler: gcc-9
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
(please refer to attached dmesg/kmsg for entire log/backtrace)
+--------------------------------------------------------------------+------------+------------+ | | da65f29dad | ceacf0b27b | +--------------------------------------------------------------------+------------+------------+ | WARNING:at_kernel/time/clocksource-wdtest.c:#wdtest_func | 0 | 14 | | EIP:wdtest_func | 0 | 14 | +--------------------------------------------------------------------+------------+------------+
If you fix the issue in a separate patch/commit (i.e. not just a new version of the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <[email protected]>
| Closes: https://lore.kernel.org/oe-lkp/[email protected]
[ 54.778895][ T41] ------------[ cut here ]------------ [ 54.781279][ T41] WARNING: CPU: 0 PID: 41 at kernel/time/clocksource-wdtest.c:162 wdtest_func (kernel/time/clocksource-wdtest.c:162 (discriminator 1)) [ 54.785405][ T41] Modules linked in: [ 54.787152][ T41] CPU: 0 PID: 41 Comm: wdtest Tainted: G N 6.7.0-rc2-00014-gceacf0b27b5d #1 30e4ebd22e7da702dfdab1313ae74e5a246df970 [ 54.791633][ T41] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014 [ 54.795124][ T41] EIP: wdtest_func (kernel/time/clocksource-wdtest.c:162 (discriminator 1)) [ 54.796800][ T41] Code: ff 8d b4 26 00 00 00 00 66 90 0f 0b e9 ee fd ff ff 8d b4 26 00 00 00 00 66 90 0f 0b e9 08 fe ff ff 8d b4 26 00 00 00 00 66 90 <0f> 0b e9 76 ff ff ff cc cc cc cc cc cc cc cc cc 3e 8d 74 26 00 55 All code ======== 0: ff 8d b4 26 00 00 decl 0x26b4(%rbp) 6: 00 00 add %al,(%rax) 8: 66 90 xchg %ax,%ax a: 0f 0b ud2 c: e9 ee fd ff ff jmpq 0xfffffffffffffdff 11: 8d b4 26 00 00 00 00 lea 0x0(%rsi,%riz,1),%esi 18: 66 90 xchg %ax,%ax 1a: 0f 0b ud2 1c: e9 08 fe ff ff jmpq 0xfffffffffffffe29 21: 8d b4 26 00 00 00 00 lea 0x0(%rsi,%riz,1),%esi 28: 66 90 xchg %ax,%ax 2a:* 0f 0b ud2 <-- trapping instruction 2c: e9 76 ff ff ff jmpq 0xffffffffffffffa7 31: cc int3 32: cc int3 33: cc int3 34: cc int3 35: cc int3 36: cc int3 37: cc int3 38: cc int3 39: cc int3 3a: 3e 8d 74 26 00 lea %ds:0x0(%rsi,%riz,1),%esi 3f: 55 push %rbp
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2 2: e9 76 ff ff ff jmpq 0xffffffffffffff7d 7: cc int3 8: cc int3 9: cc int3 a: cc int3 b: cc int3 c: cc int3 d: cc int3 e: cc int3 f: cc int3 10: 3e 8d 74 26 00 lea %ds:0x0(%rsi,%riz,1),%esi 15: 55 push %rbp [ 54.801794][ T41] EAX: c4a1fe8c EBX: 00000004 ECX: 00000000 EDX: 00000000 [ 54.803569][ T41] ESI: c4a1ff2e EDI: 00000000 EBP: c74aff70 ESP: c74aff60 [ 54.805314][ T41] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068 EFLAGS: 00010246 [ 54.807278][ T41] CR0: 80050033 CR2: ffda9000 CR3: 05979000 CR4: 000406d0 [ 54.808856][ T41] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000 [ 54.810216][ T41] DR6: fffe0ff0 DR7: 00000400 [ 54.811218][ T41] Call Trace: [ 54.811950][ T41] ? show_regs (arch/x86/kernel/dumpstack.c:479 arch/x86/kernel/dumpstack.c:465) [ 54.812840][ T41] ? wdtest_func (kernel/time/clocksource-wdtest.c:162 (discriminator 1)) [ 54.813801][ T41] ? __warn (kernel/panic.c:677) [ 54.814643][ T41] ? wdtest_func (kernel/time/clocksource-wdtest.c:162 (discriminator 1)) [ 54.815628][ T41] ? report_bug (lib/bug.c:201 lib/bug.c:219) [ 54.816581][ T41] ? exc_overflow (arch/x86/kernel/traps.c:250) [ 54.817506][ T41] ? handle_bug (arch/x86/kernel/traps.c:216) [ 54.818420][ T41] ? exc_invalid_op (arch/x86/kernel/traps.c:258 (discriminator 1)) [ 54.819425][ T41] ? handle_exception (arch/x86/entry/entry_32.S:1056) [ 54.820438][ T41] ? exc_overflow (arch/x86/kernel/traps.c:250) [ 54.821374][ T41] ? wdtest_func (kernel/time/clocksource-wdtest.c:162 (discriminator 1)) [ 54.822318][ T41] ? exc_overflow (arch/x86/kernel/traps.c:250) [ 54.823284][ T41] ? wdtest_func (kernel/time/clocksource-wdtest.c:162 (discriminator 1)) [ 54.824248][ T41] kthread (kernel/kthread.c:388) [ 54.825093][ T41] ? wdtest_ktime_read (kernel/time/clocksource-wdtest.c:105) [ 54.826132][ T41] ? kthread_complete_and_exit (kernel/kthread.c:341) [ 54.827307][ T41] ret_from_fork (arch/x86/kernel/process.c:153) [ 54.828219][ T41] ? kthread_complete_and_exit (kernel/kthread.c:341) [ 54.829331][ T41] ret_from_fork_asm (arch/x86/entry/entry_32.S:741) [ 54.830310][ T41] entry_INT80_32 (arch/x86/entry/entry_32.S:947) [ 54.831287][ T41] irq event stamp: 879 [ 54.832154][ T41] hardirqs last enabled at (889): console_unlock (kernel/printk/printk.c:341 kernel/printk/printk.c:2706 kernel/printk/printk.c:3038) [ 54.833838][ T41] hardirqs last disabled at (898): console_unlock (kernel/printk/printk.c:339 kernel/printk/printk.c:2706 kernel/printk/printk.c:3038) [ 54.835567][ T41] softirqs last enabled at (918): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:400 kernel/softirq.c:582) [ 54.837246][ T41] softirqs last disabled at (907): do_softirq_own_stack (arch/x86/kernel/irq_32.c:57 arch/x86/kernel/irq_32.c:147) [ 54.839049][ T41] ---[ end trace 0000000000000000 ]--- [ 54.840178][ T41] clocksource: Not enough CPUs to check clocksource 'wdtest-ktime'. [ 54.841774][ T41] clocksource_wdtest: --- Done with test.
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20240108/[email protected]
Signature · 2 lines
0-DAY CI Kernel Test Service https://github.com/intel/lkp-tests/wiki
Quoted 6 lines · kernel test robot
commit:
ceacf0b27b5d9cdc574f8d0a0bcb11d3272e7b9f("[PATCH] clocksource: Skip watchdog check for large watchdog intervals")
url: https://github.com/intel-lab-lkp/linux/commits/Jiri-Wiesner/clocksource-Skip-watchdog-check-for-large-watchdog-intervals/20240103-192257
base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.gitda65f29dada7f7cbbf0d6375b88a0316f5f7d6f5
patch link: https://lore.kernel.org/all/20240103112113.GA6108@incl/
patch subject: [PATCH] clocksource: Skip watchdog check for large watchdog intervals
Quoted 6 lines
[ 54.778895][ T41] ------------[ cut here ]------------ [ 54.781279][ T41] WARNING: CPU: 0 PID: 41 at kernel/time/clocksource-wdtest.c:162 wdtest_func (kernel/time/clocksource-wdtest.c:162 (discriminator 1)) [ 54.785405][ T41] Modules linked in: [ 54.787152][ T41] CPU: 0 PID: 41 Comm: wdtest Tainted: G N 6.7.0-rc2-00014-gceacf0b27b5d #1 30e4ebd22e7da702dfdab1313ae74e5a246df970 [ 54.791633][ T41] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014 [ 54.795124][ T41] EIP: wdtest_func (kernel/time/clocksource-wdtest.c:162 (discriminator 1))
The code:
pr_info("--- Watchdog clock-value-fuzz error injection, expect clock skew and per-CPU mismatches.\n");
WRITE_ONCE(wdtest_ktime_read_fuzz, true);
schedule_timeout_uninterruptible(2 * HZ);
WARN_ON_ONCE(!(clocksource_wdtest_ktime.flags & CLOCK_SOURCE_UNSTABLE));The warning is the consequence of the watchdog not running on i386 builds of the kernel. The watchdog does not run because the "interval > WATCHDOG_INTR_MAX_NS" check is always true on account of the WATCHDOG_INTR_MAX_NS constant evaluating to a negative number on account of integer overflow.
Quoted 7 lines
[ 54.801794][ T41] EAX: c4a1fe8c EBX: 00000004 ECX: 00000000 EDX: 00000000 [ 54.803569][ T41] ESI: c4a1ff2e EDI: 00000000 EBP: c74aff70 ESP: c74aff60 [ 54.805314][ T41] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068 EFLAGS: 00010246 [ 54.807278][ T41] CR0: 80050033 CR2: ffda9000 CR3: 05979000 CR4: 000406d0 [ 54.808856][ T41] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000 [ 54.810216][ T41] DR6: fffe0ff0 DR7: 00000400 [ 54.811218][ T41] Call Trace:
Signature · 2 lines
Jiri Wiesner SUSE Labs