Skip to contentSkip to conversation

rcu stalls seen with numasched_v2 patches applied.

DISCUSSION Srikar Dronamraju 3 participants 11 messages Aug 7, 2012 – Aug 17, 2012 Scheduler

lore
Share & tools
lore

Srikar Dronamraju

author
#0 lore raw

Hi,

I saw this while I was running the 2nd August -tip kernel + Peter's numasched patches.

Top showed load average to be 240, there was one cpu (cpu 7) which showed 100% while all other cpus were idle. The system showed some sluggishness. Before I saw this I ran Andrea's autonuma benchmark couple of times.

I am not sure if this is an already reported issue/known issue.

 INFO: rcu_sched self-detected stall on CPU { 7}  (t=105182911 jiffies)
 Pid: 5173, comm: qpidd Tainted: G        W    3.5.0numasched_v2_020812+ #1
 Call Trace:
 <IRQ>  [<ffffffff810d4c7e>] rcu_check_callbacks+0x18e/0x650
 [<ffffffff81060918>] update_process_times+0x48/0x90
 [<ffffffff810a2a7e>] tick_sched_timer+0x6e/0xe0
 [<ffffffff810789a5>] __run_hrtimer+0x75/0x1a0
 [<ffffffff810a2a10>] ? tick_setup_sched_timer+0x100/0x100
 [<ffffffff810591cf>] ? __do_softirq+0x13f/0x240
 [<ffffffff81078d56>] hrtimer_interrupt+0xf6/0x240
 [<ffffffff814f0179>] smp_apic_timer_interrupt+0x69/0x99
 [<ffffffff814ef14a>] apic_timer_interrupt+0x6a/0x70
 <EOI>  [<ffffffff814e64b2>] ? _raw_spin_unlock_irqrestore+0x12/0x20
 [<ffffffff81082552>] sched_setnode+0x82/0xf0
 [<ffffffff8108bd38>] task_numa_work+0x1e8/0x240
 [<ffffffff81070c6c>] task_work_run+0x6c/0x80
 [<ffffffff81013984>] do_notify_resume+0x94/0xa0
 [<ffffffff814e6a6c>] retint_signal+0x48/0x8c
 INFO: rcu_sched self-detected stall on CPU { 7}  (t=105362914 jiffies)
 Pid: 5173, comm: qpidd Tainted: G        W    3.5.0numasched_v2_020812+ #1
 Call Trace:
 <IRQ>  [<ffffffff810d4c7e>] rcu_check_callbacks+0x18e/0x650
 [<ffffffff81060918>] update_process_times+0x48/0x90
 [<ffffffff810a2a7e>] tick_sched_timer+0x6e/0xe0
 [<ffffffff810789a5>] __run_hrtimer+0x75/0x1a0
 [<ffffffff810a2a10>] ? tick_setup_sched_timer+0x100/0x100
 [<ffffffff810591cf>] ? __do_softirq+0x13f/0x240
 [<ffffffff81078d56>] hrtimer_interrupt+0xf6/0x240
 [<ffffffff814f0179>] smp_apic_timer_interrupt+0x69/0x99
 [<ffffffff814ef14a>] apic_timer_interrupt+0x6a/0x70
 <EOI>  [<ffffffff81082562>] ? sched_setnode+0x92/0xf0
 [<ffffffff81082552>] ? sched_setnode+0x82/0xf0
 [<ffffffff8108bd38>] task_numa_work+0x1e8/0x240
 [<ffffffff81070c6c>] task_work_run+0x6c/0x80
 [<ffffffff81013984>] do_notify_resume+0x94/0xa0
 [<ffffffff814e6a6c>] retint_signal+0x48/0x8c
 INFO: rcu_sched self-detected stall on CPU { 7}  (t=105542917 jiffies)
 Pid: 5173, comm: qpidd Tainted: G        W    3.5.0numasched_v2_020812+ #1
 Call Trace:
 <IRQ>  [<ffffffff810d4c7e>] rcu_check_callbacks+0x18e/0x650
 [<ffffffff81060918>] update_process_times+0x48/0x90
 [<ffffffff810a2a7e>] tick_sched_timer+0x6e/0xe0
 [<ffffffff810789a5>] __run_hrtimer+0x75/0x1a0
 [<ffffffff810a2a10>] ? tick_setup_sched_timer+0x100/0x100
 [<ffffffff810591cf>] ? __do_softirq+0x13f/0x240
 [<ffffffff81078d56>] hrtimer_interrupt+0xf6/0x240
 [<ffffffff814f0179>] smp_apic_timer_interrupt+0x69/0x99
 [<ffffffff814ef14a>] apic_timer_interrupt+0x6a/0x70
 <EOI>  [<ffffffff814e64b2>] ? _raw_spin_unlock_irqrestore+0x12/0x20
 [<ffffffff81082552>] sched_setnode+0x82/0xf0
 [<ffffffff8108bd38>] task_numa_work+0x1e8/0x240
 [<ffffffff81070c6c>] task_work_run+0x6c/0x80
 [<ffffffff81013984>] do_notify_resume+0x94/0xa0
 [<ffffffff814e6a6c>] retint_signal+0x48/0x8c

