schedule under irqs_disabled in SLUB problem

will do my best.

that is basically what happens if the counter goes negative.

…

ideally the interrupts would be always enabled because they have to on -RT but we can't do so early in the boot process.

…

In newer -RT we have
if (system_state > SYSTEM_BOOTING)
instead but this won't work even in v4.9 because it does not have SYSTEM_SCHEDULING yet. So v4.11/v4.13 should not be affected.

If that is true, then something like

index 6470deef01c9..362761effeac 100644
@@ -379,6 +379,7 @@ static void __init setup_command_line(char *command_line)
  */
 
 static __initdata DECLARE_COMPLETION(kthreadd_done);
+extern bool slab_do_irq_on;
 
 static noinline void __ref rest_init(void)
 {

@@ -396,6 +397,7 @@ static noinline void __ref rest_init(void)
 	rcu_read_lock();
 	kthreadd_task = find_task_by_pid_ns(pid, &init_pid_ns);
 	rcu_read_unlock();
+	slab_do_irq_on = true;
 	complete(&kthreadd_done);
 
 	/*

index 67eb368b9314..22ec805130e5 100644
@@ -1527,6 +1527,7 @@ static inline bool shuffle_freelist(struct kmem_cache *s, struct page *page)
 	return false;
 }
 #endif /* CONFIG_SLAB_FREELIST_RANDOM */
+bool slab_do_irq_on;
 
 static struct page *allocate_slab(struct kmem_cache *s, gfp_t flags, int node)
 {

@@ -1543,7 +1544,7 @@ static struct page *allocate_slab(struct kmem_cache *s, gfp_t flags, int node)
 	if (gfpflags_allow_blocking(flags))
 		enableirqs = true;
 #ifdef CONFIG_PREEMPT_RT_FULL
-	if (system_state == SYSTEM_RUNNING)
+	if (slab_do_irq_on)
 		enableirqs = true;
 #endif
 	if (enableirqs)

might just work. Can you test this please?

Sebastian

I've used to see the same and created patch for 4.9 (should work for 4.1) which does mostly the same things, but it also enables __might_sleep() during boot. Of course, it's possible that I've selected wrong place to set SYSTEM_BOOTING_LATE and it's more correct to do it in rest_init().

NOTE: As Sebastian mentioned below patch is not relevant for newer Kernel versions.

From: Grygorii Strashko <[email protected]>
Date: Fri, 9 Oct 2015 08:52:16 -0500
Subject: [DEBUG PATCH] core: introduce SYSTEM_BOOTING_LATE state

This patch introduces new SYSTEM_BOOTING_LATE system state which will be set right after scheduler is fully operational during the boot.

And reuse this state in update ___might_sleep() to allow catching "BUG: sleeping function called from invalid context" early during the boot which is very helping for debugging.

---
 include/linux/kernel.h | 1 +
 init/main.c            | 1 +
 kernel/sched/core.c    | 4 +++-
 mm/slub.c              | 3 +--
 4 files changed, 6 insertions(+), 3 deletions(-)

index 7894d55..5dfed24 100644
@@ -488,6 +488,7 @@ extern bool early_boot_irqs_disabled;
 /* Values used for system_state */
 extern enum system_states {
 	SYSTEM_BOOTING,
+	SYSTEM_BOOTING_LATE,
 	SYSTEM_RUNNING,
 	SYSTEM_HALT,
 	SYSTEM_POWER_OFF,

index a4a61e7..e5e5906 100644
@@ -989,6 +989,7 @@ static noinline void __init kernel_init_freeable(void)
 
 	/* Now the scheduler is fully set up and can do blocking allocations */
 	gfp_allowed_mask = __GFP_BITS_MASK;
+	system_state = SYSTEM_BOOTING_LATE;
 
 	/*
 	 * init can allocate pages on any node

index 127aaf4..04c1805 100644
@@ -7977,7 +7977,9 @@ void ___might_sleep(const char *file, int line, int preempt_offset)
 	rcu_sleep_check(); /* WARN_ON_ONCE() by default, no rate limit reqd. */
 	if ((preempt_count_equals(preempt_offset) && !irqs_disabled() &&
 	     !is_idle_task(current)) ||
-		 (system_state != SYSTEM_RUNNING && system_state != SYSTEM_SUSPEND) || oops_in_progress)
+		 (system_state != SYSTEM_RUNNING &&
+		  system_state != SYSTEM_SUSPEND &&
+		  system_state != SYSTEM_BOOTING_LATE) || oops_in_progress)
 		return;
 	if (time_before(jiffies, prev_jiffy + HZ) && prev_jiffy)
 		return;

index 6d72b7f..993c89b 100644
@@ -1540,8 +1540,7 @@ static struct page *allocate_slab(struct kmem_cache *s, gfp_t flags, int node)
 	if (gfpflags_allow_blocking(flags))
 		enableirqs = true;
 #ifdef CONFIG_PREEMPT_RT_FULL
-	if (system_state == SYSTEM_RUNNING)
-		enableirqs = true;
+	enableirqs = system_state == SYSTEM_RUNNING || system_state == SYSTEM_BOOTING_LATE;
 #endif
 	if (enableirqs)
 		local_irq_enable();

2.10.5



-- 
regards,
-grygorii

I'll try Sebastian's patch on the next week. Thanks!

Thanks, it works.

Thanks, it works.

Thanks, it works.

+ Steven & Julia

Okay, good to hear.

Steven + Julia:
We need to decide what are going to do about this stable-wise. The bug was reported against 3.14.79-rt85 and the devel tree is not affected*. The thread starts at
https://www.spinics.net/lists/linux-rt-users/msg17560.html

[*] probably since v4.11.5-rt1 once
"sched/core: Enable might_sleep() and smp_processor_id() checks early" and its prerequisites appeared in the queue.

Sebastian

kernel 4.9 has the same problem.

Your proposed patch seems reasonable to me to pull back into the relevant releases. Can you send a proper patch against the latest affected tree (4.9?) and the stable team will pull it back? It looks like it will need some minor massaging on it's way back, but that shouldn't be a problem.

Thanks,
Julia

Hi,

I am also faces a similar kind of issue on X86 target, while testing 3.10.105-rt119.
The issue is seen during boot-up when USB/SCSI enumeration starts.

Below is the log from my console

scsi 0:0:0:0: Direct-Access Linux scsi_debug 0004 PQ: 0 ANSI: 5

------------[ cut here ]------------
------------[ cut here ]------------
WARNING: at kernel/sched/core.c:3052 migrate_disable+0xee/0x100()
Modules linked in:
CPU: 3 PID: 7 Comm: kworker/u16:0 Not tainted 3.10.107-rt120+ #2
Hardware name: Intel Corporation S1200RP_SE/S1200RP_SE, BIOS
S1200RP.86B.02.02.0005.102320140911 10/23/2014
Workqueue: events_unbound async_run_entry_fn
 0000000000000000 ffff880244927338 ffffffff8168b2f0 0000000000000000
 0000000000000009 ffff880244927370 ffffffff8105ef8c ffff8802448fb540
 0000000000000025 0000000000000004 0000000000000025 ffffffff81d9810c
Call Trace:
 [<ffffffff8168b2f0>] dump_stack+0x4f/0x65
 [<ffffffff8105ef8c>] warn_slowpath_common+0x5c/0xa0
 [<ffffffff8105f085>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109355e>] migrate_disable+0xee/0x100
 [<ffffffff810600af>] call_console_drivers.constprop.14+0x4f/0xd0
 [<ffffffff81061241>] console_unlock+0x2a1/0x470
 [<ffffffff810616e2>] vprintk_emit+0x2d2/0x550
 [<ffffffff8168eb49>] ? _raw_spin_unlock_irqrestore+0x19/0x50
 [<ffffffff810936ce>] ? migrate_enable+0x15e/0x1f0
 [<ffffffff816892d3>] printk+0x4a/0x52
 [<ffffffff810936ce>] ? migrate_enable+0x15e/0x1f0
 [<ffffffff8105ef5a>] warn_slowpath_common+0x2a/0xa0
 [<ffffffff8105f085>] warn_slowpath_null+0x15/0x20
 [<ffffffff810936ce>] migrate_enable+0x15e/0x1f0
 [<ffffffff810fce40>] get_page_from_freelist+0x630/0xb90
 [<ffffffff8168e32a>] ? rt_spin_lock_slowlock+0x2ca/0x310
 [<ffffffff810fe36d>] __alloc_pages_nodemask+0x13d/0x9e0
 [<ffffffff810fce72>] ? get_page_from_freelist+0x662/0xb90
 [<ffffffff81133dd0>] alloc_pages_current+0xb0/0x150
 [<ffffffff81138e05>] new_slab+0x2b5/0x380
 [<ffffffff8113b67a>] __slab_alloc.isra.18+0x58a/0x670
 [<ffffffff813d3f40>] ? scsi_pool_alloc_command+0x20/0x70
 [<ffffffff81133dd0>] ? alloc_pages_current+0xb0/0x150
 [<ffffffff8113b956>] kmem_cache_alloc+0xd6/0x100
 [<ffffffff813d3f40>] ? scsi_pool_alloc_command+0x20/0x70
 [<ffffffff813d3f40>] scsi_pool_alloc_command+0x20/0x70
 [<ffffffff813d492e>] scsi_host_alloc_command.isra.1+0x1e/0x80
 [<ffffffff813d49b0>] __scsi_get_command+0x20/0xc0
 [<ffffffff813d4a83>] scsi_get_command+0x33/0xc0
 [<ffffffff813dad1a>] scsi_get_cmd_from_req+0x4a/0x60
 [<ffffffff813db6cb>] scsi_setup_blk_pc_cmnd+0x2b/0xf0
 [<ffffffff813db8fc>] scsi_prep_fn+0x3c/0x50
 [<ffffffff812c9ef3>] blk_peek_request+0xf3/0x1c0
 [<ffffffff813db960>] scsi_request_fn+0x50/0x570
 [<ffffffff812c6c6e>] __blk_run_queue+0x2e/0x40
 [<ffffffff812cdde0>] blk_execute_rq_nowait+0x70/0x100
 [<ffffffff812cdef8>] blk_execute_rq+0x88/0xe0

sd 0:0:0:0: Attached scsi generic sg0 type 0
[<ffffffff812ca040>] ? blk_rq_bio_prep+0x60/0xc0 [<ffffffff812cdcf0>] ? blk_rq_map_kern+0xf0/0x170 [<ffffffff812c86c0>] ? blk_get_request+0x60/0xe0

 [<ffffffff813da050>] scsi_execute+0xf0/0x150
 [<ffffffff813da182>] scsi_execute_req_flags+0x82/0xf0
 [<ffffffff8145d87f>] read_capacity_16+0xcf/0x520
 [<ffffffff8145e060>] sd_revalidate_disk+0x350/0x1bd0
 [<ffffffff8145f9a4>] sd_probe_async+0xc4/0x1d0
 [<ffffffff8108e7c2>] async_run_entry_fn+0x32/0x130
 [<ffffffff8107f5a5>] process_one_work+0x145/0x420
 [<ffffffff81080903>] worker_thread+0x163/0x470
 [<ffffffff8168d91c>] ? preempt_schedule+0x4c/0x70
 [<ffffffff810807a0>] ? manage_workers.isra.7+0x2d0/0x2d0
 [<ffffffff8108735f>] kthread+0xbf/0xd0
 [<ffffffff810872a0>] ? kthread_worker_fn+0x1a0/0x1a0
 [<ffffffff8168f6be>] ret_from_fork+0x4e/0x80
 [<ffffffff810872a0>] ? kthread_worker_fn+0x1a0/0x1a0
---[ end trace 0000000000000001 ]---
------------[ cut here ]------------
WARNING: at kernel/sched/core.c:3087 migrate_enable+0x15e/0x1f0()
Modules linked in:
CPU: 3 PID: 7 Comm: kworker/u16:0 Tainted: G        W    3.10.1

Test case to reproduce:
1. Enable PXE boot and mount file-system on USB stick
2. Continuously reboot the system with USB stick connected
3. We generally see the issue after every 3 to 5 hours.

On looking at the issue it is identified that there is some piece of code someplace that
calls migrate_disable() with interrupts off, enables interrupts, then calls migrate_enable().

On instrumentation it is observed that for some SCSI layer calls(calls from get_requests) the above condition is not evaluated to true hence reaches at buffered_rmqueue with irqs in disabled state.

buffered_rmqueue-> local_spin_lock_irqsave -> local_lock_irqsave -> spin_lock ->rt_spin_lock -> rt_spin_lock_fastlock -> rt_spin_lock_slowlock

In a normal case, when it enters rt_spin_lock_slowlock with irqs_disabled, the same is returned in below case,

        if (__try_to_take_rt_mutex(lock, self, NULL, STEAL_LATERAL)) {
                raw_spin_unlock(&lock->wait_lock);
                return;
        }

But in the some case above condition is meet true and the control reaches below in same function,

        pi_lock(&self->pi_lock);
        self->saved_state = self->state;
        __set_current_state(TASK_UNINTERRUPTIBLE);
        pi_unlock(&self->pi_lock);

pi_lock & pi_unlock disables and enables the irqs respectively, so in this special case the irq state is not retained while exiting rt_spin_lock_slowlock function and this results in the crash!

Could you please help to resolve the issue.

Regards,
Sam

Hi,

Can you try if the patch I posted solves that? From the callchain it looks like the same thing.

Sebastian

Hi,

Many thanks for your kind response.
I will put it for long run test and update.

Could you please look at my below queries?

1.)
I had derived and tried a patch based on the below analysis. ( I referred below open source commit, to derive on this patch.
https://git.kernel.org/pub/scm/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v4.9.47-rt37-rebase&id=7a347757f027190c95a363a491c18156a926a370
)

In some cases pi_lock in rt_spin_lock_slowlock does not retain the irqs state while exiting function, this causes
issue in migrate_disable() + enable as they are not symmetrical in regard to the status of interrupts.
To fix pi_lock & pi_unlock in rt_spin_lock_slowlock, it has been modified to retain irq state by using
raw_spin_lock and raw_spin_unlock and also modified wait_lock in rt_spin_lock_slowlock with raw_spin_lock_irqsave & *_restore.

kernel/rtmutex.c | 25 ++++++++++++-------------

 1 file changed, 12 insertions(+), 13 deletions(-)

index 7cf4b8b..9c67d80 100644
@@ -1191,8 +1191,6 @@ static int adaptive_wait(struct rt_mutex *lock,
 }
 #endif
 
-# define pi_lock(lock) raw_spin_lock_irq(lock)
-# define pi_unlock(lock) raw_spin_unlock_irq(lock)
 
 /*
  * Slow path lock function spin_lock style: this variant is very

@@ -1206,14 +1204,15 @@ static void  noinline __sched

rt_spin_lock_slowlock(struct rt_mutex *lock)
struct task_struct *lock_owner, *self = current; struct rt_mutex_waiter waiter, *top_waiter; int ret;
+ unsigned long flags;

  rt_mutex_init_waiter(&waiter, true);

- raw_spin_lock(&lock->wait_lock);
+ raw_spin_lock_irqsave(&lock->wait_lock, flags);
init_lists(lock);

if (__try_to_take_rt_mutex(lock, self, NULL, STEAL_LATERAL)) {
- raw_spin_unlock(&lock->wait_lock);
+ raw_spin_unlock_irqrestore(&lock->wait_lock, flags); return;
}

@@ -1225,10 +1224,10 @@ static void noinline __sched rt_spin_lock_slowlock(struct rt_mutex *lock)
* as well. We are serialized via pi_lock against wakeups. See
* try_to_wake_up().
*/
- pi_lock(&self->pi_lock);
+ raw_spin_lock(&self->pi_lock);
self->saved_state = self->state; __set_current_state(TASK_UNINTERRUPTIBLE);
- pi_unlock(&self->pi_lock);
+ raw_spin_unlock(&self->pi_lock);

ret = task_blocks_on_rt_mutex(lock, &waiter, self, RT_MUTEX_MIN_CHAINWALK); BUG_ON(ret);
@@ -1241,18 +1240,18 @@ static void noinline __sched rt_spin_lock_slowlock(struct rt_mutex *lock)
top_waiter = rt_mutex_top_waiter(lock);
lock_owner = rt_mutex_owner(lock);

- raw_spin_unlock(&lock->wait_lock);
+ raw_spin_unlock_irqrestore(&lock->wait_lock, flags);

  debug_rt_mutex_print_deadlock(&waiter);

  if (top_waiter != &waiter || adaptive_wait(lock, lock_owner))
  schedule_rt_mutex(lock);

- raw_spin_lock(&lock->wait_lock);
+ raw_spin_lock_irqsave(&lock->wait_lock, flags);

- pi_lock(&self->pi_lock);
+ raw_spin_lock(&self->pi_lock);
__set_current_state(TASK_UNINTERRUPTIBLE);
- pi_unlock(&self->pi_lock);
+ raw_spin_unlock(&self->pi_lock);
}

