[BUG] sleeping function called from invalid context at ./include/linux/sched/mm.h:321

[BUG] sleeping function called from invalid context at ./include/linux/sched/mm.h:321

[Paul E. McKenney]

Hello!

The next-20250512 release got the following while running either of the
rcutorture TINY02 and SRCU-T scenarios with strict KCSAN enabled:

BUG: sleeping function called from invalid context at ./include/linux/sched/mm.h:321

This is the last line of this function:

	static inline void might_alloc(gfp_t gfp_mask)
	{
		fs_reclaim_acquire(gfp_mask);
		fs_reclaim_release(gfp_mask);

		might_sleep_if(gfpflags_allow_blocking(gfp_mask));
	}

The reproducer is as follows:

tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus --duration 1m --configs TINY02 --kcsan --kmake-arg CC=clang

I ran this on x86 with clang version 19.1.7 (CentOS 19.1.7-1.el9).

See below for the full splat.  The TINY02 and SRCU-T scenarios are unique
in setting both CONFIG_SMP=n and CONFIG_PROVE_LOCKING=y.

Bisection converges here:

c836e5a70c59 ("genirq/chip: Rework irq_set_msi_desc_off()")

The commit reverts cleanly, but results in the following build error:

kernel/irq/chip.c:98:26: error: call to undeclared function 'irq_get_desc_lock'

Thoughts?

						Thanx, Paul

------------------------------------------------------------------------

[    8.862165] BUG: sleeping function called from invalid context at ./include/linux/sched/mm.h:321 
[    8.862706] in_atomic(): 0, irqs_disabled(): 1, non_block: 0, pid: 1, name: swapper
[    8.862706] preempt_count: 0, expected: 0
[    8.862706] 1 lock held by swapper/1:
[    8.862706]  #0: ffff99018127a1a0 (&dev->mutex){....}-{4:4}, at: __driver_attach+0x189/0x2f0 
[    8.862706] irq event stamp: 83979
[    8.862706] hardirqs last  enabled at (83978): [<ffffffff8b01a83d>] _raw_spin_unlock_irqrestore+0x3d/0x60
[    8.862706] hardirqs last disabled at (83979): [<ffffffff8b01a616>] _raw_spin_lock_irqsave+0x56/0xb0
[    8.862706] softirqs last  enabled at (83749): [<ffffffff896e22d8>] __irq_exit_rcu+0x58/0xc0
[    8.862706] softirqs last disabled at (83740): [<ffffffff896e22d8>] __irq_exit_rcu+0x58/0xc0
[    8.862706] CPU: 0 UID: 0 PID: 1 Comm: swapper Not tainted 6.15.0-rc5-next-20250508-00001-g3d99c237b0d4-dirty #4043 NONE
[    8.862706] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
[    8.862706] Call Trace:
[    8.862706]  <TASK>
[    8.862706]  dump_stack_lvl+0x77/0xb0
[    8.862706]  dump_stack+0x19/0x24
[    8.862706]  __might_resched+0x282/0x2a0
[    8.862706]  __kmalloc_node_track_caller_noprof+0xa1/0x2a0
[    8.862706]  ? _pcim_request_region+0x55/0x190
[    8.862706]  ? __pfx_pcim_addr_resource_release+0x10/0x10
[    8.862706]  __devres_alloc_node+0x4b/0xc0
[    8.862706]  _pcim_request_region+0x55/0x190
[    8.862706]  pcim_request_all_regions+0x37/0x260
[    8.862706]  ahci_init_one+0x2f0/0x1750
[    8.862706]  ? rpm_resume+0x48d/0xc30
[    8.862706]  ? __pm_runtime_resume+0xa7/0xc0
[    8.862706]  pci_device_probe+0xfc/0x1b0
[    8.862706]  really_probe+0x1ba/0x500
[    8.862706]  __driver_probe_device+0x137/0x1a0
[    8.862706]  driver_probe_device+0x67/0x2d0
[    8.862706]  __driver_attach+0x194/0x2f0
[    8.862706]  ? __pfx___driver_attach+0x10/0x10
[    8.862706]  bus_for_each_dev+0x17a/0x1d0
[    8.862706]  driver_attach+0x30/0x40
[    8.862706]  bus_add_driver+0x22a/0x380
[    8.862706]  driver_register+0xcf/0x1c0
[    8.862706]  __pci_register_driver+0xfc/0x120
[    8.862706]  ? __pfx_ahci_pci_driver_init+0x10/0x10
[    8.862706]  ahci_pci_driver_init+0x24/0x40
[    8.862706]  ? __pfx_ahci_pci_driver_init+0x10/0x10
[    8.862706]  do_one_initcall+0xfb/0x300
[    8.862706]  ? prb_first_seq+0x1ba/0x1f0
[    8.862706]  ? _prb_read_valid+0x627/0x660
[    8.862706]  ? prb_read_valid+0x47/0x70
[    8.862706]  ? console_unlock+0x179/0x1a0
[    8.862706]  ? vprintk_emit+0x43d/0x480
[    8.862706]  ? _printk+0x83/0xb0
[    8.862706]  ? parse_args+0x24f/0x5a0
[    8.862706]  do_initcall_level+0x91/0xf0
[    8.862706]  do_initcalls+0x60/0xa0
[    8.862706]  ? __pfx_kernel_init+0x10/0x10
[    8.862706]  do_basic_setup+0x41/0x50
[    8.862706]  kernel_init_freeable+0xb3/0x120
[    8.862706]  kernel_init+0x20/0x200
[    8.862706]  ret_from_fork+0x13e/0x1e0
[    8.862706]  ? __pfx_kernel_init+0x10/0x10
[    8.862706]  ret_from_fork_asm+0x19/0x30
[    8.862706]  </TASK>

