BUG: KCSAN: data-race in tick_nohz_next_event / tick_nohz_stop_tick

BUG: KCSAN: data-race in tick_nohz_next_event / tick_nohz_stop_tick

[Naresh Kamboju]

LKFT started testing KCSAN enabled kernel from the linux next tree.
Here we have found BUG: KCSAN: data-race in tick_nohz_next_event /
tick_nohz_stop_tick

This report is from an x86_64 machine clang-11 linux next 20201201.
Since we are running for the first time we do not call this regression.

[   47.811425] BUG: KCSAN: data-race in tick_nohz_next_event /
tick_nohz_stop_tick
[   47.818738]
[   47.820239] write to 0xffffffffa4cbe920 of 4 bytes by task 0 on cpu 2:
[   47.826766]  tick_nohz_stop_tick+0x8b/0x310
[   47.830951]  tick_nohz_idle_stop_tick+0xcb/0x170
[   47.835571]  do_idle+0x193/0x250
[   47.838804]  cpu_startup_entry+0x25/0x30
[   47.842728]  start_secondary+0xa0/0xb0
[   47.846482]  secondary_startup_64_no_verify+0xc2/0xcb
[   47.851531]
[   47.853034] read to 0xffffffffa4cbe920 of 4 bytes by task 0 on cpu 3:
[   47.859473]  tick_nohz_next_event+0x165/0x1e0
[   47.863831]  tick_nohz_get_sleep_length+0x94/0xd0
[   47.868539]  menu_select+0x250/0xac0
[   47.872116]  cpuidle_select+0x47/0x50
[   47.875781]  do_idle+0x17c/0x250
[   47.879015]  cpu_startup_entry+0x25/0x30
[   47.882942]  start_secondary+0xa0/0xb0
[   47.886694]  secondary_startup_64_no_verify+0xc2/0xcb
[   47.891743]
[   47.893234] Reported by Kernel Concurrency Sanitizer on:
[   47.898541] CPU: 3 PID: 0 Comm: swapper/3 Not tainted
5.10.0-rc6-next-20201201 #2
[   47.906017] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.2 05/23/2018

metadata:
    git_repo: https://gitlab.com/aroxell/lkft-linux-next
    target_arch: x86
    toolchain: clang-11
    git_describe: next-20201201
    download_url: https://builds.tuxbuild.com/1l8eiWgGMi6W4aDobjAAlOleFVl/

Full test log link,
https://lkft.validation.linaro.org/scheduler/job/2002643#L2019

-- 
Linaro LKFT
https://lkft.linaro.org

Re: BUG: KCSAN: data-race in tick_nohz_next_event / tick_nohz_stop_tick

[Marco Elver]

On Fri, 4 Dec 2020 at 20:04, Naresh Kamboju <naresh.kamboju@linaro.org> wrote:
> LKFT started testing KCSAN enabled kernel from the linux next tree.
> Here we have found BUG: KCSAN: data-race in tick_nohz_next_event /
> tick_nohz_stop_tick

Thank you for looking into KCSAN. Would it be possible to collect
these reports in a moderation queue for now?

