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
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=d835c53d1a5e27922fcd1fbefc926a74790156c... ]
Thanks, -- Marco
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=d835c53d1a5e27922fcd1fbefc926a74790156c... ]
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=03911d1370705fe3667dae48c9cda46d982cea3... https://syzkaller.appspot.com/bug?id=440c51f56c3f3923f9b364679da48b0c1a0bdfe...
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
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=f5a5ed5b2b6c3e92bc1a9dadc934c44ee3ba4ec... https://syzkaller.appspot.com/bug?id=36fc4ad4cac8b8fc8a40713f38818488faa9e9f...
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=e613fc2458de1c8a544738baf46286a99e8e746... https://syzkaller.appspot.com/bug?id=55bc81ed3b2f620f64fa6209000f40ace4469bc... https://syzkaller.appspot.com/bug?id=972894de81731fc8f62b8220e7cd5153d3e0d38... .....
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
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=f5a5ed5b2b6c3e92bc1a9dadc934c44ee3ba4ec... https://syzkaller.appspot.com/bug?id=36fc4ad4cac8b8fc8a40713f38818488faa9e9f...
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=e613fc2458de1c8a544738baf46286a99e8e746... https://syzkaller.appspot.com/bug?id=55bc81ed3b2f620f64fa6209000f40ace4469bc... https://syzkaller.appspot.com/bug?id=972894de81731fc8f62b8220e7cd5153d3e0d38... .....
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
-
Marco Elver -
Naresh Kamboju -
Thomas Gleixner