Message-ID: <dtde47mfm3amxg4mbrnbct53ehpfbekdvrjhhd6j5tzl7lulwj@zwdsvkq3orag>
Date: Tue, 18 Jun 2024 17:52:19 -0500
From: Andrew Halaney <ahalaney@...hat.com>
To: John Ogness <john.ogness@...utronix.de>
Cc: Derek Barbosa <debarbos@...hat.com>, pmladek@...e.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, 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);
	} 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
    [   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,
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
    [  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
    [  495.910875]  ? __pfx_wq_barrier_func+0x10/0x10
    [  495.910878]  __lru_add_drain_all+0x19d/0x1e0
    [  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,
Andrew

Powered by blists - more mailing lists