A recent change to the clocksource watchdog in commit db3a34e17433
("clocksource: Retry clock read if long delays detected") has caused a
severe performance regression in TCP throughput tests. Netperf executed on
localhost was used for testing. The regression was more than 80%. On the
testing machine, the HPET clocksource was used to detect delays in reading
the TSC clocksource, which was the selected clocksource. In 10% of the
boots of the machine, TSC was marked unstable and the HPET clocksource was
selected as the best clocksource:
[ 13.669682] clocksource: timekeeping watchdog on CPU6: hpet read-back delay of 60666ns, attempt 4, marking unstable
[ 13.669827] tsc: Marking TSC unstable due to clocksource watchdog
[ 13.669917] TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
[ 13.670048] sched_clock: Marking unstable (11633513890, 2036384489)<-(13965149377, -295250974)
[ 13.672268] clocksource: Checking clocksource tsc synchronization from CPU 0 to CPUs 1-3,6-7.
[ 13.673148] clocksource: Switched to clocksource hpet
The earliest occurrence was this:
[ 3.423636] clocksource: timekeeping watchdog on CPU2: hpet read-back delay of 61833ns, attempt 4, marking unstable
[ 3.435182] tsc: Marking TSC unstable due to clocksource watchdog
[ 3.455228] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0, 0, 0, 0, 0, 0
[ 3.459182] hpet0: 8 comparators, 64-bit 24.000000 MHz counter
[ 3.471195] clocksource: Switched to clocksource hpet
The HPET clocksource suffers from lock contention when its read() function
is executed on multiple CPUs concurrently. A perf profile from the netperf
test (netperf ran on CPU 1, netserver ran on CPU 0):
Samples: 14K of event 'bus-cycles'
Overhead Command Shared Object Symbol CPU
43.83% netperf [kernel.vmlinux] [k] read_hpet 001
40.86% netserver [kernel.vmlinux] [k] read_hpet 000
2.27% netperf [kernel.vmlinux] [k] syscall_exit_to_user_mode 001
2.19% netserver [kernel.vmlinux] [k] syscall_exit_to_user_mode 000
0.96% netserver [kernel.vmlinux] [k] entry_SYSCALL_64 000
0.92% swapper [kernel.vmlinux] [k] read_hpet 000
For timestamping, TCP needs to execute ktime_get() in both the transmit
and receive path. Lock contention caused by HPET on 2 CPUs was enough to
lose 88% of the throughput measured with TSC (1.6 Gbit/s with HPET, 13
Gbit/s with TSC). The lock contention can also be reproduced by switching
to HPET via sysfs.
Tests were carried out to tweak the value of the
clocksource.max_cswd_read_retries parameter. The results indicate that
setting the number of retries to 50 mitigates the issue on the testing
machine, but it does not make it go away entirely:
clocksource.max_cswd_read_retries=3
Reboots: 100 TSC unstable: 10
Reboots: 300 TSC unstable: 32
clocksource.max_cswd_read_retries=5
Reboots: 100 TSC unstable: 5
clocksource.max_cswd_read_retries=10
Reboots: 100 TSC unstable: 6
clocksource.max_cswd_read_retries=50
Reboots: 100 TSC unstable: 0
Reboots: 300 TSC unstable: 1
The testing machine has a Skylake CPU (Intel(R) Xeon(R) CPU E3-1240 v5 @
3.50GHz) with 4 cores (8 CPUs when SMT is on). Perhaps, the number of
retries to mitigate the issue could depend on the number of online CPUs on
the system. Tweaking clocksource.verify_n_cpus had no effect:
clocksource.max_cswd_read_retries=3 clocksource.verify_n_cpus=1
Reboots: 100 TSC unstable: 11
The issue has been observed on both Intel and AMD machines, and it is not
specific to Skylake CPUs. The observed regression varies but, so far, tens
of per cent have been observed.
Signed-off-by: Jiri Wiesner <[email protected]>
---
Documentation/admin-guide/kernel-parameters.txt | 4 ++--
kernel/time/clocksource.c | 2 +-
2 files changed, 3 insertions(+), 3 deletions(-)
diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 43dc35fe5bc0..b8bebca0f520 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -603,8 +603,8 @@
clocksource.max_cswd_read_retries= [KNL]
Number of clocksource_watchdog() retries due to
external delays before the clock will be marked
- unstable. Defaults to three retries, that is,
- four attempts to read the clock under test.
+ unstable. Defaults to fifty retries, that is,
+ fiftyone attempts to read the clock under test.
clocksource.verify_n_cpus= [KNL]
Limit the number of CPUs checked for clocksources
diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
index b8a14d2fb5ba..c15de711617a 100644
--- a/kernel/time/clocksource.c
+++ b/kernel/time/clocksource.c
@@ -199,7 +199,7 @@ void clocksource_mark_unstable(struct clocksource *cs)
spin_unlock_irqrestore(&watchdog_lock, flags);
}
-ulong max_cswd_read_retries = 3;
+ulong max_cswd_read_retries = 50;
module_param(max_cswd_read_retries, ulong, 0644);
EXPORT_SYMBOL_GPL(max_cswd_read_retries);
static int verify_n_cpus = 8;
--
2.26.2
On Wed, Oct 27, 2021 at 06:43:52PM +0200, Jiri Wiesner wrote:
> A recent change to the clocksource watchdog in commit db3a34e17433
> ("clocksource: Retry clock read if long delays detected") has caused a
> severe performance regression in TCP throughput tests. Netperf executed on
> localhost was used for testing. The regression was more than 80%. On the
> testing machine, the HPET clocksource was used to detect delays in reading
> the TSC clocksource, which was the selected clocksource. In 10% of the
> boots of the machine, TSC was marked unstable and the HPET clocksource was
> selected as the best clocksource:
>
> [ 13.669682] clocksource: timekeeping watchdog on CPU6: hpet read-back delay of 60666ns, attempt 4, marking unstable
> [ 13.669827] tsc: Marking TSC unstable due to clocksource watchdog
> [ 13.669917] TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
> [ 13.670048] sched_clock: Marking unstable (11633513890, 2036384489)<-(13965149377, -295250974)
> [ 13.672268] clocksource: Checking clocksource tsc synchronization from CPU 0 to CPUs 1-3,6-7.
> [ 13.673148] clocksource: Switched to clocksource hpet
>
> The earliest occurrence was this:
>
> [ 3.423636] clocksource: timekeeping watchdog on CPU2: hpet read-back delay of 61833ns, attempt 4, marking unstable
> [ 3.435182] tsc: Marking TSC unstable due to clocksource watchdog
> [ 3.455228] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0, 0, 0, 0, 0, 0
> [ 3.459182] hpet0: 8 comparators, 64-bit 24.000000 MHz counter
> [ 3.471195] clocksource: Switched to clocksource hpet
>
> The HPET clocksource suffers from lock contention when its read() function
> is executed on multiple CPUs concurrently. A perf profile from the netperf
> test (netperf ran on CPU 1, netserver ran on CPU 0):
>
> Samples: 14K of event 'bus-cycles'
> Overhead Command Shared Object Symbol CPU
> 43.83% netperf [kernel.vmlinux] [k] read_hpet 001
> 40.86% netserver [kernel.vmlinux] [k] read_hpet 000
> 2.27% netperf [kernel.vmlinux] [k] syscall_exit_to_user_mode 001
> 2.19% netserver [kernel.vmlinux] [k] syscall_exit_to_user_mode 000
> 0.96% netserver [kernel.vmlinux] [k] entry_SYSCALL_64 000
> 0.92% swapper [kernel.vmlinux] [k] read_hpet 000
>
> For timestamping, TCP needs to execute ktime_get() in both the transmit
> and receive path. Lock contention caused by HPET on 2 CPUs was enough to
> lose 88% of the throughput measured with TSC (1.6 Gbit/s with HPET, 13
> Gbit/s with TSC). The lock contention can also be reproduced by switching
> to HPET via sysfs.
>
> Tests were carried out to tweak the value of the
> clocksource.max_cswd_read_retries parameter. The results indicate that
> setting the number of retries to 50 mitigates the issue on the testing
> machine, but it does not make it go away entirely:
>
> clocksource.max_cswd_read_retries=3
> Reboots: 100 TSC unstable: 10
> Reboots: 300 TSC unstable: 32
> clocksource.max_cswd_read_retries=5
> Reboots: 100 TSC unstable: 5
> clocksource.max_cswd_read_retries=10
> Reboots: 100 TSC unstable: 6
> clocksource.max_cswd_read_retries=50
> Reboots: 100 TSC unstable: 0
> Reboots: 300 TSC unstable: 1
>
> The testing machine has a Skylake CPU (Intel(R) Xeon(R) CPU E3-1240 v5 @
> 3.50GHz) with 4 cores (8 CPUs when SMT is on). Perhaps, the number of
> retries to mitigate the issue could depend on the number of online CPUs on
> the system. Tweaking clocksource.verify_n_cpus had no effect:
>
> clocksource.max_cswd_read_retries=3 clocksource.verify_n_cpus=1
> Reboots: 100 TSC unstable: 11
>
> The issue has been observed on both Intel and AMD machines, and it is not
> specific to Skylake CPUs. The observed regression varies but, so far, tens
> of per cent have been observed.
>
> Signed-off-by: Jiri Wiesner <[email protected]>
First, apologies for the inconvenience!
I had something like this pending, but people came up with other workloads
that resulted in repeated delays. In those cases, it does not make sense
to ever mark the affected clocksource unstable. This led me to the patch
shown below, which splats after about 100 consecutive long-delay retries,
but which avoids marking the clocksource unstable. This is queued on -rcu.
Does this work for you?
Thanx, Paul
------------------------------------------------------------------------
commit 9ec2a03bbf4bee3d9fbc02a402dee36efafc5a2d
Author: Paul E. McKenney <[email protected]>
Date: Thu May 27 11:03:28 2021 -0700
clocksource: Forgive repeated long-latency watchdog clocksource reads
Currently, the clocksource watchdog reacts to repeated long-latency
clocksource reads by marking that clocksource unstable on the theory that
these long-latency reads are a sign of a serious problem. And this theory
does in fact have real-world support in the form of firmware issues [1].
However, it is also possible to trigger this using stress-ng on what
the stress-ng man page terms "poorly designed hardware" [2]. And it
is not necessarily a bad thing for the kernel to diagnose cases where
heavy memory-contention workloads are being run on hardware that is not
designed for this sort of use.
Nevertheless, it is quite possible that real-world use will result in
some situation requiring that high-stress workloads run on hardware
not designed to accommodate them, and also requiring that the kernel
refrain from marking clocksources unstable.
Therefore, react to persistent long-latency reads by leaving the
clocksource alone, but using the old 62.5-millisecond skew-detection
threshold. In addition, the offending clocksource is marked for
re-initialization, which both restarts that clocksource with a clean bill
of health and avoids false-positive skew reports on later watchdog checks.
Once marked for re-initialization, the clocksource is not subjected to
further watchdog checking until a subsequent successful read from that
clocksource that is free of excessive delays.
However, if clocksource.max_cswd_coarse_reads consecutive clocksource read
attempts result in long latencies, a warning (splat) will be emitted.
This kernel boot parameter defaults to 100, and this warning can be
disabled by setting it to zero or to a negative value.
[ paulmck: Apply feedback from Chao Gao ]
Link: https://lore.kernel.org/lkml/20210513155515.GB23902@xsang-OptiPlex-9020/ # [1]
Link: https://lore.kernel.org/lkml/20210521083322.GG25531@xsang-OptiPlex-9020/ # [2]
Link: https://lore.kernel.org/lkml/20210521084405.GH25531@xsang-OptiPlex-9020/
Link: https://lore.kernel.org/lkml/20210511233403.GA2896757@paulmck-ThinkPad-P17-Gen-1/
Tested-by: Chao Gao <[email protected]>
Signed-off-by: Paul E. McKenney <[email protected]>
diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 316027c3aadc..61d2436ae9df 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -600,6 +600,14 @@
loops can be debugged more effectively on production
systems.
+ clocksource.max_cswd_coarse_reads= [KNL]
+ Number of consecutive clocksource_watchdog()
+ coarse reads (that is, clocksource reads that
+ were unduly delayed) that are permitted before
+ the kernel complains (gently). Set to a value
+ less than or equal to zero to suppress these
+ complaints.
+
clocksource.max_cswd_read_retries= [KNL]
Number of clocksource_watchdog() retries due to
external delays before the clock will be marked
diff --git a/include/linux/clocksource.h b/include/linux/clocksource.h
index 1d42d4b17327..3e925d9ffc31 100644
--- a/include/linux/clocksource.h
+++ b/include/linux/clocksource.h
@@ -110,6 +110,7 @@ struct clocksource {
int rating;
enum clocksource_ids id;
enum vdso_clock_mode vdso_clock_mode;
+ unsigned int n_coarse_reads;
unsigned long flags;
int (*enable)(struct clocksource *cs);
@@ -291,6 +292,7 @@ static inline void timer_probe(void) {}
#define TIMER_ACPI_DECLARE(name, table_id, fn) \
ACPI_DECLARE_PROBE_ENTRY(timer, name, table_id, 0, NULL, 0, fn)
+extern int max_cswd_coarse_reads;
extern ulong max_cswd_read_retries;
void clocksource_verify_percpu(struct clocksource *cs);
diff --git a/kernel/time/clocksource-wdtest.c b/kernel/time/clocksource-wdtest.c
index df922f49d171..7e82500c400b 100644
--- a/kernel/time/clocksource-wdtest.c
+++ b/kernel/time/clocksource-wdtest.c
@@ -145,13 +145,12 @@ static int wdtest_func(void *arg)
else if (i <= max_cswd_read_retries)
s = ", expect message";
else
- s = ", expect clock skew";
+ s = ", expect coarse-grained clock skew check and re-initialization";
pr_info("--- Watchdog with %dx error injection, %lu retries%s.\n", i, max_cswd_read_retries, s);
WRITE_ONCE(wdtest_ktime_read_ndelays, i);
schedule_timeout_uninterruptible(2 * HZ);
WARN_ON_ONCE(READ_ONCE(wdtest_ktime_read_ndelays));
- WARN_ON_ONCE((i <= max_cswd_read_retries) !=
- !(clocksource_wdtest_ktime.flags & CLOCK_SOURCE_UNSTABLE));
+ WARN_ON_ONCE(clocksource_wdtest_ktime.flags & CLOCK_SOURCE_UNSTABLE);
wdtest_ktime_clocksource_reset();
}
diff --git a/kernel/time/clocksource.c b/kernel/time/clocksource.c
index b8a14d2fb5ba..796a127aabb9 100644
--- a/kernel/time/clocksource.c
+++ b/kernel/time/clocksource.c
@@ -199,6 +199,9 @@ void clocksource_mark_unstable(struct clocksource *cs)
spin_unlock_irqrestore(&watchdog_lock, flags);
}
+int max_cswd_coarse_reads = 100;
+module_param(max_cswd_coarse_reads, int, 0644);
+EXPORT_SYMBOL_GPL(max_cswd_coarse_reads);
ulong max_cswd_read_retries = 3;
module_param(max_cswd_read_retries, ulong, 0644);
EXPORT_SYMBOL_GPL(max_cswd_read_retries);
@@ -226,13 +229,22 @@ static bool cs_watchdog_read(struct clocksource *cs, u64 *csnow, u64 *wdnow)
pr_warn("timekeeping watchdog on CPU%d: %s retried %d times before success\n",
smp_processor_id(), watchdog->name, nretries);
}
- return true;
+ cs->n_coarse_reads = 0;
+ return false;
}
+ WARN_ONCE(max_cswd_coarse_reads > 0 &&
+ !(++cs->n_coarse_reads % max_cswd_coarse_reads),
+ "timekeeping watchdog on CPU%d: %s %u consecutive coarse-grained reads\n", smp_processor_id(), watchdog->name, cs->n_coarse_reads);
}
- pr_warn("timekeeping watchdog on CPU%d: %s read-back delay of %lldns, attempt %d, marking unstable\n",
- smp_processor_id(), watchdog->name, wd_delay, nretries);
- return false;
+ if ((cs->flags & CLOCK_SOURCE_WATCHDOG) && !atomic_read(&watchdog_reset_pending)) {
+ pr_warn("timekeeping watchdog on CPU%d: %s read-back delay of %lldns, attempt %d, coarse-grained skew check followed by re-initialization\n",
+ smp_processor_id(), watchdog->name, wd_delay, nretries);
+ } else {
+ pr_warn("timekeeping watchdog on CPU%d: %s read-back delay of %lldns, attempt %d, awaiting re-initialization\n",
+ smp_processor_id(), watchdog->name, wd_delay, nretries);
+ }
+ return true;
}
static u64 csnow_mid;
@@ -356,6 +368,7 @@ static void clocksource_watchdog(struct timer_list *unused)
int next_cpu, reset_pending;
int64_t wd_nsec, cs_nsec;
struct clocksource *cs;
+ bool coarse;
u32 md;
spin_lock(&watchdog_lock);
@@ -373,16 +386,13 @@ static void clocksource_watchdog(struct timer_list *unused)
continue;
}
- if (!cs_watchdog_read(cs, &csnow, &wdnow)) {
- /* Clock readout unreliable, so give it up. */
- __clocksource_unstable(cs);
- continue;
- }
+ coarse = cs_watchdog_read(cs, &csnow, &wdnow);
/* Clocksource initialized ? */
if (!(cs->flags & CLOCK_SOURCE_WATCHDOG) ||
atomic_read(&watchdog_reset_pending)) {
- cs->flags |= CLOCK_SOURCE_WATCHDOG;
+ if (!coarse)
+ cs->flags |= CLOCK_SOURCE_WATCHDOG;
cs->wd_last = wdnow;
cs->cs_last = csnow;
continue;
@@ -403,7 +413,13 @@ static void clocksource_watchdog(struct timer_list *unused)
continue;
/* Check the deviation from the watchdog clocksource. */
- md = cs->uncertainty_margin + watchdog->uncertainty_margin;
+ if (coarse) {
+ md = 62500 * NSEC_PER_USEC;
+ cs->flags &= ~CLOCK_SOURCE_WATCHDOG;
+ pr_warn("timekeeping watchdog on CPU%d: %s coarse-grained %lu.%03lu ms clock-skew check followed by re-initialization\n", smp_processor_id(), watchdog->name, md / NSEC_PER_MSEC, md % NSEC_PER_MSEC / NSEC_PER_USEC);
+ } else {
+ md = cs->uncertainty_margin + watchdog->uncertainty_margin;
+ }
if (abs(cs_nsec - wd_nsec) > md) {
pr_warn("timekeeping watchdog on CPU%d: Marking clocksource '%s' as unstable because the skew is too large:\n",
smp_processor_id(), cs->name);
On Wed, Oct 27, 2021 at 02:38:29PM -0700, Paul E. McKenney wrote:
> I had something like this pending, but people came up with other workloads
> that resulted in repeated delays. In those cases, it does not make sense
> to ever mark the affected clocksource unstable. This led me to the patch
> shown below, which splats after about 100 consecutive long-delay retries,
> but which avoids marking the clocksource unstable. This is queued on -rcu.
>
> Does this work for you?
>
> commit 9ec2a03bbf4bee3d9fbc02a402dee36efafc5a2d
> Author: Paul E. McKenney <[email protected]>
> Date: Thu May 27 11:03:28 2021 -0700
>
> clocksource: Forgive repeated long-latency watchdog clocksource reads
Yes, it does. I have done 100 reboots of the testing machine (running 5.15-rc5 with the above patch applied) and TSC was stable every time. I am going to start a longer test of 300 reboots for good measure and report back next week. J.
On Thu, Oct 28, 2021 at 06:20:25PM +0200, Jiri Wiesner wrote:
> On Wed, Oct 27, 2021 at 02:38:29PM -0700, Paul E. McKenney wrote:
> > I had something like this pending, but people came up with other workloads
> > that resulted in repeated delays. In those cases, it does not make sense
> > to ever mark the affected clocksource unstable. This led me to the patch
> > shown below, which splats after about 100 consecutive long-delay retries,
> > but which avoids marking the clocksource unstable. This is queued on -rcu.
> >
> > Does this work for you?
> >
> > commit 9ec2a03bbf4bee3d9fbc02a402dee36efafc5a2d
> > Author: Paul E. McKenney <[email protected]>
> > Date: Thu May 27 11:03:28 2021 -0700
> >
> > clocksource: Forgive repeated long-latency watchdog clocksource reads
>
> Yes, it does. I have done 100 reboots of the testing machine (running
> 5.15-rc5 with the above patch applied) and TSC was stable every time. I
> am going to start a longer test of 300 reboots for good measure and
> report back next week. J.
Very good, and thank you for giving it a go! If it passes the upcoming
tests, may I have your Tested-by?
Thanx, Paul
On Thu, Oct 28, 2021 at 11:42:09AM -0700, Paul E. McKenney wrote:
> On Thu, Oct 28, 2021 at 06:20:25PM +0200, Jiri Wiesner wrote:
> > On Wed, Oct 27, 2021 at 02:38:29PM -0700, Paul E. McKenney wrote:
> > > I had something like this pending, but people came up with other workloads
> > > that resulted in repeated delays. In those cases, it does not make sense
> > > to ever mark the affected clocksource unstable. This led me to the patch
> > > shown below, which splats after about 100 consecutive long-delay retries,
> > > but which avoids marking the clocksource unstable. This is queued on -rcu.
> > >
> > > Does this work for you?
> > >
> > > commit 9ec2a03bbf4bee3d9fbc02a402dee36efafc5a2d
> > > Author: Paul E. McKenney <[email protected]>
> > > Date: Thu May 27 11:03:28 2021 -0700
> > >
> > > clocksource: Forgive repeated long-latency watchdog clocksource reads
> >
> > Yes, it does. I have done 100 reboots of the testing machine (running
> > 5.15-rc5 with the above patch applied) and TSC was stable every time. I
> > am going to start a longer test of 300 reboots for good measure and
> > report back next week. J.
>
> Very good, and thank you for giving it a go!
Thank you for the fix! It resolves several strange results we got in our performance testing.
> If it passes the upcoming tests
I have done 300 reboots of the testing machine. Again, TSC was stable every time.
> may I have your Tested-by?
Absolutely:
Tested-by: Jiri Wiesner <[email protected]>
On Mon, Nov 01, 2021 at 11:28:03AM +0100, Jiri Wiesner wrote:
> On Thu, Oct 28, 2021 at 11:42:09AM -0700, Paul E. McKenney wrote:
> > On Thu, Oct 28, 2021 at 06:20:25PM +0200, Jiri Wiesner wrote:
> > > On Wed, Oct 27, 2021 at 02:38:29PM -0700, Paul E. McKenney wrote:
> > > > I had something like this pending, but people came up with other workloads
> > > > that resulted in repeated delays. In those cases, it does not make sense
> > > > to ever mark the affected clocksource unstable. This led me to the patch
> > > > shown below, which splats after about 100 consecutive long-delay retries,
> > > > but which avoids marking the clocksource unstable. This is queued on -rcu.
> > > >
> > > > Does this work for you?
> > > >
> > > > commit 9ec2a03bbf4bee3d9fbc02a402dee36efafc5a2d
> > > > Author: Paul E. McKenney <[email protected]>
> > > > Date: Thu May 27 11:03:28 2021 -0700
> > > >
> > > > clocksource: Forgive repeated long-latency watchdog clocksource reads
> > >
> > > Yes, it does. I have done 100 reboots of the testing machine (running
> > > 5.15-rc5 with the above patch applied) and TSC was stable every time. I
> > > am going to start a longer test of 300 reboots for good measure and
> > > report back next week. J.
> >
> > Very good, and thank you for giving it a go!
>
> Thank you for the fix! It resolves several strange results we got in our performance testing.
>
> > If it passes the upcoming tests
>
> I have done 300 reboots of the testing machine. Again, TSC was stable every time.
>
> > may I have your Tested-by?
>
> Absolutely:
> Tested-by: Jiri Wiesner <[email protected]>
Applied, thank you!
Thanx, Paul