I'm currently trying to work out a strategy on how to best proceed
with all the data races in the kernel. We do know there are plenty. On
syzbot's internal moderation queue, we're currently looking at >300 of
them (some here:
https://syzkaller.appspot.com/upstream?manager=ci2-upstream-kcsan-gce).
Part of this strategy involves prioritizing certain concurrency bug
classes. Let's define the following buckets for concurrency bugs:

A. Data race, where failure due to current compilers is unlikely
(supposedly "benign"); merely marking the accesses
appropriately is sufficient. Finding a crash for these will
require a miscompilation, but otherwise look "benign" at the
C-language level.

B. Race-condition bugs where the bug manifests as a data race,
too -- simply marking things doesn't fix the problem. These
are the types of bugs where a data race would point out a
more severe issue.

C. Race-condition bugs where the bug never manifests as a data
race. An example of these might be 2 threads that acquire the
necessary locks, yet some interleaving of them still results
in a bug (e.g. because the logic inside the critical sections
is buggy). These are harder to detect with KCSAN as-is, and
require using ASSERT_EXCLUSIVE_ACCESS() or
ASSERT_EXCLUSIVE_WRITER() in the right place. See
https://lwn.net/Articles/816854/.

One problem currently is that the kernel has quite a lot type-(A)
reports if we run KCSAN, which makes it harder to identify bugs of type
(B) and (C). My wish for the future is that we can get to a place, where
the kernel has almost no unintentional (A) issues, so that we primarily
find (B) and (C) bugs.

The report below looks to be of type (A). Generally, the best strategy
for resolving these is to send a patch, and not a report. However, be
aware that sometimes it is really quite difficult to say if we're
looking at a type (A) or (B) issue, in which case it may still be fair
to send a report and briefly describe what you think is happening
(because that'll increase the likelihood of getting a response). I
recommend also reading "Developer/Maintainer data-race strategies" in
https://lwn.net/Articles/816854/ -- specifically note "[...] you
should not respond to KCSAN reports by mindlessly adding READ_ONCE(),
data_race(), and WRITE_ONCE(). Instead, a patch addressing a KCSAN
report must clearly identify the fix's approach and why that approach
is appropriate."

I recommend reading https://lwn.net/Articles/816850/ for more details.

> This report is from an x86_64 machine clang-11 linux next 20201201.
> Since we are running for the first time we do not call this regression.
>
> [   47.811425] BUG: KCSAN: data-race in tick_nohz_next_event /
> tick_nohz_stop_tick
> [   47.818738]
> [   47.820239] write to 0xffffffffa4cbe920 of 4 bytes by task 0 on cpu 2:
> [   47.826766]  tick_nohz_stop_tick+0x8b/0x310
> [   47.830951]  tick_nohz_idle_stop_tick+0xcb/0x170
> [   47.835571]  do_idle+0x193/0x250
> [   47.838804]  cpu_startup_entry+0x25/0x30
> [   47.842728]  start_secondary+0xa0/0xb0
> [   47.846482]  secondary_startup_64_no_verify+0xc2/0xcb
> [   47.851531]
> [   47.853034] read to 0xffffffffa4cbe920 of 4 bytes by task 0 on cpu 3:
> [   47.859473]  tick_nohz_next_event+0x165/0x1e0
> [   47.863831]  tick_nohz_get_sleep_length+0x94/0xd0
> [   47.868539]  menu_select+0x250/0xac0
> [   47.872116]  cpuidle_select+0x47/0x50
> [   47.875781]  do_idle+0x17c/0x250
> [   47.879015]  cpu_startup_entry+0x25/0x30
> [   47.882942]  start_secondary+0xa0/0xb0
> [   47.886694]  secondary_startup_64_no_verify+0xc2/0xcb
> [   47.891743]
> [   47.893234] Reported by Kernel Concurrency Sanitizer on:
> [   47.898541] CPU: 3 PID: 0 Comm: swapper/3 Not tainted
> 5.10.0-rc6-next-20201201 #2
> [   47.906017] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.2 05/23/2018

This report should have line numbers, otherwise it's impossible to say
which accesses are racing.

[ For those curious, this is the same report on syzbot's moderation
queue, with line numbers:
https://syzkaller.appspot.com/bug?id=d835c53d1a5e27922fcd1fbefc926a74790156cb
]

Thanks,
-- Marco

Re: BUG: KCSAN: data-race in tick_nohz_next_event / tick_nohz_stop_tick

[Thomas Gleixner]

On Fri, Dec 04 2020 at 20:53, Marco Elver wrote:
> On Fri, 4 Dec 2020 at 20:04, Naresh Kamboju <naresh.kamboju@linaro.org> wrote:
>> LKFT started testing KCSAN enabled kernel from the linux next tree.
>> Here we have found BUG: KCSAN: data-race in tick_nohz_next_event /
>> tick_nohz_stop_tick
>
> Thank you for looking into KCSAN. Would it be possible to collect
> these reports in a moderation queue for now?

Yes please. This is the forth or fifth incarnation of report for that
data race in the tick code and I just did not come around to work on it.

> I'm currently trying to work out a strategy on how to best proceed
> with all the data races in the kernel. We do know there are plenty. On

I think having a central point where the reports are collected, i.e. a
moderation queue, is a good start. Reports like the one at hand should
stick out because they should reproduce pretty instantanious as it's an
intentional one and on NOHZ=y machines where CPUs are not fully loaded
its hard not to detect it :)

> The report below looks to be of type (A). Generally, the best strategy
> for resolving these is to send a patch, and not a report. However, be
> aware that sometimes it is really quite difficult to say if we're
> looking at a type (A) or (B) issue, in which case it may still be fair
> to send a report and briefly describe what you think is happening
> (because that'll increase the likelihood of getting a response). I
> recommend also reading "Developer/Maintainer data-race strategies" in
> https://lwn.net/Articles/816854/ -- specifically note "[...] you
> should not respond to KCSAN reports by mindlessly adding READ_ONCE(),
> data_race(), and WRITE_ONCE(). Instead, a patch addressing a KCSAN
> report must clearly identify the fix's approach and why that approach
> is appropriate."

Yes. I've seen a fair amount of 'Fix KCSAN warnings' patches which just
slap READ/WRITE_ONCE() all over the place to shut it up without any
justification. Most of them ended in limbo when asking for that
justification.

But the problem is that it is not necessarily trivial to understand code
when there are intentional data races without a lot of comments - guilty
as charged in this case. I actually felt so guilty that I sat down and
annotated and documented it now. Took me quite some time to comment all
the racy reads correctly as I really had to think about each of them
carefully again.

OTOH, in general it's a good exercise for reporters to do such analysis
and maintainers are happy to help when the analysis is not entirely
correct or comes to the wrong conclusion, e.g. assuming type B when it's
actually A. That's way better than just reports or mechanical "paper
over it" patches.

Just getting the reports over and over is not going to solve anything
because as in this case there is always more important stuff to do and
to the people familiar with the code it's clear that it's A and
therefore not urgent.

But that causes the problem that the A types are staying around for a
long time and blend over the B/C issues which are the real interesting
ones.

> This report should have line numbers, otherwise it's impossible to say
> which accesses are racing.

I just had to look at the function names to know that it is about:

tick_do_timer_cpu :)

> [ For those curious, this is the same report on syzbot's moderation
> queue, with line numbers:
> https://syzkaller.appspot.com/bug?id=d835c53d1a5e27922fcd1fbefc926a74790156cb
> ]

Confirmed :)

