kernel: thread: race condition between create and join

[cfriedt]

Describe the bug
While investigating #56163 and digging through pthreads, testing showed that k_thread_create() and k_thread_join() also exhibit a race condition when re-using the same struct k_threads over and over again.

It's not something regularly seen in production at the moment, and was only detected by accident. Originally reported here.

On the kernel side, this mainly seems to be an issue with smp platforms.

Please also mention any information which could help others to understand
the problem you're facing:

• What target platform are you using? qemu_x86_64, qemu_cortex_a53_smp, qemu_riscv64_smp, qemu_riscv32_smp
• What have you tried to diagnose or workaround this issue? Wrote a testsuite ([DNM]: tests: posix: stress test for pthread_create and pthread_join #58115). Note, pthreads are disabled in this suite currently, so all failures are k_thread at the moment. It happens on all libc configurations and most smp platforms.
• Is this a regression? Probably not although it's hard to say.
• ...

To Reproduce
Steps to reproduce the behavior:

1. twister -i -T tests/posix/pthread_pressure
2. see errors

Expected behavior
Tests passing ideally 100% of the time on all platforms.

Impact
It seems to be the opposite of what several contributors and maintainers expect, and is possibly just a corner case that did not receive a lot of traffic.

Logs and console output
E.g.

ERROR   - *** Booting Zephyr OS build zephyr-v3.3.0-4124-gf67ff9c38640 ***
Running TESTSUITE pthread_pressure
===================================================================
START - test_k_thread_create_join
I: NUM_THREADS: 2
I: TEST_NUM_CPUS: 2
I: TEST_DURATION_S: 10
I: TEST_DELAY_US: 0
ASSERTION FAIL [0] @ WEST_TOPDIR/zephyr/kernel/sched.c:1785
	aborted _current back from dead
E:      a0: 0000000000000004    t0: 0000000000000000
E:      a1: 00000000000006f9    t1: 0000000000000009
E:      a2: 0000000080009d98    t2: 0000000000000000
E:      a3: 0000000000000000    t3: 0000000000000001
E:      a4: 0000000000000000    t4: 0000000000000023
E:      a5: 0000000000000001    t5: 000000008000b2b0
E:      a6: 0000000000000001    t6: 0000000080006514
E:      a7: 0000000000000001
E:      ra: 00000000800063c4
E:    mepc: 00000000800017e0
E: mstatus: 0000000a00021880
E: 
E: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
E: Current thread: (nil) (unknown)
E: Halting system

Environment (please complete the following information):

• OS: Linux
• Toolchain: Zephyr SDK v0.16.1
• Commit SHA or Version used: d01780f (main), v2.7.4

Additional context
#56163
#57637

[andyross]

OK, I have this sorta reproduced, but only on ARM. The test code as it is in the current PR doesn't run long enough for me to see failures, does it for you? If I crank the runtime up to an hour, I can see qemu_cortex_a53_smp panic fairly reliably after 2-10 minutes and ~2M iterations (pretty randomly, with a lot of spread).

I pushed the runtime all the way up to the 6-hour maximum and let it run at bedtime. And I saw one panic on qemu_x86_64[1] after ~5 hours. I haven't seen a failure on RISC-V at all.

The code below is the hello-world-ized variant I'm using right now that eliminates the yield/delay steps, the dependence on logging and pthreads, etc... It fails pretty reliably on a53 after about a minute, usually. (Oddly qemu just exits though and doesn't print a panic, did we break something with panics in hello_world apps?). As with the original, it's so far working reliably on the other SMP platforms.

So... basically my gut says that we have a SMP glitch in the arm64 code, almost certainly in interrupt entry/exit or context switch. It really doesn't seem to be a race in the kernel per se. One theory, inspired by the recent discovery that x86 qemu correctly implements an obscure 1-instruction interrupt shadow slow, is that qemu is actually doing pedantic memory reordering and we're missing some barrier instructions. Of all our platforms, arm64 has by far the trickiest memory model.

Unless there's an easier way to repro this on other platforms?

[1] The huge difference in scale here points to this being a separate bug, IMHO. But once you get this far down to failures in the one-in-a-billion range, we need to start accepting that bugs in qemu or memory glitches on the host processor are possibilities.

#include <zephyr/kernel.h>

