lkml.org 
[lkml]   [2020]   [Jan]   [10]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
Date
SubjectRe: [PATCH -rcu 2/2] kcsan: Rate-limit reporting per data races
On Thu, 9 Jan 2020 at 16:23, Marco Elver <elver@google.com> wrote:
>
> Adds support for rate limiting reports. This uses a time based rate
> limit, that limits any given data race report to no more than one in a
> fixed time window (default is 3 sec). This should prevent the console
> from being spammed with data race reports, that would render the system
> unusable.
>
> The implementation assumes that unique data races and the rate at which
> they occur is bounded, since we cannot store arbitrarily many past data
> race report information: we use a fixed-size array to store the required
> information. We cannot use kmalloc/krealloc and resize the list when
> needed, as reporting is triggered by the instrumentation calls; to
> permit using KCSAN on the allocators, we cannot (re-)allocate any memory
> during report generation (data races in the allocators lead to
> deadlock).
>
> Reported-by: Qian Cai <cai@lca.pw>
> Suggested-by: Paul E. McKenney <paulmck@kernel.org>
> Signed-off-by: Marco Elver <elver@google.com>
> ---
> kernel/kcsan/report.c | 112 ++++++++++++++++++++++++++++++++++++++----
> lib/Kconfig.kcsan | 10 ++++
> 2 files changed, 112 insertions(+), 10 deletions(-)
>
> diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c
> index 9f503ca2ff7a..e324af7d14c9 100644
> --- a/kernel/kcsan/report.c
> +++ b/kernel/kcsan/report.c
> @@ -1,6 +1,7 @@
> // SPDX-License-Identifier: GPL-2.0
>
> #include <linux/kernel.h>
> +#include <linux/ktime.h>
> #include <linux/preempt.h>
> #include <linux/printk.h>
> #include <linux/sched.h>
> @@ -31,12 +32,101 @@ static struct {
> int num_stack_entries;
> } other_info = { .ptr = NULL };
>
> +/*
> + * Information about reported data races; used to rate limit reporting.
> + */
> +struct report_time {
> + /*
> + * The last time the data race was reported.
> + */
> + ktime_t time;
> +
> + /*
> + * The frames of the 2 threads; if only 1 thread is known, one frame
> + * will be 0.
> + */
> + unsigned long frame1;
> + unsigned long frame2;
> +};
> +
> +/*
> + * Since we also want to be able to debug allocators with KCSAN, to avoid
> + * deadlock, report_times cannot be dynamically resized with krealloc in
> + * rate_limit_report.
> + *
> + * Therefore, we use a fixed-size array, which at most will occupy a page. This
> + * still adequately rate limits reports, assuming that a) number of unique data
> + * races is not excessive, and b) occurrence of unique data races within the
> + * same time window is limited.
> + */
> +#define REPORT_TIMES_MAX (PAGE_SIZE / sizeof(struct report_time))
> +#define REPORT_TIMES_SIZE \
> + (CONFIG_KCSAN_REPORT_ONCE_IN_MS > REPORT_TIMES_MAX ? \
> + REPORT_TIMES_MAX : \
> + CONFIG_KCSAN_REPORT_ONCE_IN_MS)
> +static struct report_time report_times[REPORT_TIMES_SIZE];
> +
> /*
> * This spinlock protects reporting and other_info, since other_info is usually
> * required when reporting.
> */
> static DEFINE_SPINLOCK(report_lock);
>
> +/*
> + * Checks if the data race identified by thread frames frame1 and frame2 has
> + * been reported since (now - KCSAN_REPORT_ONCE_IN_MS).
> + */
> +static bool rate_limit_report(unsigned long frame1, unsigned long frame2)
> +{
> + struct report_time *use_entry = &report_times[0];
> + ktime_t now;
> + ktime_t invalid_before;
> + int i;
> +
> + BUILD_BUG_ON(CONFIG_KCSAN_REPORT_ONCE_IN_MS != 0 && REPORT_TIMES_SIZE == 0);
> +
> + if (CONFIG_KCSAN_REPORT_ONCE_IN_MS == 0)
> + return false;
> +
> + now = ktime_get();
> + invalid_before = ktime_sub_ms(now, CONFIG_KCSAN_REPORT_ONCE_IN_MS);

Been thinking about this a bit more, and wondering if we should just
use jiffies here? Don't think we need the precision.

Thanks,
-- Marco

> + /* Check if a matching data race report exists. */
> + for (i = 0; i < REPORT_TIMES_SIZE; ++i) {
> + struct report_time *rt = &report_times[i];
> +
> + /*
> + * Must always select an entry for use to store info as we
> + * cannot resize report_times; at the end of the scan, use_entry
> + * will be the oldest entry, which ideally also happened before
> + * KCSAN_REPORT_ONCE_IN_MS ago.
> + */
> + if (ktime_before(rt->time, use_entry->time))
> + use_entry = rt;
> +
> + /*
> + * Initially, no need to check any further as this entry as well
> + * as following entries have never been used.
> + */
> + if (rt->time == 0)
> + break;
> +
> + /* Check if entry expired. */
> + if (ktime_before(rt->time, invalid_before))
> + continue; /* before KCSAN_REPORT_ONCE_IN_MS ago */
> +
> + /* Reported recently, check if data race matches. */
> + if ((rt->frame1 == frame1 && rt->frame2 == frame2) ||
> + (rt->frame1 == frame2 && rt->frame2 == frame1))
> + return true;
> + }
> +
> + use_entry->time = now;
> + use_entry->frame1 = frame1;
> + use_entry->frame2 = frame2;
> + return false;
> +}
> +
> /*
> * Special rules to skip reporting.
> */
> @@ -132,7 +222,9 @@ static bool print_report(const volatile void *ptr, size_t size, int access_type,
> unsigned long stack_entries[NUM_STACK_ENTRIES] = { 0 };
> int num_stack_entries = stack_trace_save(stack_entries, NUM_STACK_ENTRIES, 1);
> int skipnr = get_stack_skipnr(stack_entries, num_stack_entries);
> - int other_skipnr;
> + unsigned long this_frame = stack_entries[skipnr];
> + unsigned long other_frame = 0;
> + int other_skipnr = 0; /* silence uninit warnings */
>
> /*
> * Must check report filter rules before starting to print.
> @@ -143,34 +235,34 @@ static bool print_report(const volatile void *ptr, size_t size, int access_type,
> if (type == KCSAN_REPORT_RACE_SIGNAL) {
> other_skipnr = get_stack_skipnr(other_info.stack_entries,
> other_info.num_stack_entries);
> + other_frame = other_info.stack_entries[other_skipnr];
>
> /* @value_change is only known for the other thread */
> - if (skip_report(other_info.access_type, value_change,
> - other_info.stack_entries[other_skipnr]))
> + if (skip_report(other_info.access_type, value_change, other_frame))
> return false;
> }
>
> + if (rate_limit_report(this_frame, other_frame))
> + return false;
> +
> /* Print report header. */
> pr_err("==================================================================\n");
> switch (type) {
> case KCSAN_REPORT_RACE_SIGNAL: {
> - void *this_fn = (void *)stack_entries[skipnr];
> - void *other_fn = (void *)other_info.stack_entries[other_skipnr];
> int cmp;
>
> /*
> * Order functions lexographically for consistent bug titles.
> * Do not print offset of functions to keep title short.
> */
> - cmp = sym_strcmp(other_fn, this_fn);
> + cmp = sym_strcmp((void *)other_frame, (void *)this_frame);
> pr_err("BUG: KCSAN: data-race in %ps / %ps\n",
> - cmp < 0 ? other_fn : this_fn,
> - cmp < 0 ? this_fn : other_fn);
> + (void *)(cmp < 0 ? other_frame : this_frame),
> + (void *)(cmp < 0 ? this_frame : other_frame));
> } break;
>
> case KCSAN_REPORT_RACE_UNKNOWN_ORIGIN:
> - pr_err("BUG: KCSAN: data-race in %pS\n",
> - (void *)stack_entries[skipnr]);
> + pr_err("BUG: KCSAN: data-race in %pS\n", (void *)this_frame);
> break;
>
> default:
> diff --git a/lib/Kconfig.kcsan b/lib/Kconfig.kcsan
> index 3f78b1434375..3552990abcfe 100644
> --- a/lib/Kconfig.kcsan
> +++ b/lib/Kconfig.kcsan
> @@ -81,6 +81,16 @@ config KCSAN_SKIP_WATCH_RANDOMIZE
> KCSAN_WATCH_SKIP. If false, the chosen value is always
> KCSAN_WATCH_SKIP.
>
> +config KCSAN_REPORT_ONCE_IN_MS
> + int "Duration in milliseconds, in which any given data race is only reported once"
> + default 3000
> + help
> + Any given data race is only reported once in the defined time window.
> + Different data races may still generate reports within a duration
> + that is smaller than the duration defined here. This allows rate
> + limiting reporting to avoid flooding the console with reports.
> + Setting this to 0 disables rate limiting.
> +
> # Note that, while some of the below options could be turned into boot
> # parameters, to optimize for the common use-case, we avoid this because: (a)
> # it would impact performance (and we want to avoid static branch for all
> --
> 2.25.0.rc1.283.g88dfdc4193-goog
>

\
 
 \ /
  Last update: 2020-01-10 19:21    [W:0.090 / U:0.100 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site