<these messages keep repeating>

I saw this on a 2 node 24 cpu machine.

If I am able to reproduce this again, I plan to test these without the numasched patches applied.

Signature · 2 lines
Thanks and Regards
Srikar Dronamraju
maintainer
#1 lore raw
Quoted 22 lines · Srikar Dronamraju

Hi,

I saw this while I was running the 2nd August -tip kernel + Peter's numasched patches.

Top showed load average to be 240, there was one cpu (cpu 7) which showed 100% while all other cpus were idle. The system showed some sluggishness. Before I saw this I ran Andrea's autonuma benchmark couple of times.

I am not sure if this is an already reported issue/known issue.

 INFO: rcu_sched self-detected stall on CPU { 7}  (t=105182911 jiffies)
 Pid: 5173, comm: qpidd Tainted: G        W    3.5.0numasched_v2_020812+ #1
 Call Trace:
 <IRQ>  [<ffffffff810d4c7e>] rcu_check_callbacks+0x18e/0x650
 [<ffffffff81060918>] update_process_times+0x48/0x90
 [<ffffffff810a2a7e>] tick_sched_timer+0x6e/0xe0
 [<ffffffff810789a5>] __run_hrtimer+0x75/0x1a0
 [<ffffffff810a2a10>] ? tick_setup_sched_timer+0x100/0x100
 [<ffffffff810591cf>] ? __do_softirq+0x13f/0x240
 [<ffffffff81078d56>] hrtimer_interrupt+0xf6/0x240
Quoted 8 lines
 [<ffffffff814f0179>] smp_apic_timer_interrupt+0x69/0x99
 [<ffffffff814ef14a>] apic_timer_interrupt+0x6a/0x70
 <EOI>  [<ffffffff814e64b2>] ? _raw_spin_unlock_irqrestore+0x12/0x20
 [<ffffffff81082552>] sched_setnode+0x82/0xf0
 [<ffffffff8108bd38>] task_numa_work+0x1e8/0x240
 [<ffffffff81070c6c>] task_work_run+0x6c/0x80
 [<ffffffff81013984>] do_notify_resume+0x94/0xa0
 [<ffffffff814e6a6c>] retint_signal+0x48/0x8c

I haven't seen anything like that (obviously), but the one thing you can try is undo the optimization Oleg suggested and use a separate callback_head for the task_work and not reuse task_struct::rcu.

author
#2 lore raw
Quoted 22 lines · Peter Zijlstra
Quoted 12 lines · Srikar Dronamraju

Hi,

 INFO: rcu_sched self-detected stall on CPU { 7}  (t=105182911 jiffies)
 Pid: 5173, comm: qpidd Tainted: G        W    3.5.0numasched_v2_020812+ #1
 Call Trace:
 <IRQ>  [<ffffffff810d4c7e>] rcu_check_callbacks+0x18e/0x650
 [<ffffffff81060918>] update_process_times+0x48/0x90
 [<ffffffff810a2a7e>] tick_sched_timer+0x6e/0xe0
 [<ffffffff810789a5>] __run_hrtimer+0x75/0x1a0
 [<ffffffff810a2a10>] ? tick_setup_sched_timer+0x100/0x100
 [<ffffffff810591cf>] ? __do_softirq+0x13f/0x240
 [<ffffffff81078d56>] hrtimer_interrupt+0xf6/0x240