#define NTHREAD 2
#define STACKSZ 4096
#define LOG_INTERVAL_MS 2000

struct k_thread threads[NTHREAD];
K_KERNEL_STACK_ARRAY_DEFINE(stacks, NTHREAD, STACKSZ);

volatile int alive[NTHREAD];

void thread_fn(void *a, void *b, void *c)
{
	alive[(long)a] = true;
}

void spawn(int i)
{
	k_thread_create(&threads[i], stacks[i], STACKSZ,
			thread_fn, (void *)(long)i, NULL, NULL,
			-2, 0, K_NO_WAIT);
}

int main(void)
{
	for (int i = 0; i < NTHREAD; i++) {
		spawn(i);
	}

	uint64_t n = 0, next_log_ms = 0;

	while (true) {
		for (int i = 0; i < NTHREAD; i++) {
			if (alive[i]) {
				k_thread_join(&threads[i], K_FOREVER);
				alive[i] = false;
				spawn(i);
				n++;
			}
		}

		uint64_t now = k_uptime_get();

		if (now > next_log_ms) {
			printk("%lld joins in %lld ms\n", n, now);
			next_log_ms += LOG_INTERVAL_MS;
		}
	}

	return 0;
}

[andyross]

Flag @carlocaione and @povergoing for the seeming arm64 dependence. Also @dcpleung and @npitre are usually helpful on this sort of thing.

[npitre]

I confirm having the same experience: reproduced 3 times on ARM64 within
2 minutes (twice within 1 minute). Not reproducible on RISCV after
several hours.

Obviously the reported error dump above comes from RISCV.

@cfriedt: Can you test with the simplified code from @andyross and confirm
if you still get a failure on RISCV?

Oddly qemu just exits though and doesn't print a panic, did we break
something with panics in hello_world apps?

By default the hello_world app is configured with CONFIG_LOG and
CONFIG_ASSERT unset. You need at least the former to get a printed panic.

[andyross]

Been running these all morning collecting statistics. Both qemu_riscv32_smp and qemu_riscv64_smp have been running without trouble for 6.1 hours now, reaching 1.84G and 1.49G joins respectively (qemu runs at different rates for different architectures). To the extent we can measure right now, joins on these architectures are 100% bug free.

As mentioned, arm64 is the problem child. The rig above dies (usually just exiting qemu, sometimes with a deadlock) relatively promptly for me. Over a few dozen runs I measured an average uptime of 6.5M joins and 72 seconds.

But x86_64 has a real, measurable issue too: checking and restarting regularly, I've seen a total of seven individual failures with an average uptime of 344M joins in 38 minutes (it turns out that x86 is about 60% faster in qemu, which I guess isn't surprising given that it matches the host architecture).

Not sure where to go from here though beyond careful reading of the platform interrupt and context switch code...

[cfriedt]

@cfriedt: Can you test with the simplified code from @andyross and confirm
if you still get a failure on RISCV?

I'll give it a run later this evening

[cfriedt]

@cfriedt: Can you test with the simplified code from @andyross and confirm
if you still get a failure on RISCV?

I'll give it a run later this evening

Have some cycles now...

[cfriedt]

@andyross, @npitre - Definitely qemu_cortex_a53_smp is problematic and reproducibly fails multiple times within 1 minute.

(.venv) cfriedt@ubuntu:~/zephyrproject/zephyr$ west build -p auto -b qemu_cortex_a53_smp -t run samples/kernel/pressure/
-- west build: running target run
[0/1] To exit from QEMU enter: 'CTRL+a, x'[QEMU] CPU: cortex-a53
*** Booting Zephyr OS build zephyr-v3.3.0-4125-g86c5bf81b4e5 ***
Secondary CPU core 1 (MPID:0x1) is up
490 joins in 10 ms
299586 joins in 2010 ms
565609 joins in 4010 ms
833152 joins in 6010 ms
1094691 joins in 8010 ms
1366318 joins in 10010 ms
1639701 joins in 12010 ms
1905485 joins in 14010 ms
2168655 joins in 16010 ms
2421484 joins in 18010 ms
2685592 joins in 20010 ms
(.venv) cfriedt@ubuntu:~/zephyrproject/zephyr$ west build -p auto -b qemu_cortex_a53_smp -t run samples/kernel/pressure/
-- west build: running target run
[0/1] To exit from QEMU enter: 'CTRL+a, x'[QEMU] CPU: cortex-a53
*** Booting Zephyr OS build zephyr-v3.3.0-4125-g86c5bf81b4e5 ***
Secondary CPU core 1 (MPID:0x1) is up
452 joins in 10 ms