/*
@@ -1262,10 +1261,10 @@ static void noinline __sched rt_spin_lock_slowlock(struct rt_mutex *lock)
* happened while we were blocked. Clear saved_state so
* try_to_wakeup() does not get confused.
*/
- pi_lock(&self->pi_lock);
+ raw_spin_lock(&self->pi_lock); __set_current_state(self->saved_state); self->saved_state = TASK_RUNNING;
- pi_unlock(&self->pi_lock);
+ raw_spin_unlock(&self->pi_lock);

/*
* try_to_take_rt_mutex() sets the waiter bit
@@ -1276,7 +1275,7 @@ static void noinline __sched rt_spin_lock_slowlock(struct rt_mutex *lock)
BUG_ON(rt_mutex_has_waiters(lock) && &waiter == rt_mutex_top_waiter(lock)); BUG_ON(!plist_node_empty(&waiter.list_entry));

- raw_spin_unlock(&lock->wait_lock);
+ raw_spin_unlock_irqrestore(&lock->wait_lock, flags);

debug_rt_mutex_free_waiter(&waiter);
}

2.7.4

We were testing above patch on multiple targets we could experience
some stuck issue on some remote target after 2 days. I am not
sure what really happens there, may be the issue when try for
scheduling with irq in disabled state.
The systems I have tested found to be worked 7 days after that I
stopped the test.


2.) With your patch during the slab allocations irqs will be in enabled state.
So if we enable irqs in early stage will there be any side effects? I
am sorry if my question doesn't seem
to be logical.



Regards,
Sam






On Fri, Nov 24, 2017 at 3:07 PM, Sebastian Andrzej Siewior

Hi,

Can you provide more informations on this? Like a stack strace that shows that this happens and when it happens? It should not happen.

…

Which patch? The patch I've sent and ask you for testing or the patch you had in this email?

You must not enable the interrupts too early. At the time of scheduling it is okay.

Sebastian

Hi,

Thanks for looking at my queries. Please see my answers inline.

1.)

Can you provide more informations on this? Like a stack strace that shows that this happens and when it happens? It should not happen.

As we were experiencing a panic issue with in 3 to 6 hours during the test(Test is continues soft reboot of the system
as mentioned in previous mail). With the help of instrument code we have been tracked it down to the function rt_spin_lock_slowlock() in rtmutex.c.
We see this issue when there is a state change for irqs from disabled to enabled. During slab allocations for SCSI on bootup
the irqs are found to be in disabled state since the system state is not yet in "RUNNING".

So we have added instrument code throughout the call trace and confirmed culprit as pi_lock()/pi_unlock for changing the irqs state. Basically it happens when it acquires the lock with irqs in disabled state.

I guess below scenario is happens when issue hits.

It looks like during normal cases with irqs in disabled state from the function rt_spin_lock_slowlock(),
It gets mutex lock in its first try and takes first return path so it
need not have to take pi_lock/unlock. But in some special case (error
case)
mutex lock is not available(I am not sure why this happens? ) and go further retry hence it acquires pi_lock/unlock
then into panic.

I am providing below some stack traces which we have seen during the test. All relevant debug configs were enabled while testing.

scsi 0:0:0:0: Direct-Access Linux scsi_debug 0004 PQ: 0 ANSI: 5
mm/mempolicy.c alloc_pages_current 2067 irq disabled!!! ==> debug
print added by me
mm/mempolicy.c alloc_pages_current 2067 irq disabled!!! ==> debug
print added by me
mm/mempolicy.c alloc_pages_current 2067 irq disabled!!! ==> debug
print added by me
mm/mempolicy.c alloc_pages_current 2067 irq disabled!!! ==> debug
print added by me

------------[ cut here ]------------
------------[ cut here ]------------
WARNING: at kernel/sched/core.c:3052 migrate_disable+0x10b/0x120()
Modules linked in:
CPU: 1 PID: 7 Comm: kworker/u8:0 Not tainted 3.10.107-rt120+ #49
Hardware name: To be filled by O.E.M. To be filled by
O.E.M./WADE-8078, BIOS R1.00.E0 07/07/2014
Workqueue: events_unbound async_run_entry_fn
 0000000000000000 ffff880159ee72e8 ffffffff816b617c 0000000000000000
 0000000000000009 ffff880159ee7328 ffffffff8105fc8b ffff880159ee7348
 ffff880159ea3540 0000000000000038 0000000000000001 0000000000000004
Call Trace:
 [<ffffffff816b617c>] dump_stack+0x4f/0x65
 [<ffffffff8105fc8b>] warn_slowpath_common+0x6b/0xa0
 [<ffffffff8105fcd5>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109585b>] migrate_disable+0x10b/0x120
 [<ffffffff81060c45>] call_console_drivers.constprop.20+0x65/0x100
 [<ffffffff81061da8>] console_unlock+0x398/0x3d0
 [<ffffffff81062303>] vprintk_emit+0x2b3/0x500
 [<ffffffff810b9526>] ? __try_to_take_rt_mutex+0x146/0x190
 [<ffffffff8109569c>] ? migrate_enable+0x14c/0x200
 [<ffffffff816b17e5>] printk+0x48/0x4a
 [<ffffffff8109569c>] ? migrate_enable+0x14c/0x200
 [<ffffffff8105fc59>] warn_slowpath_common+0x39/0xa0
 [<ffffffff8105fcd5>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109569c>] migrate_enable+0x14c/0x200
 [<ffffffff81100fb1>] get_page_from_freelist+0x9a1/0xbc0
 [<ffffffff812fc3d9>] ? number.isra.1+0x329/0x360
 [<ffffffff81101f89>] __alloc_pages_nodemask+0x179/0xa50
 [<ffffffff816ba6b3>] ? _raw_spin_unlock+0x13/0x40
 [<ffffffff8109de14>] ? update_curr+0xa4/0xf0
 [<ffffffff81138ab1>] alloc_pages_current+0x101/0x1f0
 [<ffffffff8113cf95>] new_slab+0x265/0x310
 [<ffffffff816b386e>] __slab_alloc.isra.62+0x4e0/0x6ca
 [<ffffffff816ba744>] ? _raw_spin_unlock_irq+0x14/0x40
 [<ffffffff810fbd0a>] ? mempool_alloc_slab+0x3a/0x70
 [<ffffffff816ba6b3>] ? _raw_spin_unlock+0x13/0x40
 [<ffffffff8113f5d0>] kmem_cache_alloc+0x170/0x190
 [<ffffffff810fbd0a>] ? mempool_alloc_slab+0x3a/0x70
 [<ffffffff810fbd0a>] mempool_alloc_slab+0x3a/0x70
 [<ffffffff810fc0be>] mempool_alloc+0xae/0x210
 [<ffffffff81063f85>] ? unpin_current_cpu+0x15/0x70
 [<ffffffff812d5ce8>] get_request+0x3a8/0x7c0
 [<ffffffff81089c30>] ? __init_waitqueue_head+0x60/0x60
 [<ffffffff812d619a>] blk_get_request+0x9a/0x140
 [<ffffffff8113fb68>] ? kmem_cache_free+0x188/0x1a0
 [<ffffffff813ef02a>] scsi_execute+0x4a/0x170
 [<ffffffff813ef226>] scsi_execute_req_flags+0xd6/0x190
 [<ffffffff81478349>] read_capacity_16+0xb9/0x550
 [<ffffffff81478fc8>] sd_revalidate_disk+0x4c8/0x1c90
 [<ffffffff8147a855>] sd_probe_async+0xc5/0x1d0
 [<ffffffff81090a96>] async_run_entry_fn+0x36/0x130
 [<ffffffff81081047>] process_one_work+0x147/0x3d0
 [<ffffffff810824e1>] worker_thread+0x161/0x3d0
 [<ffffffff81082380>] ? manage_workers.isra.33+0x2f0/0x2f0
 [<ffffffff81088f75>] kthread+0xc5/0xd0
 [<ffffffff81088eb0>] ? __init_kthread_worker+0x60/0x60
 [<ffffffff816bb37e>] ret_from_fork+0x4e/0x80
 [<ffffffff81088eb0>] ? __init_kthread_worker+0x60/0x60
---[ end trace 0000000000000001 ]---
------------[ cut here ]------------
WARNING: at kernel/sched/core.c:3087 migrate_enable+0x14c/0x200()
Modules linked in:
CPU: 1 PID: 7 Comm: kworker/u8:0 Tainted: G        W    3.10.107-rt120+ #49
Hardware name: To be filled by O.E.M. To be filled by
O.E.M./WADE-8078, BIOS R1.00.E0 07/07/2014
Workqueue: events_unbound async_run_entry_fn
 0000000000000000 ffff880159ee7228 ffffffff816b617c 0000000000000000
 0000000000000009 ffff880159ee7268 ffffffff8105fc8b ffff880159ee7258
 ffff880159ea3540 ffffffff81e1a9e8 ffffffff81e1a840 0000000000000000
Call Trace:
 [<ffffffff816b617c>] dump_stack+0x4f/0x65
 [<ffffffff8105fc8b>] warn_slowpath_common+0x6b/0xa0
 [<ffffffff8105fcd5>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109569c>] migrate_enable+0x14c/0x200
 [<ffffffff8138ae56>] serial8250_poll+0xd6/0x120
 [<ffffffff813878dd>] uartdrv_console_write+0xdd/0x330
 [<ffffffff81060cad>] call_console_drivers.constprop.20+0xcd/0x100
 [<ffffffff81061da8>] console_unlock+0x398/0x3d0
 [<ffffffff81062303>] vprintk_emit+0x2b3/0x500
 [<ffffffff810b9526>] ? __try_to_take_rt_mutex+0x146/0x190
sd 0:0:0:0: Attached scsi generic sg0 type 0
 [<ffffffff8109569c>] ? migrate_enable+0x14c/0x200
 [<ffffffff816b17e5>] printk+0x48/0x4a
 [<ffffffff8109569c>] ? migrate_enable+0x14c/0x200
 [<ffffffff8105fc59>] warn_slowpath_common+0x39/0xa0
 [<ffffffff8105fcd5>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109569c>] migrate_enable+0x14c/0x200
 [<ffffffff81100fb1>] get_page_from_freelist+0x9a1/0xbc0
 [<ffffffff812fc3d9>] ? number.isra.1+0x329/0x360
 [<ffffffff81101f89>] __alloc_pages_nodemask+0x179/0xa50
 [<ffffffff816ba6b3>] ? _raw_spin_unlock+0x13/0x40
 [<ffffffff8109de14>] ? update_curr+0xa4/0xf0
 [<ffffffff81138ab1>] alloc_pages_current+0x101/0x1f0
 [<ffffffff8113cf95>] new_slab+0x265/0x310
 [<ffffffff816b386e>] __slab_alloc.isra.62+0x4e0/0x6ca
 [<ffffffff816ba744>] ? _raw_spin_unlock_irq+0x14/0x40
 [<ffffffff810fbd0a>] ? mempool_alloc_slab+0x3a/0x70
 [<ffffffff816ba6b3>] ? _raw_spin_unlock+0x13/0x40
 [<ffffffff8113f5d0>] kmem_cache_alloc+0x170/0x190
 [<ffffffff810fbd0a>] ? mempool_alloc_slab+0x3a/0x70
 [<ffffffff810fbd0a>] mempool_alloc_slab+0x3a/0x70
 [<ffffffff810fc0be>] mempool_alloc+0xae/0x210
 [<ffffffff81063f85>] ? unpin_current_cpu+0x15/0x70
 [<ffffffff812d5ce8>] get_request+0x3a8/0x7c0
 [<ffffffff81089c30>] ? __init_waitqueue_head+0x60/0x60
 [<ffffffff812d619a>] blk_get_request+0x9a/0x140
 [<ffffffff8113fb68>] ? kmem_cache_free+0x188/0x1a0
 [<ffffffff813ef02a>] scsi_execute+0x4a/0x170
 [<ffffffff813ef226>] scsi_execute_req_flags+0xd6/0x190
 [<ffffffff81478349>] read_capacity_16+0xb9/0x550
 [<ffffffff81478fc8>] sd_revalidate_disk+0x4c8/0x
------------------------------------------------------------------------------------

scsi0 : scsi_debug, version 1.82 [20100324], dev_size_mb=8, opts=0x0
scsi 0:0:0:0: Direct-Access Linux scsi_debug 0004 PQ: 0 ANSI: 5
kernel/rtmutex.c rt_spin_lock_slowlock 1266 enterirq 1 exitirq 0!!!==> debug print added by me
XXX: After local_spin_lock_irqsave enterirqs 1 exitirqs 0!!! ==>
debug print added by me

------------[ cut here ]------------
WARNING: at kernel/sched/core.c:3052 migrate_disable+0x10b/0x120()
Modules linked in:
CPU: 0 PID: 7 Comm: kworker/u8:0 Not tainted 3.10.107-rt120+ #106
Hardware name: To be filled by O.E.M. To be filled by
O.E.M./WADE-8078, BIOS R1.00.E0 07/07/2014
Workqueue: events_unbound async_run_entry_fn
 0000000000000000 ffff880159ee73f8 ffffffff816b65bc 0000000000000000
 0000000000000009 ffff880159ee7438 ffffffff8105fc8b ffff880159ee7438
 ffff880159ea3540 0000000000000044 0000000000000001 0000000000000004
Call Trace:
 [<ffffffff816b65bc>] dump_stack+0x4f/0x65
 [<ffffffff8105fc8b>] warn_slowpath_common+0x6b/0xa0
 [<ffffffff8105fcd5>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109585b>] migrate_disable+0x10b/0x120
 [<ffffffff81060c45>] call_console_drivers.constprop.20+0x65/0x100
 [<ffffffff81061da8>] console_unlock+0x398/0x3d0
 [<ffffffff81062303>] vprintk_emit+0x2b3/0x500
 [<ffffffff816b1c25>] printk+0x48/0x4a
 [<ffffffff81100f85>] get_page_from_freelist+0x985/0xc70
 [<ffffffff81102029>] __alloc_pages_nodemask+0x179/0xa50
 [<ffffffff81100b7a>] ? get_page_from_freelist+0x57a/0xc70
 [<ffffffff81063f85>] ? unpin_current_cpu+0x15/0x70
 [<ffffffff81138b2c>] alloc_pages_current+0xdc/0x1b0
 [<ffffffff8113d015>] new_slab+0x285/0x370
 [<ffffffff816b3cae>] __slab_alloc.isra.62+0x4e0/0x6ca
 [<ffffffff810fbcf8>] ? mempool_alloc_slab+0x28/0x60
 [<ffffffff8113f752>] kmem_cache_alloc+0x1a2/0x1e0
 [<ffffffff810fbcf8>] ? mempool_alloc_slab+0x28/0x60
 [<ffffffff810fbcf8>] mempool_alloc_slab+0x28/0x60
 [<ffffffff810fc0ae>] mempool_alloc+0xae/0x210
 [<ffffffff81063f85>] ? unpin_current_cpu+0x15/0x70
 [<ffffffff812d60f8>] get_request+0x3a8/0x7c0
 [<ffffffff81089c30>] ? __init_waitqueue_head+0x60/0x60
 [<ffffffff812d65aa>] blk_get_request+0x9a/0x140
 [<ffffffff813ef46a>] scsi_execute+0x4a/0x170
 [<ffffffff813ef666>] scsi_execute_req_flags+0xd6/0x190
 [<ffffffff81479008>] sd_revalidate_disk+0xc8/0x1c90
 [<ffffffff816ba561>] ? rt_spin_lock_slowlock+0x291/0x340
 [<ffffffff8147ac95>] sd_probe_async+0xc5/0x1d0
 [<ffffffff81090a96>] async_run_entry_fn+0x36/0x130
 [<ffffffff81081047>] process_one_work+0x147/0x3d0
 [<ffffffff810824e1>] worker_thread+0x161/0x3d0
 [<ffffffff81082380>] ? manage_workers.isra.33+0x2f0/0x2f0
 [<ffffffff81088f75>] kthread+0xc5/0xd0
 [<ffffffff81088eb0>] ? __init_kthread_worker+0x60/0x60
 [<ffffffff816bb8fe>] ret_from_fork+0x4e/0x80
 [<ffffffff81088eb0>] ? __init_kthread_worker+0x60/0x60
---[ end trace 0000000000000001 ]---
------------[ cut here ]------------
WARNING: at kernel/sched/core.c:3087 migrate_enable+0x14c/0x200()
Modules linked in:
CPU: 0 PID: 7 Comm: kworker/u8:0 Tainted: G        W    3.10.107-rt120+ #106
Hardware name: To be filled by O.E.M. To be filled by
O.E.M./WADE-8078, BIOS R1.00.E0 07/07/2014
Workqueue: events_unbound async_run_entry_fn
 0000000000000000 ffff880159ee7338 ffffffff816b65bc 0000000000000000
 0000000000000009 ffff880159ee7378 ffffffff8105fc8b ffff880159ee7368
 ffff880159ea3540 ffffffff81e1aa28 ffffffff81e1a880 0000000000000000
Call Trace:
 [<ffffffff816b65bc>] dump_stack+0x4f/0x65
 [<ffffffff8105fc8b>] warn_slowpath_common+0x6b/0xa0
 [<ffffffff8105fcd5>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109569c>] migrate_enable+0x14c/0x200
 [<ffffffff8138b266>] serial8250_poll+0xd6/0x120
 [<ffffffff81387ced>] uartdrv_console_write+0xdd/0x330
 [<ffffffff81060cad>] call_console_drivers.constprop.20+0xcd/0x100
 [<ffffffff81061da8>] console_unlock+0x398/0x3d0
 [<ffffffff81062303>] vprintk_emit+0x2b3/0x500
 [<ffffffff816b1c25>] printk+0x48/0x4a
 [<ffffffff81100f85>] get_page_from_freelist+0x985/0xc70
 [<ffffffff81102029>] __alloc_pages_nodemask+0x179/0xa50
 [<ffffffff81100b7a>] ? get_page_from_freelist+0x57a/0xc70
 [<ffffffff81063f85>] ? unpin_current_cpu+0x15/0x70
 [<ffffffff81138b2c>] alloc_pages_current+0xdc/0x1b0
 [<ffffffff8113d015>] new_slab+0x285/0x370
 [<ffffffff816b3cae>] __slab_alloc.isra.62+0x4e0/0x6ca
 [<ffffffff810fbcf8>] ? mempool_alloc_slab+0x28/0x60
 [<ffffffff8113f752>] kmem_cache_alloc+0x1a2/0x1e0
 [<ffffffff810fbcf8>] ? mempool_alloc_slab+0x28/0x60
 [<ffffffff810fbcf8>] mempool_alloc_slab+0x28/0x60
 [<ffffffff810fc0ae>] mempool_alloc+0xae/0x210
 [<ffffffff81063f85>] ? unpin_current_cpu+0x15/0x70
 [<ffffffff812d60f8>] get_request+0x3a8/0x7c0
 [<ffffffff81089c30>] ? __init_waitqueue_head+0x60/0x60
 [<ffffffff812d65aa>] blk_get_request+0x9a/0x140
 [<ffffffff813ef46a>] scsi_execute+0x4a/0x170
 [<ffffffff813ef666>] scsi_execute_req_flags+0xd6/0x190
 [<ffffffff81479008>] sd_revalidate_disk+0xc8/0x1c90
 [<ffffffff816ba561>] ? rt_spin_lock_slowlock+0x291/0x340
 [<ffffffff8147ac95>] sd_probe_async+0xc5/0x1d0
 [<ffffffff81090a96>] async_run_entry_fn+0x36/0x130
 [<ffffffff81081047>] process_one_work+0x147/0x3d0
 [<ffffffff810824e1>] worker_thread+0x161/0x3d0
 [<ffffffff81082380>] ? manage_workers.isra.33+0x2f0/0x2f0
 [<ffffffff81088f75>] kthread+0xc5/0xd0
 [<ffffffff81088eb0>] ? __init_kthread_worker+0x60/0x60
 [<ffffffff816bb8fe>] ret_from_fork+0x4e/0x80
 [<ffffffff81088eb0>] ? __init_kthread_worker+0x60/0x60
---[ end trace 0000000000000002 ]---
XXX: __rmqueue enterirqs 1 exitirqs 0!!!             ==> debug print added by me
XXX: __mod_zone_freepage_state enterirq 1 exitirq 0!!!    ==> debug
print added by me
------------[ cut here ]------------
sd 0:0:0:0: Attached scsi generic sg0 type 0

ahci 0000:00:13.0: controller can't do DEVSLP, turning off
ahci 0000:00:13.0: AHCI 0001.0300 32 slots 2 ports 3 Gbps 0x0 impl SATA mode ahci 0000:00:13.0: flags: 64bit ncq pm led clo pio slum part deso scsi1 : ahci
----------------------------------------------------------------------------------------------

WARNING: at kernel/sched/core.c:3052 migrate_disable+0x10b/0x120()
Modules linked in:
CPU: 1 PID: 7 Comm: kworker/u8:0 Not tainted 3.10.107-rt120+ #49
Hardware name: To be filled by O.E.M. To be filled by
O.E.M./WADE-8078, BIOS R1.00.E0 07/07/2014
Workqueue: events_unbound async_run_entry_fn
 0000000000000000 ffff880159ee72e8 ffffffff816b617c 0000000000000000
 0000000000000009 ffff880159ee7328 ffffffff8105fc8b ffff880159ee7348
 ffff880159ea3540 0000000000000038 0000000000000001 0000000000000004
Call Trace:
 [<ffffffff816b617c>] dump_stack+0x4f/0x65
 [<ffffffff8105fc8b>] warn_slowpath_common+0x6b/0xa0
 [<ffffffff8105fcd5>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109585b>] migrate_disable+0x10b/0x120
 [<ffffffff81060c45>] call_console_drivers.constprop.20+0x65/0x100
 [<ffffffff81061da8>] console_unlock+0x398/0x3d0
 [<ffffffff81062303>] vprintk_emit+0x2b3/0x500
 [<ffffffff810b9526>] ? __try_to_take_rt_mutex+0x146/0x190
 [<ffffffff8109569c>] ? migrate_enable+0x14c/0x200
 [<ffffffff816b17e5>] printk+0x48/0x4a
 [<ffffffff8109569c>] ? migrate_enable+0x14c/0x200
 [<ffffffff8105fc59>] warn_slowpath_common+0x39/0xa0
 [<ffffffff8105fcd5>] warn_slowpath_null+0x15/0x20
 [<ffffffff8109569c>] migrate_enable+0x14c/0x200
 [<ffffffff81100fb1>] get_page_from_freelist+0x9a1/0xbc0
 [<ffffffff812fc3d9>] ? number.isra.1+0x329/0x360
 [<ffffffff81101f89>] __alloc_pages_nodemask+0x179/0xa50
 [<ffffffff816ba6b3>] ? _raw_spin_unlock+0x13/0x40
 [<ffffffff8109de14>] ? update_curr+0xa4/0xf0
 [<ffffffff81138ab1>] alloc_pages_current+0x101/0x1f0
 [<ffffffff8113cf95>] new_slab+0x265/0x310
 [<ffffffff816b386e>] __slab_alloc.isra.62+0x4e0/0x6ca
 [<ffffffff816ba744>] ? _raw_spin_unlock_irq+0x14/0x40
 [<ffffffff810fbd0a>] ? mempool_alloc_slab+0x3a/0x70
 [<ffffffff816ba6b3>] ? _raw_spin_unlock+0x13/0x40
 [<ffffffff8113f5d0>] kmem_cache_alloc+0x170/0x190
 [<ffffffff810fbd0a>] ? mempool_alloc_slab+0x3a/0x70
 [<ffffffff810fbd0a>] mempool_alloc_slab+0x3a/0x70
 [<ffffffff810fc0be>] mempool_alloc+0xae/0x210
 [<ffffffff81063f85>] ? unpin_current_cpu+0x15/0x70
 [<ffffffff812d5ce8>] get_request+0x3a8/0x7c0
 [<ffffffff81089c30>] ? __init_waitqueue_head+0x60/0x60
 [<ffffffff812d619a>] blk_get_request+0x9a/0x140
 [<ffffffff8113fb68>] ? kmem_cache_free+0x188/0x1a0
 [<ffffffff813ef02a>] scsi_execute+0x4a/0x170
 [<ffffffff813ef226>] scsi_execute_req_flags+0xd6/0x190
 [<ffffffff81478349>] read_capacity_16+0xb9/0x550
 [<ffffffff81478fc8>] sd_revalidate_disk+0x4c8/0x1c90
 [<ffffffff8147a855>] sd_probe_async+0xc5/0x1d0
 [<ffffffff81090a96>] async_run_entry_fn+0x36/0x130
 [<ffffffff81081047>] process_one_work+0x147/0x3d0
 [<ffffffff810824e1>] worker_thread+0x161/0x3d0
 [<ffffffff81082380>] ? manage_workers.isra.33+0x2f0/0x2f0
 [<ffffffff81088f75>] kthread+0xc5/0xd0
 [<ffffffff81088eb0>] ? __init_kthread_worker+0x60/0x60
 [<ffffffff816bb37e>] ret_from_fork+0x4e/0x80
 [<ffffffff81088eb0>] ? __init_kthread_worker+0x60/0x60
---[ end trace 0000000000000001 ]---
------------[ cut here ]------------
WARNING: at kernel/sched/core.c:3087 migrate_enable+0x14c/0x200()
Modules linked in:

…

Which patch? The patch I've sent and ask you for testing or the patch you had in this email?

Patch I had in this mail.

You must not enable the interrupts too early. At the time of scheduling it is okay.

Thanks. I have been testing your patch, I will update once I finish the long run test.

Regards,
Sam

Hi,

please don't top-post. Please use a client which adds proper indention while quoting the email.

but by pi_lock/pi_unlock you don't mean the futex operation, do you?

based on the fact that the system is not in state "running" yet and this trace here:

…

…

…

I would that this is the same issue and the patch I posted should help.

Okay, so a note to myself, there is nothing outstanding for me to do so far.

Sebastian

The whole email looks like quote of my email with no additional content. Did you press the send button too soon or did you hide the new content somewhere where I could not find it :)?

Sebastian

Pavel V. Panteleev reported that a WARN_ON_ONCE(p->migrate_disable <= 0) triggered in 3.14.79-rt85 during boot from radix_tree_insert(). The problem is that radix_tree_insert() allocates memory and SLUB does not enable interrupts in allocate_slab().
They can't be be enabled unconditionally because early in the boot process they have to remain off. Enabling them at the "SYSTEM_RUNNING" state is too late. The earliest point is once we have scheduling working that is once the kthread is running.

In newer -RT (v4.11+) there is the check
if (system_state > SYSTEM_BOOTING)

to enable interrupts in the allocator which is what this patch intends:
Once scheduling is working enable interrupts in the allocator path so we can take sleeping locks.

---
 init/main.c | 2 ++
 mm/slub.c   | 3 ++-
 2 files changed, 4 insertions(+), 1 deletion(-)

index 6470deef01c9..362761effeac 100644
@@ -379,6 +379,7 @@ static void __init setup_command_line(char *command_line)
  */
 
 static __initdata DECLARE_COMPLETION(kthreadd_done);