Quoted 8 lines
 [<ffffffff814f0179>] smp_apic_timer_interrupt+0x69/0x99
 [<ffffffff814ef14a>] apic_timer_interrupt+0x6a/0x70
 <EOI>  [<ffffffff814e64b2>] ? _raw_spin_unlock_irqrestore+0x12/0x20
 [<ffffffff81082552>] sched_setnode+0x82/0xf0
 [<ffffffff8108bd38>] task_numa_work+0x1e8/0x240
 [<ffffffff81070c6c>] task_work_run+0x6c/0x80
 [<ffffffff81013984>] do_notify_resume+0x94/0xa0
 [<ffffffff814e6a6c>] retint_signal+0x48/0x8c
Quoted 4 lines

I haven't seen anything like that (obviously), but the one thing you can try is undo the optimization Oleg suggested and use a separate callback_head for the task_work and not reuse task_struct::rcu.

Are you referring to this the commit 158e1645e (trim task_work: get rid of hlist)

I am also able to reproduce this on another 8 node machine too.

Just to update, I had to revert commit: b9403130a5 sched/cleanups: Add load balance cpumask pointer to 'struct lb_env' so that your patches apply cleanly. (I dont think this should have caused any problem.. but)

Signature · 2 lines
Thanks and Regards
Srikar
maintainer
#3 lore raw
Quoted 1 line · Srikar Dronamraju

Are you referring to this the commit 158e1645e (trim task_work: get rid of hlist)

No, to something like the below..

Quoted 1 line

I am also able to reproduce this on another 8 node machine too.

Ship me one ;-)

Quoted 3 lines

Just to update, I had to revert commit: b9403130a5 sched/cleanups: Add load balance cpumask pointer to 'struct lb_env' so that your patches apply cleanly. (I dont think this should have caused any problem.. but)

Yeah, I've got a rebase on top of that.. just wanted fold this page::last_nid thing into the page::flags before posting again.

---

include/linux/sched.h +1 -0
@@ -1539,6 +1539,7 @@ struct task_struct {
 #ifdef CONFIG_SMP
 	u64 node_stamp;			/* migration stamp  */
 	unsigned long numa_contrib;
+	struct callback_head numa_work;
 #endif /* CONFIG_SMP  */
 #endif /* CONFIG_NUMA */
 	struct rcu_head rcu;
kernel/sched/fair.c +3 -3
@@ -816,7 +816,7 @@ void task_numa_work(struct callback_head
 	struct task_struct *t, *p = current;
 	int node = p->node_last;
 
-	WARN_ON_ONCE(p != container_of(work, struct task_struct, rcu));
+	WARN_ON_ONCE(p != container_of(work, struct task_struct, numa_work));
 
 	/*
 	 * Who cares about NUMA placement when they're dying.

@@ -891,8 +891,8 @@ void task_tick_numa(struct rq *rq, struc
 			 * yet and exit_task_work() is called before
 			 * exit_notify().
 			 */
-			init_task_work(&curr->rcu, task_numa_work);
-			task_work_add(curr, &curr->rcu, true);
+			init_task_work(&curr->numa_work, task_numa_work);
+			task_work_add(curr, &curr->numa_work, true);
 		}
 		curr->node_last = node;
 	}
author
#4 lore raw
Quoted 24 lines

---

