Date: Wed, 19 Jun 2024 11:46:38 +0200
From: Petr Mladek <pmladek@...e.com>
To: Andrew Halaney <ahalaney@...hat.com>
Cc: John Ogness <john.ogness@...utronix.de>,
	Derek Barbosa <debarbos@...hat.com>, rostedt@...dmis.org,
	senozhatsky@...omium.org, linux-rt-users@...r.kernel.org,
	linux-kernel@...r.kernel.org, williams@...hat.com,
	jlelli@...hat.com, lgoncalv@...hat.com, jwyatt@...hat.com,
	aubaker@...hat.com
Subject: Re: [BUG] printk/nbcon.c: watchdog BUG: softlockup - CPU#x stuck for
 78s

On Tue 2024-06-18 17:52:19, Andrew Halaney wrote:
> On Tue, Jun 18, 2024 at 09:03:00PM GMT, John Ogness wrote:
> > Hi Derek,
> > 
> > On 2024-06-18, Derek Barbosa <debarbos@...hat.com> wrote:
> > > The realtime team at Red Hat has recently backported the latest printk
> > > changes present in 6.6-rt stable (HEAD at 20fd4439f644 printk: nbcon:
> > > move locked_port flag to struct uart_port) to CentOS Stream 9 for
> > > performance improvements and printk-related bugfixes.
> > >
> > > Since merging this said code, we've hit an interesting bug during
> > > testing, specifically, on larger systems, a softlockup may be reported
> > > by the watchdog when there is a heavy amount of printing to tty
> > > devices (whether it be through printk, /dev/kmsg, etc).
> > >
> > > We have a modicum of reasonable suspicion to believe that
> > > nbcon_reacquire, or some other nbcon mechanism *may* be causing such
> > > behavior.
> > >
> > > Since we've succesfully reproduced this in the Kernel-ARK/Fedora-ELN
> > > (osbuild-rt), and linux-rt-devel 6.10.rc4-rt6, we are reporting this
> > > bug upstream.
> > >
> > > Anyway, here is a more in-depth description, along with some call traces.
> > >
> > > Description:
> > >
> > > On x86 systems with a large amount of logical cores (nproc ~> 60), a
> > > softlockup can be observed with accompanying call trace when a large
> > > amount of "printing" activity is taking place.
> > >
> > > As shown in the call traces appended below, during some kind of numa
> > > balancing/numa_migration after a task_numa_fault --where a set of
> > > processess are being migrated/swapped between two CPUs-- there is a
> > > busy thread that is being waited on (in the order of seconds), causing
> > > a livelock. Additional investigation of collected vmcores by toggling
> > > panic on softlockup shows that the waiting thread may be waiting for a
> > > thread looping with nbcon_reacquire.
> > >
> > > I suspect that some logic within nbcon_context_try_acquire may be a
> > > good place to start. My understanding of the code becomes a bit fuzzy
> > > here, so apologies in advance for any erroneous statements. As I see
> > > it, there may be something happening during migration (or under heavy
> > > load) in which nbcon_reacquire() is in a non-migratable or
> > > non-preemtible state as it is attempting to regain access to a
> > > lost/taken console. It could very well be a situation in which context
> > > was forcefully taken from the printing thread.
> > >
> > > Alternatively, Andrew Halaney <ahalaney@...hat.com> suspects that it
> > > is the loop within nbcon_kthread_func() -- since there is nothing that
> > > would yield the task in said loop (cant_migrate()), the migrate code
> > > would be essentially waiting forever for the aforementioned loop to
> > > "finish". I believe in PREEMPT_RT, there would be a preemption point
> > > here. Furthermore, in his investigation, there were signs that the
> > > loop was just iterating up until the crash, leaving reason to believe
> > > that task would be the culprit.
> > >
> > > In fact, with the following diff, we noticed this output:
> > >
> > > ```
> > > ahalaney@...en2nano ~/git/linux-rt-devel (git)-[tags/v6.10-rc4-rt6-rebase] % git diff | cat
> > > diff --git a/kernel/printk/nbcon.c b/kernel/printk/nbcon.c
> > > index bb9689f94d30..d716b72bf2f8 100644
> > > --- a/kernel/printk/nbcon.c
> > > +++ b/kernel/printk/nbcon.c
> > > @@ -1075,6 +1075,7 @@ static int nbcon_kthread_func(void *__console)
> > >       *
> > >       * This pairs with rcuwait_has_sleeper:A and nbcon_kthread_wake:A.
> > >       */
> > > +    trace_printk("Before rcuwait_wait_event()\n");
> > >      ret = rcuwait_wait_event(&con->rcuwait,
> > >                   nbcon_kthread_should_wakeup(con, ctxt),
> > >                   TASK_INTERRUPTIBLE); /* LMM(nbcon_kthread_func:A) */
> > > @@ -1086,7 +1087,10 @@ static int nbcon_kthread_func(void *__console)
> > >      if (ret)
> > >          goto wait_for_event;
> > >
> > > +    trace_printk("Starting do while(backlog) loop \n");
> > > +    unsigned long int loop = 0;
> > >      do {
> > > +        trace_printk("On loop %lu\n", ++loop);
> > >          backlog = false;
> > >
> > >          cookie = console_srcu_read_lock();
> > > @@ -1121,6 +1125,7 @@ static int nbcon_kthread_func(void *__console)
> > >          console_srcu_read_unlock(cookie);
> > >
> > >      } while (backlog);
> > > +    trace_printk("End of while(backlog) loop, looped %lu times \n", loop);
> > >
> > >      goto wait_for_event;
> > > ```
> > >
> > > The output:
> > >
> > > ```
> > > [ 1681.309720] pr/ttyS0-18       21.N... 893365994us : nbcon_kthread_func: On loop 2117
> > > [ 1681.309727] pr/ttyS0-18       21.N... 893374418us : nbcon_kthread_func: On loop 2118
> > > [ 1681.309734] pr/ttyS0-18       21.N... 893382860us : nbcon_kthread_func: On loop 2119
> > > (...)
> > > [ 1681.396193] pr/ttyS0-18       21.N... 954571399us : nbcon_kthread_func: On loop 14025
> > > [ 1681.396200] pr/ttyS0-18       21.N... 954576525us : nbcon_kthread_func: On loop 14026
> > > [ 1681.396207] pr/ttyS0-18       21.N... 954581561us : nbcon_kthread_func: On loop 14027
> > > [ 1681.396213] pr/ttyS0-18       21.N... 954584954us : nbcon_kthread_func: On loop 14028
> > > [ 1681.396220] pr/ttyS0-18       21.N... 954590111us : nbcon_kthread_func: On loop 14029
> > > [ 1681.396223] ---------------------------------
> > > [ 1681.396230] Kernel panic - not syncing: softlockup: hung tasks
> > > (...)
> > > ```
> > >
> > > Demonstrating evidence that the nbcon kthread function is invoked
> > > continuously up until the point of panic. I do believe that this
> > > approach is more sound than my initial hints (or it could be more than
> > > a handful of threads). Some traces around
> > > serial8250_console_write_thread() also denote continuous calls without
> > > any holdups.
> > >
> > > As a sidenote, we are seeing the softlockup with !CONFIG_PREEMPT_RT
> > 
> > This trace shows that the thread is successfully printing
> > lines. So I doubt nbcon_reacquire() is involved here.
> > 
> > Assuming the ringbuffer is getting filled as fast or faster than the
> > thread can print, then we effectively have this:
> > 
> > DEFINE_STATIC_SRCU(test_srcu);
> > static DEFINE_SPINLOCK(test_lock);
> > 
> > static int kthread_func(void *arg)
> > {
> > 	unsigned long flags;
> > 
> > 	do {
> > 		srcu_read_lock_nmisafe(&test_srcu);
> > 		spin_lock_irqsave(&test_lock, flags);
> > 		udelay(5000);  // print a line to serial
> > 		spin_unlock_irqrestore(&test_lock, flags);
> > 		srcu_read_unlock_nmisafe(&test_srcu);
> > 	} while (true);
> > 
> > 	return 0;
> > }
> > 
> > And since the thread has a nice value of -20, it will get a lot of CPU
> > time allocated to it. Is that a problem? Shouldn't the scheduler
> > eventually kick the task off the CPU after its timeslice is up?
> 
> I trust you better than myself about this, but this is being reproduced
> with a CONFIG_PREEMPT_DYNAMIC=y + CONFIG_PREEMPT_VOLUNTARY=y setup (so
> essentially the current mode is VOLUNTARY). Does that actually work that
> way for a kthread in that mode? I've been trying to reason with myself
> on when the scheduler actually will get involved and stop the above
> kthread_func() to run something else.
> 
> > 
> > > Some questions arise from this, as we've never encountered this in our
> > > testing with John Ogness' console_blast (kudos to <jwyatt@...hat.com>)
> > > and other printk torture tests that have been compiled
> > > [here](https://gitlab.com/debarbos/printktorture).
> > 
> > Yes, that is odd since those tests will ensure that the printing thread
> > never exits its printing loop because it will never catch up. So it
> > should be the same situation.
> > 
> > > We are curious to understand why is it that the printing thread is
> > > chosen by the NUMA balancer for migration/swap, and how that
> > > interaction is handled within the code (in other words, how else would
> > > nbcon handle a migrated printing thread?).
> > 
> > The nbcon console can only be owned when migration is disabled. In the
> > case of the printing thread for serial, this is under the
> > spin_lock_irqsave(). The NUMA balancer would only be able to migrate the
> > thread outside of the spin_lock critical section. And outside of the
> > spin_lock critical section, the thread does not own/hold any resources
> > at all. So it should be no problem to migrate it.
> > 
> > > Our next round of tests aim to disable numa balancing on
> > > large-multi-core-systems to determine whether it is the NUMA
> > > mechanisms + nbcon interactions are at fault here.
> > 
> > I am curious if starting a kthread using the code I wrote above (with
> > nice=-20) would cause similar issues.
> >
> 
> Just in case I did something dumb, here's the module I wrote up:
> 
> ahalaney@...en2nano ~/git/linux-rt-devel (git)-[tags/v6.10-rc4-rt6-rebase] % cat kernel/printk/test_thread.c                         :(
> /*
>  * Test making a kthread similar to nbcon's (under load)
>  * to see if it also has issues with migrate_swap()
>  */
> #include "linux/nmi.h"
> #include <asm-generic/delay.h>
> #include <linux/kthread.h>
> #include <linux/module.h>
> #include <linux/sched.h>
> 
> DEFINE_STATIC_SRCU(test_srcu);
> static DEFINE_SPINLOCK(test_lock);
> static struct task_struct *kt;
> static bool dont_stop = true;
> 
> static int test_thread_func(void *unused) {
> 	unsigned long flags;
> 
> 	pr_info("Starting the while true loop\n");
> 	do {
> 		int cookie = srcu_read_lock_nmisafe(&test_srcu);
> 		spin_lock_irqsave(&test_lock, flags);
> 		touch_nmi_watchdog();
> 		udelay(5000);  // print a line to serial
> 		spin_unlock_irqrestore(&test_lock, flags);
> 		srcu_read_unlock_nmisafe(&test_srcu, cookie);

Does it help to add here?

		cond_resched();

> 	} while (dont_stop);
> 
> 	return 0;
> }
> 
> static int __init test_thread_init(void) {
> 
> 	pr_info("Creating test_thread at -20 nice level\n");
> 	kt = kthread_run(test_thread_func, NULL, "test_thread");
> 	if (IS_ERR(kt)) {
> 		pr_err("Failed to make test_thread\n");
> 		return PTR_ERR(kt);
> 	}
> 	sched_set_normal(kt, -20);
> 
> 	return 0;
> }
> 
> static void __exit test_thread_exit(void) {
> 	dont_stop = false;
> 	kthread_stop(kt);
> }
> 
> module_init(test_thread_init);
> module_exit(test_thread_exit);
> MODULE_LICENSE("GPL");
> ahalaney@...en2nano ~/git/linux-rt-devel (git)-[tags/v6.10-rc4-rt6-rebase] %
> 
> That shows a softlockup quite quickly on the CPU that thread is
> running on (as opposed to what Derek reports, where migrate_swap() is
> going on and the softlockup reports on the other CPU in the swapping of
> tasks). I guess that's because of the touch_nmi_watchdog() happening
> in serial8250_console_write_thread().
> 
> The below is without the touch_nmi_watchdog() in the above snippet
> (just to show what happens as written in your reply).
> 
>     [   72.018480] Creating test_thread at -20 nice level
>     [   72.018632] Starting the while true loop
>     [   99.673116] watchdog: BUG: soft lockup - CPU#53 stuck for 26s! [test_thread:2628]
>     [   99.673119] Modules linked in: test_thread rfkill intel_rapl_msr intel_rapl_common sb_edac x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel mei_me ipmi_si kvm mei acpi_power_meter i2c_i801 mgag200 iTCO_wdt rapl acpi_ipmi i2c_algo_bit iTCO_vendor_support mxm_wmi pcspkr i2c_smbus joydev lpc_ich ioatdma intel_cstate intel_uncore ipmi_devintf ipmi_msghandler acpi_pad fuse xfs sd_mod t10_pi sg ahci crct10dif_pclmul libahci crc32_pclmul ixgbe crc32c_intel libata megaraid_sas ghash_clmulni_intel mdio dca wmi dm_mirror dm_region_hash dm_log dm_mod
>     [   99.673159] CPU: 53 PID: 2628 Comm: test_thread Kdump: loaded Not tainted 6.10.0-rc4-rt6+ #7
>     [   99.673162] Hardware name: Intel Corporation S2600CWR/S2600CWR, BIOS SE5C610.86B.01.01.0018.072020161249 07/20/2016
>     [   99.673163] RIP: 0010:_raw_spin_unlock_irqrestore+0x1f/0x40

This is the point where the interrupts were enabled. It allowed to
handle pending timers, including watchdog_timer_fn().
It printed this softlockup report.

It means that test_thread() never scheduled in the do while() loop.

I believe that the cond_resched() would cure the problem.


>     [   99.673179] Code: 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 0f 1f 44 00 00 c6 07 00 0f 1f 00 f7 c6 00 02 00 00 74 01 fb 65 ff 0d 09 17 9c 4a <74> 06 c3 cc cc cc cc cc 0f 1f 44 00 00 c3 cc cc cc cc cc 66 66 66
>     [   99.673180] RSP: 0018:ffffb10887dafed0 EFLAGS: 00000246
>     [   99.673182] RAX: 00000000e3ddc104 RBX: 0000000000000000 RCX: 0000000000001035
>     [   99.673183] RDX: 0000000000af11a8 RSI: 0000000000000286 RDI: ffffffffc0e1b700
>     [   99.673184] RBP: ffffb1088a4c77b0 R08: 0000000000000035 R09: 0000000000000035
>     [   99.673185] R10: 0000000000017ffd R11: ffffffffb5649760 R12: ffff8b5f0caa4f00
>     [   99.673186] R13: ffff8b4f87c04e80 R14: 0000000000000286 R15: ffff8b5f200e3380
>     [   99.673187] FS:  0000000000000000(0000) GS:ffff8b6ebf880000(0000) knlGS:0000000000000000
>     [   99.673189] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>     [   99.673190] CR2: 000055a7bd4f3b68 CR3: 0000001f35820003 CR4: 00000000001706f0
>     [   99.673191] Call Trace:
>     [   99.673192]  <IRQ>
>     [   99.673193]  ? watchdog_timer_fn+0x21f/0x2a0
>     [   99.673197]  ? __pfx_watchdog_timer_fn+0x10/0x10
>     [   99.673198]  ? __hrtimer_run_queues+0xfa/0x270
>     [   99.673202]  ? hrtimer_interrupt+0xf4/0x390
>     [   99.673205]  ? __sysvec_apic_timer_interrupt+0x52/0x160
>     [   99.673208]  ? sysvec_apic_timer_interrupt+0x6f/0x80
>     [   99.673210]  </IRQ>
>     [   99.673211]  <TASK>
>     [   99.673212]  ? asm_sysvec_apic_timer_interrupt+0x1a/0x20
>     [   99.673215]  ? __pfx_delay_tsc+0x10/0x10
>     [   99.673221]  ? _raw_spin_unlock_irqrestore+0x1f/0x40
>     [   99.673222]  test_thread_func+0x5e/0xff0 [test_thread]
>     [   99.673225]  ? __pfx_test_thread_func+0x10/0x10 [test_thread]
>     [   99.673226]  kthread+0xec/0x110
>     [   99.673230]  ? __pfx_kthread+0x10/0x10
>     [   99.673232]  ret_from_fork+0x3a/0x50
>     [   99.673235]  ? __pfx_kthread+0x10/0x10
>     [   99.673237]  ret_from_fork_asm+0x1a/0x30
>     [   99.673239]  </TASK>
> 
> 
> If you mimic that touch_nmi_watchdog() above the udelay() in the function above,

The touch_nmi_watchdog() caused that watchdog_timer_fn() did not see
that "test_thread" kthread did not schedule. By other words, it did
hide the problem.


> then you have to get the system to decide to migrate. Something like:
> 
>     stress-ng --timeout 60000s --numa 64
> 
> seems to help tickle problems out. With that I got a bit different of a
> backtrace than what Derek reported or above, but I'd guess its a similar
> root cause:
> 
>     [  258.175904] Creating test_thread at -20 nice level
>     [  258.176237] Starting the while true loop
>     [  495.910816] INFO: task khugepaged:483 blocked for more than 122 seconds.
>     [  495.910824]       Not tainted 6.10.0-rc4-rt6+ #7

This is from check_hung_task(). It means that the task
TASK_UNINTERRUPTIBLE sleep for more than 122 second.


>     [  495.910827] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>     [  495.910829] task:khugepaged      state:D stack:0     pid:483   tgid:483   ppid:2      flags:0x00004000
>     [  495.910834] Call Trace:
>     [  495.910836]  <TASK>
>     [  495.910838]  __schedule+0x5e9/0x1420
>     [  495.910845]  ? update_load_avg+0x1fb/0x860
>     [  495.910851]  ? __update_curr+0x15d/0x3a0
>     [  495.910854]  schedule+0x6d/0xf0
>     [  495.910857]  schedule_timeout+0x32/0x1b0
>     [  495.910860]  ? sched_clock+0x10/0x30
>     [  495.910866]  wait_for_common+0xfe/0x1c0
>     [  495.910869]  __flush_work+0x258/0x2d0

I guess that it is the wait_for_completion() called from __flush_work().

>     [  495.910875]  ? __pfx_wq_barrier_func+0x10/0x10
>     [  495.910878]  __lru_add_drain_all+0x19d/0x1e0

__lru_add_drain_all() does

	for_each_cpu(cpu, &has_work)
		flush_work(&per_cpu(lru_add_drain_work, cpu));

It is most likely blocked when waiting on the CPU which is occupied
by the "test_thread" kthread.

IMHO, it is not related to a process migration. It is just yet another
way how to get blocked by a task which is not scheduling.

>     [  495.910882]  khugepaged+0x160/0xa90
>     [  495.910887]  ? __pfx_autoremove_wake_function+0x10/0x10
>     [  495.910892]  ? __pfx_khugepaged+0x10/0x10
>     [  495.910894]  kthread+0xec/0x110
>     [  495.910898]  ? __pfx_kthread+0x10/0x10
>     [  495.910900]  ret_from_fork+0x3a/0x50
>     [  495.910902]  ? __pfx_kthread+0x10/0x10
>     [  495.910904]  ret_from_fork_asm+0x1a/0x30
>     [  495.910907]  </TASK>
> 
> I got that once this afternoon, haven't gotten anything since (was
> hoping to see the exact same thing as Derek with that, but oh well).

Thanks a lot for proving these detailed debugging information.

I think that we need to add the cond_resched() into the do-while()
loop in nbcon_kthread_func(). Otherwise, the kthread would not
schedule in this loop with a voluntary preemption.

And it is a great catch! I haven't realized this when reviewing
the code.

Best Regards,
Petr

Powered by blists - more mailing lists