+extern bool slab_do_irq_on;
 
 static noinline void __ref rest_init(void)
 {

@@ -396,6 +397,7 @@ static noinline void __ref rest_init(void)
 	rcu_read_lock();
 	kthreadd_task = find_task_by_pid_ns(pid, &init_pid_ns);
 	rcu_read_unlock();
+	slab_do_irq_on = true;
 	complete(&kthreadd_done);
 
 	/*

index 67eb368b9314..22ec805130e5 100644
@@ -1527,6 +1527,7 @@ static inline bool shuffle_freelist(struct kmem_cache *s, struct page *page)
 	return false;
 }
 #endif /* CONFIG_SLAB_FREELIST_RANDOM */
+bool slab_do_irq_on;
 
 static struct page *allocate_slab(struct kmem_cache *s, gfp_t flags, int node)
 {

@@ -1543,7 +1544,7 @@ static struct page *allocate_slab(struct kmem_cache *s, gfp_t flags, int node)
 	if (gfpflags_allow_blocking(flags))
 		enableirqs = true;
 #ifdef CONFIG_PREEMPT_RT_FULL
-	if (system_state == SYSTEM_RUNNING)
+	if (slab_do_irq_on)
 		enableirqs = true;
 #endif
 	if (enableirqs)

2.15.0