Hi,
On Tue, Jul 19, 2022 at 3:41 AM Hillf Danton <hdanton@xxxxxxxx> wrote:
>
> On Mon, 18 Jul 2022 17:27:28 -0700 Doug Anderson <dianders@xxxxxxxxxxxx> wrote:
> >
> > I've been tracking down an occasional hang at reboot on my system and
> > I've ended up at this as the first bad commit. I will not pretend to
> > understand the intricacies of the rwsem implementation, but I can
> > describe what I saw. I have also produced a fairly small test case
> > that reproduces the problem rather quickly.
> >
> > First, what I saw:
> >
> > My system failed to fully boot up and eventually the "hung task"
> > detection kicked in. Many tasks in my system were hung all waiting on
> > the "kernfs_rwsem". No tasks actually had the semaphore--it only had
> > tasks waiting.
> >
> > Of the tasks waiting, 3 of them were doing a down_write(). The rest
> > were all waiting on down_read().
> >
> > 2 of the tasks waiting on the down_write() were locked to CPU0. One of
> > these tasks was a bound kworker. Another of these tasks was a threaded
> > IRQ handler. The threaded IRQ handler was set to "real time" priority
> > because in setup_irq_thread() you can see the call to
> > sched_set_fifo().
> >
> > At the time the hung task detector kicked in, the real time task was
> > actually active on a CPU. Specifically it was running in the for (;;)
> > loop in rwsem_down_write_slowpath(). rwsem_try_write_lock() had
> > clearly just returned false which meant we didn't get the lock.
> > Everything else was sitting in schedule().
> >
> > I managed to get the real time task into kgdb and I could analyze its
> > state as well as the state of "sem". The real time task was _not_ the
> > first waiter. The kworker was the first waiter. The
> > "waiter.handoff_set" was set to "true" for the real time task. The
> > rwsem owner was OWNER_NULL.
> >
> > Looking through the code and watching what was happening.
> >
> > 1. The function rwsem_try_write_lock() was instantly returning false
> > since `handoff` is set and we're not first.
> > 2. After we get back into rwsem_down_write_slowpath() we'll see the
> > handoff set and we'll try to spin on the owner. There is no owner, so
> > this is a noop.
> > 3. Since there's no owner, we'll go right back to the start of the loop.
> >
> > So basically the real time thread (the threaded IRQ handler) was
> > locked to CPU0 and spinning as fast as possible. The "first waiter"
> > for the semaphore was blocked from running because it could only run
> > on CPU0 but was _not_ real time priority.
> >
> > -
> >
> > So all the analysis above was done on the Chrome OS 5.15 kernel
> > branch, which has ${SUBJECT} patch from the stable tree. The code
> > looks reasonably the same on mainline.
> >
> > ...and also, I coded up a test case that can reproduce this on
> > mainline. It's ugly/hacky but it gets the job done. This reproduces
> > the problem at the top of mainline as of commit 80e19f34c288 ("Merge
> > tag 'hte/for-5.19' of
> > git://git.kernel.org/pub/scm/linux/kernel/git/tegra/linux").
> >
> > For me, I was only able to reproduce this without "lockdep" enabled.
> > My lockdep configs were:
> >
> > CONFIG_DEBUG_RT_MUTEXES=y
> > CONFIG_DEBUG_SPINLOCK=y
> > CONFIG_DEBUG_MUTEXES=y
> > CONFIG_PROVE_RCU=y
> > CONFIG_PROVE_LOCKING=y
> > CONFIG_DEBUG_ATOMIC_SLEEP=y
> >
> > I don't know for sure if lockdep is actually required to reproduce.
> >
> > -
> >
> > OK, so here's my hacky test case. In my case, I put a call to this
> > test function in a convenient debugfs "show" function to make it easy
> > to trigger. You can put it wherever.
> >
> > struct test_data {
> > struct rw_semaphore *rwsem;
> > int i;
> > bool should_sleep;
> > };
> >
> > static int test_thread_fn(void *data)
> > {
> > struct test_data *test_data = data;
> > struct rw_semaphore *rwsem = test_data->rwsem;
> > ktime_t start;
> >
> > trace_printk("Starting\n");
> > start = ktime_get();
> > while (ktime_to_ms(ktime_sub(ktime_get(), start)) < 60000) {
> > trace_printk("About to grab\n");
> > down_write(rwsem);
> > trace_printk("Grabbed write %d\n", test_data->i);
> > schedule();
> > up_write(rwsem);
> > trace_printk("Released write %d\n", test_data->i);
> > if (test_data->should_sleep)
> > msleep(1);
> > }
> > trace_printk("Done\n");
> >
> > return 0;
> > }
> >
> > static void test(void)
> > {
> > static struct task_struct *t[10];
> > static struct test_data test_data[10];
> > static DECLARE_RWSEM(rwsem);
> > int i;
> >
> > trace_printk("About to create threads\n");
> >
> > for (i = 0; i < ARRAY_SIZE(t); i++) {
> > test_data[i].rwsem = &rwsem;
> > test_data[i].i = i;
> >
> > if (i == ARRAY_SIZE(t) - 1) {
> > /*
> > * Last thread will be bound to CPU0 and realtime.
> > * Have it sleep to give other threads a chance to
> > * run and contend.
> > */
> > test_data[i].should_sleep = true;
> > t[i] = kthread_create_on_cpu(test_thread_fn,
> > &test_data[i], 0,
> > "test0 FIFO-%u");
> > sched_set_fifo(t[i]);
> > } else if (i == ARRAY_SIZE(t) - 2) {
> > /* 2nd to last thread will be bound to CPU0 */
> > t[i] = kthread_create_on_cpu(test_thread_fn,
> > &test_data[i], 0,
> > "test0-%u");
> > } else {
> > /* All other threads are just normal */
> > t[i] = kthread_create(test_thread_fn,
> > &test_data[i], "test");
> > }
> > wake_up_process(t[i]);
> > msleep(10);
> > }
> > }
> >
> > -
> >
> > With the reproducer above, I was able to:
> >
> > 1. Validate that on chromeos-5.15 I could revert ${SUBJECT} patch and
> > the problem went away.
> >
> > 2. I could go to mainline at exactly the commit hash of ${SUBJECT}
> > patch, see the problem, then revert ${SUBJECT} patch and see the
> > problem go away.
> >
> > Thus I'm fairly confident that the problem is related to ${SUBJECT} patch.
> >
> > -
> >
> > I'm hoping that someone on this thread can propose a fix. I'm happy to
> > test, but I was hoping not to have to become an expert on the rwsem
> > implementation to try to figure out the proper fix.
> >
>
> See if it makes sense to only allow the first waiter to spin on owner.
>
> Hillf
>
> --- mainline/kernel/locking/rwsem.c
> +++ b/kernel/locking/rwsem.c
> @@ -337,7 +337,7 @@ struct rwsem_waiter {
> unsigned long timeout;
>
> /* Writer only, not initialized in reader */
> - bool handoff_set;
> + bool handoff_set, first;
> };
> #define rwsem_first_waiter(sem) \
> list_first_entry(&sem->wait_list, struct rwsem_waiter, list)
> @@ -604,6 +604,7 @@ static inline bool rwsem_try_write_lock(
>
> lockdep_assert_held(&sem->wait_lock);
>
> + waiter->first = first;
> count = atomic_long_read(&sem->count);
> do {
> bool has_handoff = !!(count & RWSEM_FLAG_HANDOFF);
> @@ -1114,6 +1115,7 @@ rwsem_down_write_slowpath(struct rw_sema
> waiter.type = RWSEM_WAITING_FOR_WRITE;
> waiter.timeout = jiffies + RWSEM_WAIT_TIMEOUT;
> waiter.handoff_set = false;
> + waiter.first = false;
>
> raw_spin_lock_irq(&sem->wait_lock);
> rwsem_add_waiter(sem, &waiter);
> @@ -1158,7 +1160,7 @@ rwsem_down_write_slowpath(struct rw_sema
> * In this case, we attempt to acquire the lock again
> * without sleeping.
> */
> - if (waiter.handoff_set) {
> + if (waiter.handoff_set && waiter.first) {
Your patch does fix my test case, so FWIW:
Tested-by: Douglas Anderson <dianders@xxxxxxxxxxxx>
I haven't done any stress testing other than my test case, though, so
I can't speak to whether there might be any other unintended issues.
-Doug