include/linux/sched.h +1 -0
@@ -1539,6 +1539,7 @@ struct task_struct {
 #ifdef CONFIG_SMP
 	u64 node_stamp;			/* migration stamp  */
 	unsigned long numa_contrib;
+	struct callback_head numa_work;
 #endif /* CONFIG_SMP  */
 #endif /* CONFIG_NUMA */
 	struct rcu_head rcu;
kernel/sched/fair.c +1 -1
@@ -816,7 +816,7 @@ void task_numa_work(struct callback_head
 	struct task_struct *t, *p = current;
 	int node = p->node_last;
 
-	WARN_ON_ONCE(p != container_of(work, struct task_struct, rcu));
+	WARN_ON_ONCE(p != container_of(work, struct task_struct, numa_work));
 
 	/*
 	 * Who cares about NUMA placement when they're dying.

kernel/sched/fair.c void task_tick_numa(struct rq *rq, struc · line 898

Quoted 10 lines
kernel/sched/fair.c +2 -2
@@ -891,8 +891,8 @@ void task_tick_numa(struct rq *rq, struc
 			 * yet and exit_task_work() is called before
 			 * exit_notify().
 			 */
-			init_task_work(&curr->rcu, task_numa_work);
-			task_work_add(curr, &curr->rcu, true);
+			init_task_work(&curr->numa_work, task_numa_work);
+			task_work_add(curr, &curr->numa_work, true);
 		}
 		curr->node_last = node;
 	}

This change worked well on the 2 node machine but on the 8 node machine it hangs with repeated messages

Pid: 60935, comm: numa01 Tainted: G W 3.5.0-numasched_v2_020812+ #4

Call Trace:
<IRQ>  [<ffffffff810d32e2>] ? rcu_check_callback s+0x632/0x650
[<ffffffff81061bb8>] ? update_process_times+0x48/0x90
[<ffffffff810a2a4e>] ? tick_sched_timer+0x6e/0xe0
[<ffffffff81079c85>] ? __run_hrtimer+0x75/0x1a0
[<ffffffff810a29e0>] ? tick_setup_sched_timer+0x100/0x100
[<ffffffff8107a036>] ? hrtimer_interrupt+0xf6/0x250
[<ffffffff814f1379>] ? smp_apic_timer_interrupt+0x69/0x99
[<ffffffff814f034a>] ? apic_timer_interrupt+0x6a/0x70
<EOI>  [<ffffffff811082e3>] ? wait_on_page_bit+0x73/0x80
[<ffffffff814e7992>] ? _raw_spin_lock+0x22/0x30
[<ffffffff81131bf3>] ? handle_pte_fault+0x1b3/0xca0
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff8107a9a8>] ? up_read+0x18/0x30
[<ffffffff814eb2be>] ? do_page_fault+0x13e/0x460
[<ffffffff810137ba>] ? __switch_to+0x1aa/0x460
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff814e7de5>] ? page_fault+0x25/0x30

{ 3} (t=62998 jiffies)

maintainer
#5 lore raw
Quoted 22 lines · Srikar Dronamraju

This change worked well on the 2 node machine but on the 8 node machine it hangs with repeated messages

Pid: 60935, comm: numa01 Tainted: G W 3.5.0-numasched_v2_020812+ #4

Call Trace:
<IRQ>  [<ffffffff810d32e2>] ? rcu_check_callback s+0x632/0x650
[<ffffffff81061bb8>] ? update_process_times+0x48/0x90
[<ffffffff810a2a4e>] ? tick_sched_timer+0x6e/0xe0
[<ffffffff81079c85>] ? __run_hrtimer+0x75/0x1a0
[<ffffffff810a29e0>] ? tick_setup_sched_timer+0x100/0x100
[<ffffffff8107a036>] ? hrtimer_interrupt+0xf6/0x250
[<ffffffff814f1379>] ? smp_apic_timer_interrupt+0x69/0x99
[<ffffffff814f034a>] ? apic_timer_interrupt+0x6a/0x70
<EOI>  [<ffffffff811082e3>] ? wait_on_page_bit+0x73/0x80
[<ffffffff814e7992>] ? _raw_spin_lock+0x22/0x30
[<ffffffff81131bf3>] ? handle_pte_fault+0x1b3/0xca0
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff8107a9a8>] ? up_read+0x18/0x30
[<ffffffff814eb2be>] ? do_page_fault+0x13e/0x460
[<ffffffff810137ba>] ? __switch_to+0x1aa/0x460
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff814e7de5>] ? page_fault+0x25/0x30
Quoted 2 lines

{ 3} (t=62998 jiffies)

If you run a -tip kernel without the numa patches, does that work?

maintainer
#6 lore raw
Quoted 27 lines · Peter Zijlstra
Quoted 22 lines · Srikar Dronamraju

