Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1671705 > unrolled thread
| Started by | Steven Rostedt <rostedt@goodmis.org> |
|---|---|
| First post | 2017-06-21 16:30 +0200 |
| Last post | 2017-06-21 20:10 +0200 |
| Articles | 2 — 2 participants |
Back to article view | Back to linux.kernel
This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by
below is the oldest one visible, not the original post.
Re: simple repro case Steven Rostedt <rostedt@goodmis.org> - 2017-06-21 16:30 +0200
Re: simple repro case Tejun Heo <tj@kernel.org> - 2017-06-21 20:10 +0200
| From | Steven Rostedt <rostedt@goodmis.org> |
|---|---|
| Date | 2017-06-21 16:30 +0200 |
| Subject | Re: simple repro case |
| Message-ID | <tUONQ-7dN-9@gated-at.bofh.it> |
On Sat, 17 Jun 2017 08:11:49 -0400
Tejun Heo <tj@kernel.org> wrote:
> Here's a simple rerpo. The test code runs whenever a CPU goes
> off/online. The test kthread is created on a different CPU and
> migrated to the target CPU while running. Without the previous patch
> applied, the kthread ends up running on the wrong CPU.
>
Hmm, I'm not able to trigger the warn_on, with this patch applied.
Adding a trace_printk("here!\n") just above the warn_on in
wq_worker_sleeping(), and doing the following:
# cd /sys/kernel/debug/tracing
# echo 1 > events/printk/console/enable
# echo 1 > events/sched/sched_migrate_task/enable
# echo 0 > /sys/devices/system/cpu/cpu2/online
# echo 1 > /sys/devices/system/cpu/cpu2/online
# cat trace
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [000] d.s4 744.572889: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=1 dest_cpu=0
kworker/0:2-406 [000] d..2 744.750944: wq_worker_sleeping: here
kworker/u8:3-111 [001] d..3 746.029980: sched_migrate_task: comm=bash pid=2390 prio=120 orig_cpu=1 dest_cpu=2
kworker/0:2-406 [000] d..2 746.798796: wq_worker_sleeping: here
<idle>-0 [001] d.s4 747.164692: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=0 dest_cpu=1
<idle>-0 [000] d.s4 747.632662: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=1 dest_cpu=0
kworker/0:2-406 [000] d..2 748.846646: wq_worker_sleeping: here
kworker/0:2-406 [000] d..2 750.894525: wq_worker_sleeping: here
<idle>-0 [002] d.s4 751.188404: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=0 dest_cpu=2
kworker/2:3-118 [002] d..2 751.194212: wq_worker_sleeping: here
cpuhp/2-20 [002] d..1 751.204894: console: [ 751.018261] TEST: cpu 2 inactive, starting on 0 and migrating (active/online=0-1,3/0-3)
test-2633 [000] d.s3 751.216796: sched_migrate_task: comm=systemd-journal pid=1839 prio=120 orig_cpu=0 dest_cpu=1
systemd-journal-1839 [001] d..4 751.216851: sched_migrate_task: comm=jbd2/dm-0-8 pid=1754 prio=120 orig_cpu=0 dest_cpu=3
cpuhp/2-20 [002] d..1 751.318375: console: [ 751.131745] TEST: test_last_cpu=0 cpus_allowed=0
cpuhp/2-20 [002] d..1 751.324249: console: [ 751.137621] TEST: migrating to inactve cpu 2
cpuhp/2-20 [002] d..1 751.438368: console: [ 751.251738] TEST: test_last_cpu=0 cpus_allowed=2
bash-2390 [000] d..1 751.445862: console: [ 751.259232] smpboot: CPU 2 is now offline
<idle>-0 [000] d.h5 751.452370: sched_migrate_task: comm=systemd-journal pid=1839 prio=120 orig_cpu=1 dest_cpu=0
<idle>-0 [000] dNs3 751.452392: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=2 dest_cpu=0
bash-2390 [000] d.s2 751.464359: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=0 dest_cpu=1
bash-2390 [000] d..2 751.466028: sched_migrate_task: comm=kworker/2:3 pid=118 prio=120 orig_cpu=2 dest_cpu=0
bash-2390 [000] d..4 751.466236: sched_migrate_task: comm=libvirtd pid=2197 prio=120 orig_cpu=2 dest_cpu=0
bash-2390 [000] d..3 751.466479: sched_migrate_task: comm=kworker/u8:5 pid=113 prio=120 orig_cpu=3 dest_cpu=1
kworker/u8:5-113 [001] d..3 751.466519: sched_migrate_task: comm=sshd pid=2389 prio=120 orig_cpu=0 dest_cpu=1
kworker/u8:5-113 [001] d..3 751.466593: sched_migrate_task: comm=sshd pid=2389 prio=120 orig_cpu=1 dest_cpu=0
systemd-udevd-2634 [001] d.s3 751.468358: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=1 dest_cpu=3
<idle>-0 [000] d.s4 751.472372: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=3 dest_cpu=0
systemd-journal-1839 [000] d..3 751.530744: sched_migrate_task: comm=in:imjournal pid=2152 prio=120 orig_cpu=2 dest_cpu=0
in:imjournal-2152 [000] d..2 751.530859: sched_migrate_task: comm=rs:main Q:Reg pid=2360 prio=120 orig_cpu=1 dest_cpu=3
in:imjournal-2152 [000] d.s3 751.531370: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=0 dest_cpu=1
sendmail-2334 [001] d.s3 752.169327: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=1 dest_cpu=3
kworker/0:2-406 [000] d..2 752.942348: wq_worker_sleeping: here
<idle>-0 [000] d.s3 753.582220: sched_migrate_task: comm=khugepaged pid=48 prio=139 orig_cpu=2 dest_cpu=0
<idle>-0 [000] d.s4 753.772209: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=3 dest_cpu=0
kworker/u8:5-113 [001] d..3 754.947065: sched_migrate_task: comm=sshd pid=2389 prio=120 orig_cpu=0 dest_cpu=3
bash-2390 [000] d.s3 754.956107: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=0 dest_cpu=1
bash-2390 [000] d..1 754.959938: console: [ 754.773306] smpboot: Booting Node 0 Processor 2 APIC 0x4
migration/1-15 [001] d..4 754.968577: sched_migrate_task: comm=bash pid=2390 prio=120 orig_cpu=0 dest_cpu=1
cpuhp/2-20 [002] d..1 754.970747: console: [ 754.784112] TEST: cpu 2 inactive, starting on 0 and migrating (active/online=0-1,3/0-3)
cpuhp/2-20 [002] d..2 754.981195: sched_migrate_task: comm=test pid=2635 prio=120 orig_cpu=3 dest_cpu=0
kworker/0:2-406 [000] d..2 754.990133: wq_worker_sleeping: here
cpuhp/2-20 [002] d..1 755.086101: console: [ 754.899471] TEST: test_last_cpu=0 cpus_allowed=0
cpuhp/2-20 [002] d..1 755.091957: console: [ 754.905328] TEST: migrating to inactve cpu 2
cpuhp/2-20 [002] d..3 755.097453: sched_migrate_task: comm=test pid=2635 prio=120 orig_cpu=0 dest_cpu=2
cpuhp/2-20 [002] d..1 755.206090: console: [ 755.019460] TEST: test_last_cpu=2 cpus_allowed=2
cpuhp/2-20 [002] dN.3 755.213683: sched_migrate_task: comm=kworker/2:3 pid=118 prio=120 orig_cpu=0 dest_cpu=2
cpuhp/2-20 [002] dN.3 755.216126: sched_migrate_task: comm=bash pid=2390 prio=120 orig_cpu=1 dest_cpu=0
kworker/2:3-118 [002] d..2 755.216143: wq_worker_sleeping: here
bash-2390 [000] d..3 755.216386: sched_migrate_task: comm=kworker/u8:5 pid=113 prio=120 orig_cpu=1 dest_cpu=2
kworker/u8:5-113 [002] d..3 755.216425: sched_migrate_task: comm=sshd pid=2389 prio=120 orig_cpu=3 dest_cpu=2
systemd-udevd-2636 [001] d.s4 755.217088: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=1 dest_cpu=2
systemd-udevd-2636 [001] d..4 755.217613: sched_migrate_task: comm=libvirtd pid=2197 prio=120 orig_cpu=0 dest_cpu=2
systemd-udevd-2637 [000] d..5 755.218850: sched_migrate_task: comm=systemd-udevd pid=1877 prio=120 orig_cpu=3 dest_cpu=0
systemd-udevd-1877 [000] d..7 755.220192: sched_migrate_task: comm=systemd-udevd pid=2637 prio=120 orig_cpu=0 dest_cpu=1
systemd-udevd-1877 [000] d..7 755.220212: sched_migrate_task: comm=systemd-udevd pid=2636 prio=120 orig_cpu=1 dest_cpu=2
<idle>-0 [000] d.s4 755.223118: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=2 dest_cpu=0
<idle>-0 [002] d.s4 755.225101: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=0 dest_cpu=2
systemd-journal-1839 [000] d..3 755.280473: sched_migrate_task: comm=in:imjournal pid=2152 prio=120 orig_cpu=0 dest_cpu=2
<idle>-0 [000] d.s8 755.722735: sched_migrate_task: comm=sshd pid=2389 prio=120 orig_cpu=2 dest_cpu=0
<idle>-0 [000] d.s4 756.334014: sched_migrate_task: comm=kworker/u8:5 pid=113 prio=120 orig_cpu=2 dest_cpu=0
sshd-2389 [000] d..3 756.350661: sched_migrate_task: comm=kworker/u8:5 pid=113 prio=120 orig_cpu=0 dest_cpu=1
<idle>-0 [000] d.s4 756.831984: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=2 dest_cpu=0
<idle>-0 [001] d.s3 756.845975: sched_migrate_task: comm=jbd2/dm-0-8 pid=1754 prio=120 orig_cpu=3 dest_cpu=1
bash-2390 [000] d.s3 756.846974: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=0 dest_cpu=1
<idle>-0 [000] d.s5 756.875008: sched_migrate_task: comm=jbd2/dm-0-8 pid=1754 prio=120 orig_cpu=1 dest_cpu=0
kworker/0:2-406 [000] d..2 757.038044: wq_worker_sleeping: here
kworker/u8:5-113 [001] d..3 758.142638: sched_migrate_task: comm=sshd pid=2389 prio=120 orig_cpu=0 dest_cpu=2
bash-2645 [001] dNs4 758.143899: sched_migrate_task: comm=rcu_sched pid=8 prio=120 orig_cpu=1 dest_cpu=2
Only the kworker/0:2-406 and kworker/2:3-113 ran the warnon path, and
was fine.
-- Steve
[toc] | [next] | [standalone]
| From | Tejun Heo <tj@kernel.org> |
|---|---|
| Date | 2017-06-21 20:10 +0200 |
| Message-ID | <tUSeL-1fP-49@gated-at.bofh.it> |
| In reply to | #1671705 |
Hello, Steven.
On Wed, Jun 21, 2017 at 10:24:57AM -0400, Steven Rostedt wrote:
> On Sat, 17 Jun 2017 08:11:49 -0400
> Tejun Heo <tj@kernel.org> wrote:
>
> > Here's a simple rerpo. The test code runs whenever a CPU goes
> > off/online. The test kthread is created on a different CPU and
> > migrated to the target CPU while running. Without the previous patch
> > applied, the kthread ends up running on the wrong CPU.
> >
>
> Hmm, I'm not able to trigger the warn_on, with this patch applied.
>
> Adding a trace_printk("here!\n") just above the warn_on in
> wq_worker_sleeping(), and doing the following:
>
> cpuhp/2-20 [002] d..1 751.204894: console: [ 751.018261] TEST: cpu 2 inactive, starting on 0 and migrating (active/online=0-1,3/0-3)
> cpuhp/2-20 [002] d..1 751.318375: console: [ 751.131745] TEST: test_last_cpu=0 cpus_allowed=0
> cpuhp/2-20 [002] d..1 751.324249: console: [ 751.137621] TEST: migrating to inactve cpu 2
> cpuhp/2-20 [002] d..1 751.438368: console: [ 751.251738] TEST: test_last_cpu=0 cpus_allowed=2
Ah, sorry about not being clear. The repro is that test_last_cpu
isn't 2 on the last line. It created a kthread on CPU 0 and tried to
migrate that to an online but inactive CPU 2 but the kthread couldn't
get on that CPU because the migration code disallowed the kthread from
moving to an inactive CPU.
The same problem affects workqueue rescuer. It tries to migrate to an
inactive CPU to service the workqueue there but silently fails to and
then ends up running the work item on the wrong CPU.
Thanks.
--
tejun
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web