Cannot reproduce with qemu_riscv64_smp or qemu_riscv32_smp so far.

[cfriedt]

Reworked the pthread_pressure test somewhat. I didn't realize just how bad it is, but most certainly, when there are conditionals in the hot path or the host system is under heavy load, there is real and measurable "scheduler noise" (jitter).

Even just zassert*() macros checking the return values every time are sufficient to bring down Andy's test above on qemu_riscv64_smp.

Whether that involves missing barriers or simply opportunistic scheduling, or simply Qemu guessing wrong, it's hard to say.

In any case, what I did with my test was I created a CONFIG_TEST_EXTRA_ASSERTIONS option. If people are running it on hardware, then it's something that may be good to enable. I'm not going to enable it right now, but definitely, without the extra assertions, I see no issues.

Likely, for the test I've written, I'll set the integration platform to qemu_riscv64_smp and will likely also skip k_thread testing.

The main assertion that I was trying to avoid was aborted _current back from dead, and I'm no longer seeing that now.

*** Booting Zephyr OS build zephyr-v3.3.0-4131-g26b93375e256 ***
Running TESTSUITE pthread_pressure
===================================================================
START - test_k_thread_create_join
BOARD: qemu_riscv64_smp
NUM_THREADS: 2
TEST_NUM_CPUS: 2
TEST_DURATION_S: 10
TEST_DELAY_US: 0
Thread 0 created and joined 5144 times
Thread 1 created and joined 5143 times
Thread 0 created and joined 10205 times
Thread 1 created and joined 10204 times
Thread 0 created and joined 15363 times
Thread 1 created and joined 15361 times
Thread 0 created and joined 20464 times
Thread 1 created and joined 20461 times
Thread 0 created and joined 25632 times
Thread 1 created and joined 25628 times
Thread 0 created and joined 30751 times
Thread 1 created and joined 30747 times
Thread 0 created and joined 35922 times
Thread 1 created and joined 35917 times
Thread 0 created and joined 41028 times
Thread 1 created and joined 41023 times
Thread 0 created and joined 46109 times
Thread 1 created and joined 46104 times
Thread 0 created and joined 50708 times
Thread 1 created and joined 50703 times
 PASS - test_k_thread_create_join in 9.997 seconds
===================================================================
START - test_pthread_create_join
NUM_THREADS: 2
TEST_NUM_CPUS: 2
TEST_DURATION_S: 10
TEST_DELAY_US: 0
Thread 0 created and joined 3912 times
Thread 1 created and joined 3912 times
Thread 0 created and joined 7853 times
Thread 1 created and joined 7853 times
Thread 0 created and joined 11788 times
Thread 1 created and joined 11788 times
Thread 0 created and joined 15726 times
Thread 1 created and joined 15726 times
Thread 0 created and joined 19673 times
Thread 1 created and joined 19673 times
Thread 0 created and joined 23613 times
Thread 1 created and joined 23613 times
Thread 0 created and joined 27539 times
Thread 1 created and joined 27539 times
Thread 0 created and joined 31393 times
Thread 1 created and joined 31393 times
Thread 0 created and joined 35324 times
Thread 1 created and joined 35324 times
Thread 0 created and joined 38771 times
Thread 1 created and joined 38771 times
 PASS - test_pthread_create_join in 10.000 seconds
===================================================================
TESTSUITE pthread_pressure succeeded

------ TESTSUITE SUMMARY START ------

SUITE PASS - 100.00% [pthread_pressure]: pass = 2, fail = 0, skip = 0, total = 2 duration = 19.997 seconds
 - PASS - [pthread_pressure.test_k_thread_create_join] duration = 9.997 seconds
 - PASS - [pthread_pressure.test_pthread_create_join] duration = 10.000 seconds

------ TESTSUITE SUMMARY END ------

===================================================================
PROJECT EXECUTION SUCCESSFUL

[cfriedt]

Even running under Twister, so much additional scheduler noise is created that most platforms will fail.

It's not something that can be easily fixed, I would say.