This change worked well on the 2 node machine but on the 8 node machine it hangs with repeated messages

Pid: 60935, comm: numa01 Tainted: G W 3.5.0-numasched_v2_020812+ #4

Call Trace:
<IRQ>  [<ffffffff810d32e2>] ? rcu_check_callback s+0x632/0x650
[<ffffffff81061bb8>] ? update_process_times+0x48/0x90
[<ffffffff810a2a4e>] ? tick_sched_timer+0x6e/0xe0
[<ffffffff81079c85>] ? __run_hrtimer+0x75/0x1a0
[<ffffffff810a29e0>] ? tick_setup_sched_timer+0x100/0x100
[<ffffffff8107a036>] ? hrtimer_interrupt+0xf6/0x250
[<ffffffff814f1379>] ? smp_apic_timer_interrupt+0x69/0x99
[<ffffffff814f034a>] ? apic_timer_interrupt+0x6a/0x70
<EOI>  [<ffffffff811082e3>] ? wait_on_page_bit+0x73/0x80
[<ffffffff814e7992>] ? _raw_spin_lock+0x22/0x30
[<ffffffff81131bf3>] ? handle_pte_fault+0x1b3/0xca0
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff8107a9a8>] ? up_read+0x18/0x30
[<ffffffff814eb2be>] ? do_page_fault+0x13e/0x460
[<ffffffff810137ba>] ? __switch_to+0x1aa/0x460
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff814e7de5>] ? page_fault+0x25/0x30
Quoted 2 lines

{ 3} (t=62998 jiffies)

Quoted 1 line

If you run a -tip kernel without the numa patches, does that work?

n/m, I found a total brain-fart in there.. does the below sort it?

---

kernel/sched/fair.c +1 -1
@@ -917,7 +917,7 @@ void task_numa_work(struct callback_head
 		t = p;
 		do {
 			sched_setnode(t, node);
-		} while ((t = next_thread(p)) != p);
+		} while ((t = next_thread(t)) != p);
 		rcu_read_unlock();
 	}
author
#7 lore raw
Quoted 38 lines · Peter Zijlstra
Quoted 27 lines · Peter Zijlstra
Quoted 22 lines · Srikar Dronamraju

This change worked well on the 2 node machine but on the 8 node machine it hangs with repeated messages

Pid: 60935, comm: numa01 Tainted: G W 3.5.0-numasched_v2_020812+ #4

Call Trace:
<IRQ>  [<ffffffff810d32e2>] ? rcu_check_callback s+0x632/0x650
[<ffffffff81061bb8>] ? update_process_times+0x48/0x90
[<ffffffff810a2a4e>] ? tick_sched_timer+0x6e/0xe0
[<ffffffff81079c85>] ? __run_hrtimer+0x75/0x1a0
[<ffffffff810a29e0>] ? tick_setup_sched_timer+0x100/0x100
[<ffffffff8107a036>] ? hrtimer_interrupt+0xf6/0x250
[<ffffffff814f1379>] ? smp_apic_timer_interrupt+0x69/0x99
[<ffffffff814f034a>] ? apic_timer_interrupt+0x6a/0x70
<EOI>  [<ffffffff811082e3>] ? wait_on_page_bit+0x73/0x80
[<ffffffff814e7992>] ? _raw_spin_lock+0x22/0x30
[<ffffffff81131bf3>] ? handle_pte_fault+0x1b3/0xca0
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff8107a9a8>] ? up_read+0x18/0x30
[<ffffffff814eb2be>] ? do_page_fault+0x13e/0x460
[<ffffffff810137ba>] ? __switch_to+0x1aa/0x460
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff814e7de5>] ? page_fault+0x25/0x30
Quoted 2 lines

{ 3} (t=62998 jiffies)

Quoted 1 line

If you run a -tip kernel without the numa patches, does that work?

n/m, I found a total brain-fart in there.. does the below sort it?

---

kernel/sched/fair.c void task_numa_work(struct callback_head · line 923

Quoted 8 lines
kernel/sched/fair.c +1 -1
@@ -917,7 +917,7 @@ void task_numa_work(struct callback_head
 		t = p;
 		do {
 			sched_setnode(t, node);
-		} while ((t = next_thread(p)) != p);
+		} while ((t = next_thread(t)) != p);
 		rcu_read_unlock();
 	}