So you have quite some of the same report collected and there are a few
other patterns which are all related to tick_do_timer_cpu, so I assume
there is a stash of the other variants as well. And indeed:

 https://syzkaller.appspot.com/bug?id=03911d1370705fe3667dae48c9cda46d982cea30
 https://syzkaller.appspot.com/bug?id=440c51f56c3f3923f9b364679da48b0c1a0bdfe7

It might be useful to find the actual variable, data member or whatever
which is involved in the various reports and if there is a match then
the reports could be aggregated. The 3 patterns here are not even the
complete possible picture.

So if you sum them up: 58 + 148 + 205 instances then their weight
becomes more significant as well.

/me goes back to read the tick_do_timer_cpu comments once more before
posting.

Thanks,

        tglx

Re: BUG: KCSAN: data-race in tick_nohz_next_event / tick_nohz_stop_tick

[Thomas Gleixner]

On Sat, Dec 05 2020 at 19:18, Thomas Gleixner wrote:
> On Fri, Dec 04 2020 at 20:53, Marco Elver wrote:
> It might be useful to find the actual variable, data member or whatever
> which is involved in the various reports and if there is a match then
> the reports could be aggregated. The 3 patterns here are not even the
> complete possible picture.
>
> So if you sum them up: 58 + 148 + 205 instances then their weight
> becomes more significant as well.