Re: [BUG] sleeping function called from invalid context at ./include/linux/sched/mm.h:321

[Thomas Gleixner]

On Mon, May 12 2025 at 16:47, Paul E. McKenney wrote:
> I ran this on x86 with clang version 19.1.7 (CentOS 19.1.7-1.el9).
>
> See below for the full splat.  The TINY02 and SRCU-T scenarios are unique
> in setting both CONFIG_SMP=n and CONFIG_PROVE_LOCKING=y.
>
> Bisection converges here:
>
> c836e5a70c59 ("genirq/chip: Rework irq_set_msi_desc_off()")
>
> The commit reverts cleanly, but results in the following build error:
>
> kernel/irq/chip.c:98:26: error: call to undeclared function 'irq_get_desc_lock'
>
> Thoughts?

Smells like what the top commit of the irq/core branch fixes:

https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git/commit/?h=irq/core

Re: [BUG] sleeping function called from invalid context at ./include/linux/sched/mm.h:321

[Paul E. McKenney]

On Tue, May 13, 2025 at 09:39:45AM +0200, Thomas Gleixner wrote:
> On Mon, May 12 2025 at 16:47, Paul E. McKenney wrote:
> > I ran this on x86 with clang version 19.1.7 (CentOS 19.1.7-1.el9).
> >
> > See below for the full splat.  The TINY02 and SRCU-T scenarios are unique
> > in setting both CONFIG_SMP=n and CONFIG_PROVE_LOCKING=y.
> >
> > Bisection converges here:
> >
> > c836e5a70c59 ("genirq/chip: Rework irq_set_msi_desc_off()")
> >
> > The commit reverts cleanly, but results in the following build error:
> >
> > kernel/irq/chip.c:98:26: error: call to undeclared function 'irq_get_desc_lock'
> >
> > Thoughts?
> 
> Smells like what the top commit of the irq/core branch fixes:
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git/commit/?h=irq/core

OK, that is this one:

47af06c9d31f ("genirq: Consistently use '%u' format specifier for unsigned int variables")

This is printk() format change, which seems unlikely, but what do I
know?  Can't hurt to run a two-minute test...  Which fails.

Ah, you sent this email at 9:39AM your time, and that commit was queued
at 9:34AM your time.  The top of the stack at 9:39AM was this one:

b5fcb6898202 ("genirq: Ensure flags in lock guard is consistently initialized")

OK, early enabling of interrupts could be a bad thing, so I guess that I
don't feel so bad about failing to have spotted the problem by inspection.
And the test passes for both rcutorture scenarios, thank you!

I have to ask...  Will you be rebasing the fixes into the offending
commits for bisectability?

							Thanx, Paul