I tried this fix, but doesnt seem to help.

will try on -tip and revert.

Signature · 2 lines
thanks and regards
srikar
author
#8 lore raw
In reply to Peter Zijlstra
Quoted 27 lines · Peter Zijlstra
Quoted 22 lines · Srikar Dronamraju

This change worked well on the 2 node machine but on the 8 node machine it hangs with repeated messages

Pid: 60935, comm: numa01 Tainted: G W 3.5.0-numasched_v2_020812+ #4

Call Trace:
<IRQ>  [<ffffffff810d32e2>] ? rcu_check_callback s+0x632/0x650
[<ffffffff81061bb8>] ? update_process_times+0x48/0x90
[<ffffffff810a2a4e>] ? tick_sched_timer+0x6e/0xe0
[<ffffffff81079c85>] ? __run_hrtimer+0x75/0x1a0
[<ffffffff810a29e0>] ? tick_setup_sched_timer+0x100/0x100
[<ffffffff8107a036>] ? hrtimer_interrupt+0xf6/0x250
[<ffffffff814f1379>] ? smp_apic_timer_interrupt+0x69/0x99
[<ffffffff814f034a>] ? apic_timer_interrupt+0x6a/0x70
<EOI>  [<ffffffff811082e3>] ? wait_on_page_bit+0x73/0x80
[<ffffffff814e7992>] ? _raw_spin_lock+0x22/0x30
[<ffffffff81131bf3>] ? handle_pte_fault+0x1b3/0xca0
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff8107a9a8>] ? up_read+0x18/0x30
[<ffffffff814eb2be>] ? do_page_fault+0x13e/0x460
[<ffffffff810137ba>] ? __switch_to+0x1aa/0x460
[<ffffffff814e64f7>] ? __schedule+0x2e7/0x710
[<ffffffff814e7de5>] ? page_fault+0x25/0x30
Quoted 2 lines

{ 3} (t=62998 jiffies)

Quoted 2 lines

If you run a -tip kernel without the numa patches, does that work?

Running on -tip kernel seems okay. Will see if I can bisect the patch that causes this issue and let you know.

Signature · 2 lines
Thanks and Regards
Srikar
#9 lore raw
In reply to Srikar Dronamraju
Quoted 11 lines · Srikar Dronamraju

Hi,

I saw this while I was running the 2nd August -tip kernel + Peter's numasched patches.

Top showed load average to be 240, there was one cpu (cpu 7) which showed 100% while all other cpus were idle. The system showed some sluggishness. Before I saw this I ran Andrea's autonuma benchmark couple of times.

I am not sure if this is an already reported issue/known issue.

So Ingo pushed a fix the other day that might address this:
http://git.linaro.org/gitweb?p=people/jstultz/linux.git;a=commitdiff_plain;h=1d17d17484d40f2d5b35c79518597a2b25296996

But do let me know any reproduction details if you can trigger this again. If you do trigger it again without that patch, watch to see if the time value from date is running much faster then it should.

thanks
-john

author
#10 lore raw
Quoted 6 lines · John Stultz
Quoted 5 lines · Srikar Dronamraju

Hi,

I saw this while I was running the 2nd August -tip kernel + Peter's numasched patches.

Quoted 8 lines
Quoted 6 lines

Top showed load average to be 240, there was one cpu (cpu 7) which showed 100% while all other cpus were idle. The system showed some sluggishness. Before I saw this I ran Andrea's autonuma benchmark couple of times.

I am not sure if this is an already reported issue/known issue.

So Ingo pushed a fix the other day that might address this:
http://git.linaro.org/gitweb?p=people/jstultz/linux.git;a=commitdiff_plain;h=1d17d17484d40f2d5b35c79518597a2b25296996

Okay, will update after applying the patch.

Quoted 5 lines

But do let me know any reproduction details if you can trigger this again. If you do trigger it again without that patch, watch to see if the time value from date is running much faster then it should.

The time value from date is normal

Signature · 2 lines
Thanks and Regards
Srikar