I just looked into the moderation queue and picked stuff which I'm
familiar with from the subject line.

There are quite some reports which have a different trigger scenario,
but are all related to the same issue.

  https://syzkaller.appspot.com/bug?id=f5a5ed5b2b6c3e92bc1a9dadc934c44ee3ba4ec5
  https://syzkaller.appspot.com/bug?id=36fc4ad4cac8b8fc8a40713f38818488faa9e9f4

are just variations of the same problem timer_base->running_timer being
set to NULL without holding the base lock. Safe, but insanely hard to
explain why :)

Next:

  https://syzkaller.appspot.com/bug?id=e613fc2458de1c8a544738baf46286a99e8e7460
  https://syzkaller.appspot.com/bug?id=55bc81ed3b2f620f64fa6209000f40ace4469bc0
  https://syzkaller.appspot.com/bug?id=972894de81731fc8f62b8220e7cd5153d3e0d383
  .....

That's just the ones which caught my eye and all are related to
task->flags usage. There are tons more judging from the subject
lines.

So you really want to look at them as classes of problems and not as
individual scenarios.

Thanks,

        tglx

Re: BUG: KCSAN: data-race in tick_nohz_next_event / tick_nohz_stop_tick

[Marco Elver]

On Sun, 6 Dec 2020 at 00:47, Thomas Gleixner <tglx@linutronix.de> wrote:
> On Sat, Dec 05 2020 at 19:18, Thomas Gleixner wrote:
> > On Fri, Dec 04 2020 at 20:53, Marco Elver wrote:
> > It might be useful to find the actual variable, data member or whatever
> > which is involved in the various reports and if there is a match then
> > the reports could be aggregated. The 3 patterns here are not even the
> > complete possible picture.
> >
> > So if you sum them up: 58 + 148 + 205 instances then their weight
> > becomes more significant as well.
>
> I just looked into the moderation queue and picked stuff which I'm
> familiar with from the subject line.

We managed to push (almost) everything that was still in private
moderation to public moderation, so now there's even more to look at:
https://syzkaller.appspot.com/upstream?manager=ci2-upstream-kcsan-gce
:-)

> There are quite some reports which have a different trigger scenario,
> but are all related to the same issue.
>
>   https://syzkaller.appspot.com/bug?id=f5a5ed5b2b6c3e92bc1a9dadc934c44ee3ba4ec5
>   https://syzkaller.appspot.com/bug?id=36fc4ad4cac8b8fc8a40713f38818488faa9e9f4
>
> are just variations of the same problem timer_base->running_timer being
> set to NULL without holding the base lock. Safe, but insanely hard to
> explain why :)
>
> Next:
>
>   https://syzkaller.appspot.com/bug?id=e613fc2458de1c8a544738baf46286a99e8e7460
>   https://syzkaller.appspot.com/bug?id=55bc81ed3b2f620f64fa6209000f40ace4469bc0
>   https://syzkaller.appspot.com/bug?id=972894de81731fc8f62b8220e7cd5153d3e0d383
>   .....
>
> That's just the ones which caught my eye and all are related to
> task->flags usage. There are tons more judging from the subject
> lines.
>
> So you really want to look at them as classes of problems and not as
> individual scenarios.

Regarding auto-dedup: as you suggest, it'd make this straightforward
if we had the variable name -- it turns out that's not so trivial. I
think we need compiler support for that, or is there some existing
infrastructure that can just tell us the canonical variable name if it
points into a struct or global? For globals it's fine, but for
arbitrary pointers that point into structs, I don't see how we could
do it without compiler support e.g. mapping PC->variable name (we need
to map instructions back to the variable names they access).

Any precedence for this? [+Cc linux-toolchains@vger.kernel.org]

Thanks,
-- Marco