From: "Paul E. McKenney" <paulmck@linux.ibm.com>
To: Peter Zijlstra <peterz@infradead.org>
Cc: rcu@vger.kernel.org, linux-kernel@vger.kernel.org,
mingo@kernel.org, jiangshanlai@gmail.com, dipankar@in.ibm.com,
akpm@linux-foundation.org, mathieu.desnoyers@efficios.com,
josh@joshtriplett.org, tglx@linutronix.de, rostedt@goodmis.org,
dhowells@redhat.com, edumazet@google.com, fweisbec@gmail.com,
oleg@redhat.com, joel@joelfernandes.org
Subject: Re: [PATCH RFC tip/core/rcu 14/14] rcu/nohz: Make multi_cpu_stop() enable tick on all online CPUs
Date: Wed, 7 Aug 2019 14:41:31 -0700 [thread overview]
Message-ID: <20190807214131.GA15124@linux.ibm.com> (raw)
In-Reply-To: <20190806180824.GA28448@linux.ibm.com>
On Tue, Aug 06, 2019 at 11:08:24AM -0700, Paul E. McKenney wrote:
> On Mon, Aug 05, 2019 at 10:48:00AM -0700, Paul E. McKenney wrote:
> > On Mon, Aug 05, 2019 at 05:50:24PM +0200, Peter Zijlstra wrote:
> > > On Mon, Aug 05, 2019 at 07:54:48AM -0700, Paul E. McKenney wrote:
> > >
> > > > > Right; so clearly we're not understanding what's happening. That seems
> > > > > like a requirement for actually doing a patch.
> > > >
> > > > Almost but not quite. It is a requirement for a patch *that* *is*
> > > > *supposed* *to* *be* *a* *fix*. If you are trying to prohibit me from
> > > > writing experimental patches, please feel free to take a long walk on
> > > > a short pier.
> > > >
> > > > Understood???
> > >
> > > Ah, my bad, I thought you were actually proposing this as an actual
> > > patch. I now see that is my bad, I'd overlooked the RFC part.
> >
> > No problem!
> >
> > And of course adding tracing decreases the frequency and duration of
> > the multi_cpu_stop(). Re-running with shorter-duration triggering. ;-)
>
> And I did eventually get a good trace. If I am interpreting this trace
> correctly, the torture_-135 task didn't get around to attempting to wake
> up all of the CPUs. I will try again, but this time with the sched_switch
> trace event enabled.
>
> As a side note, enabling ftrace from the command line seems to interact
> badly with turning tracing off and on in the kernel, so I eventually
> resorted to trace_printk() in the functions of interest. The trace
> output is below, followed by the current diagnostic patch. Please note
> that I am -not- using the desperation hammer-the-scheduler patches.
>
> More as I learn more!
And of course I forgot to dump out the online CPUs, so I really had no
idea whether or not all the CPUs were accounted for. I added tracing
to dump out the online CPUs at the beginning of __stop_cpus() and then
reworked it a few times to get the problem to happen in reasonable time.
Please see below for the resulting annotated trace.
I was primed to expect a lost IPI, perhaps due to yet another qemu bug,
but all the migration threads are running within about 2 milliseconds.
It is then almost two minutes(!) until the next trace message.
Looks like time to (very carefully!) instrument multi_cpu_stop().
Of course, if you have any ideas, please do not keep them a secret!
Thanx, Paul
------------------------------------------------------------------------
This trace is taken after an RCU CPU stall warning following the start
of CPU 4 going offline:
[ 2579.977765] Unregister pv shared memory for cpu 4
Here is the trace, trimming out the part from earlier CPU-hotplug operations:
[ 2813.040289] torture_-135 0.... 2578022804us : __stop_cpus: CPUs 0-7 online
All eight CPUs are online.
[ 2813.040289] torture_-135 0.... 2578022805us : queue_stop_cpus_work: entered
[ 2813.040289] torture_-135 0.... 2578022805us : cpu_stop_queue_work: entered for CPU 0
[ 2813.040289] torture_-135 0.... 2578022806us : wake_up_q: entered
[ 2813.040289] torture_-135 0.... 2578022806us : wake_up_process: entered
[ 2813.040289] torture_-135 0.... 2578022806us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0d... 2578022806us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0d... 2578022807us : ttwu_do_activate.isra.108: entered
[ 2813.040289] torture_-135 0d... 2578022807us : activate_task: entered
[ 2813.040289] torture_-135 0d... 2578022807us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] torture_-135 0d... 2578022807us : check_preempt_curr: entered
[ 2813.040289] torture_-135 0d... 2578022807us : resched_curr: entered
[ 2813.040289] torture_-135 0.N.. 2578022808us : cpu_stop_queue_work: entered for CPU 1
[ 2813.040289] torture_-135 0.N.. 2578022809us : wake_up_q: entered
[ 2813.040289] torture_-135 0.N.. 2578022809us : wake_up_process: entered
[ 2813.040289] torture_-135 0.N.. 2578022809us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022809us : try_to_wake_up: entered
Note: trace_printk() is confused by inlining.
[ 2813.040289] torture_-135 0dN.. 2578022810us : try_to_wake_up: entered, CPU 1
So the above is really ttwu_queue_remote().
We are running on CPU 0, so presumably don't need to IPI it.
We have IPIed CPU 1.
[ 2813.040289] torture_-135 0.N.. 2578022819us : cpu_stop_queue_work: entered for CPU 2
[ 2813.040289] torture_-135 0.N.. 2578022820us : wake_up_q: entered
[ 2813.040289] torture_-135 0.N.. 2578022820us : wake_up_process: entered
[ 2813.040289] torture_-135 0.N.. 2578022820us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022820us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022821us : try_to_wake_up: entered, CPU 2
We have IPIed CPUs 1-2.
[ 2813.040289] rcu_tort-129 1d... 2578022821us : scheduler_ipi: entered
CPU 1 got its IPI, so CPUs 1-2 IPIed and CPU 1 received IPI.
[ 2813.040289] rcu_tort-129 1d.h. 2578022821us : sched_ttwu_pending: entered
[ 2813.040289] rcu_tort-129 1d.h. 2578022821us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] rcu_tort-129 1d.h. 2578022821us : ttwu_do_activate.isra.108: entered
[ 2813.040289] rcu_tort-129 1d.h. 2578022821us : activate_task: entered
[ 2813.040289] rcu_tort-129 1d.h. 2578022821us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] rcu_tort-129 1d.h. 2578022821us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-129 1d.h. 2578022821us : resched_curr: entered
[ 2813.040289] rcu_tort-129 1d... 2578022821us : sched_switch: prev_comm=rcu_torture_rea prev_pid=129 prev_prio=139 prev_state=R+ ==> next_comm=migration/1 next_pid=14 next_prio=0
CPU 1 has switched to its migration kthread.
[ 2813.040289] torture_-135 0.N.. 2578022830us : cpu_stop_queue_work: entered for CPU 3
[ 2813.040289] torture_-135 0.N.. 2578022831us : wake_up_q: entered
[ 2813.040289] torture_-135 0.N.. 2578022831us : wake_up_process: entered
[ 2813.040289] torture_-135 0.N.. 2578022831us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022831us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022832us : try_to_wake_up: entered, CPU 3
We have IPIed CPUs 1-3.
[ 2813.040289] rcu_tort-126 2d... 2578022832us : scheduler_ipi: entered
CPU 2 got its IPI, so CPUs 1-3 IPIed and CPUs 1-2 received IPI.
[ 2813.040289] rcu_tort-126 2d.h. 2578022832us : sched_ttwu_pending: entered
[ 2813.040289] rcu_tort-126 2d.h. 2578022832us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] rcu_tort-126 2d.h. 2578022832us : ttwu_do_activate.isra.108: entered
[ 2813.040289] rcu_tort-126 2d.h. 2578022832us : activate_task: entered
[ 2813.040289] rcu_tort-126 2d.h. 2578022832us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] rcu_tort-126 2d.h. 2578022832us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-126 2d.h. 2578022832us : resched_curr: entered
[ 2813.040289] torture_-135 0.N.. 2578022841us : cpu_stop_queue_work: entered for CPU 4
[ 2813.040289] torture_-135 0.N.. 2578022841us : wake_up_q: entered
[ 2813.040289] torture_-135 0.N.. 2578022841us : wake_up_process: entered
[ 2813.040289] torture_-135 0.N.. 2578022841us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022842us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022842us : try_to_wake_up: entered, CPU 4
We have IPIed CPUs 1-4.
[ 2813.040289] rcu_tort-128 3d... 2578022842us : scheduler_ipi: entered
CPU 3 got its IPI, so CPUs 1-4 IPIed and CPUs 1-3 received IPI.
[ 2813.040289] rcu_tort-128 3d.h. 2578022842us : sched_ttwu_pending: entered
[ 2813.040289] rcu_tort-128 3d.h. 2578022842us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] rcu_tort-128 3d.h. 2578022842us : ttwu_do_activate.isra.108: entered
[ 2813.040289] rcu_tort-128 3d.h. 2578022842us : activate_task: entered
[ 2813.040289] rcu_tort-128 3d.h. 2578022842us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] rcu_tort-128 3d.h. 2578022842us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-128 3d.h. 2578022842us : resched_curr: entered
[ 2813.040289] torture_-135 0.N.. 2578022853us : cpu_stop_queue_work: entered for CPU 5
[ 2813.040289] torture_-135 0.N.. 2578022853us : wake_up_q: entered
[ 2813.040289] torture_-135 0.N.. 2578022853us : wake_up_process: entered
[ 2813.040289] torture_-135 0.N.. 2578022854us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022854us : try_to_wake_up: entered
[ 2813.040289] torture_-135 0dN.. 2578022856us : try_to_wake_up: entered, CPU 5
We have IPIed CPUs 1-5.
[ 2813.040289] <idle>-0 4d... 2578022863us : scheduler_ipi: entered
CPU 4 got its IPI, so CPUs 1-5 IPIed and CPUs 1-4 received IPI.
[ 2813.040289] <idle>-0 4d.h. 2578022865us : sched_ttwu_pending: entered
[ 2813.040289] <idle>-0 4d.h. 2578022865us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] <idle>-0 4d.h. 2578022866us : ttwu_do_activate.isra.108: entered
[ 2813.040289] <idle>-0 4d.h. 2578022866us : activate_task: entered
[ 2813.040289] <idle>-0 4d.h. 2578022867us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] rcu_tort-126 2d... 2578022867us : sched_switch: prev_comm=rcu_torture_rea prev_pid=126 prev_prio=139 prev_state=R+ ==> next_comm=migration/2 next_pid=21 next_prio=0
CPUs 1-2 have switched to their migration kthreads.
[ 2813.040289] <idle>-0 4d.h. 2578022868us : check_preempt_curr: entered
[ 2813.040289] <idle>-0 4d.h. 2578022868us : resched_curr: entered
[ 2813.040289] torture_-135 0.N.. 2578022872us : cpu_stop_queue_work: entered for CPU 6
[ 2813.040289] torture_-135 0.N.. 2578022873us : wake_up_q: entered
[ 2813.040289] torture_-135 0.N.. 2578022873us : wake_up_process: entered
[ 2813.040289] torture_-135 0.N.. 2578022874us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-125 5d... 2578022874us : scheduler_ipi: entered
CPU 5 got its IPI, so CPUs 1-5 IPIed and CPUs 1-5 received IPI.
[ 2813.040289] rcu_tort-125 5d.h. 2578022874us : sched_ttwu_pending: entered
[ 2813.040289] rcu_tort-125 5d.h. 2578022875us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] rcu_tort-125 5d.h. 2578022875us : ttwu_do_activate.isra.108: entered
[ 2813.040289] rcu_tort-125 5d.h. 2578022875us : activate_task: entered
[ 2813.040289] rcu_tort-125 5d.h. 2578022877us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] rcu_tort-125 5d.h. 2578022877us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-125 5d.h. 2578022877us : resched_curr: entered
[ 2813.040289] rcu_tort-128 3d... 2578022877us : sched_switch: prev_comm=rcu_torture_rea prev_pid=128 prev_prio=139 prev_state=R+ ==> next_comm=migration/3 next_pid=27 next_prio=0
CPUs 1-3 have switched to their migration kthreads.
[ 2813.040289] <idle>-0 4.N.. 2578022912us : sched_ttwu_pending: entered
[ 2813.040289] torture_-135 0dN.. 2578022914us : try_to_wake_up: entered
[ 2813.040289] <idle>-0 4d... 2578022914us : sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=migration/4 next_pid=33 next_prio=0
CPUs 1-4 have switched to their migration kthreads.
[ 2813.040289] torture_-135 0dN.. 2578022915us : try_to_wake_up: entered, CPU 6
We have IPIed CPUs 1-6.
[ 2813.040289] rcu_tort-125 5d... 2578022926us : sched_switch: prev_comm=rcu_torture_rea prev_pid=125 prev_prio=139 prev_state=R+ ==> next_comm=migration/5 next_pid=40 next_prio=0
CPUs 1-5 have switched to their migration kthreads.
[ 2813.040289] rcu_tort-136 6d... 2578022926us : scheduler_ipi: entered
CPU 6 got its IPI, so CPUs 1-6 IPIed and CPUs 1-6 received IPI.
[ 2813.040289] torture_-135 0.N.. 2578022929us : cpu_stop_queue_work: entered for CPU 7
[ 2813.040289] torture_-135 0.N.. 2578022930us : wake_up_q: entered
[ 2813.040289] torture_-135 0.N.. 2578022930us : wake_up_process: entered
[ 2813.040289] torture_-135 0.N.. 2578022930us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-136 6d.h. 2578022930us : sched_ttwu_pending: entered
[ 2813.040289] torture_-135 0dN.. 2578022930us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-136 6d.h. 2578022930us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] rcu_tort-136 6d.h. 2578022930us : ttwu_do_activate.isra.108: entered
[ 2813.040289] torture_-135 0dN.. 2578022931us : try_to_wake_up: entered, CPU 7
We have IPIed CPUs 1-7.
[ 2813.040289] rcu_tort-136 6d.h. 2578022931us : activate_task: entered
[ 2813.040289] rcu_tort-136 6d.h. 2578022931us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] rcu_tort-136 6d.h. 2578022931us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-136 6d.h. 2578022931us : resched_curr: entered
[ 2813.040289] torture_-135 0d... 2578022951us : sched_switch: prev_comm=torture_onoff prev_pid=135 prev_prio=120 prev_state=D ==> next_comm=migration/0 next_pid=11 next_prio=0
CPUs 0-5 have switched to their migration kthreads.
[ 2813.040289] rcu_tort-136 6d... 2578022951us : sched_switch: prev_comm=rcu_torture_fwd prev_pid=136 prev_prio=139 prev_state=R+ ==> next_comm=migration/6 next_pid=46 next_prio=0
CPUs 0-6 have switched to their migration kthreads.
[ 2813.040289] migratio-46 6d.s1 2578023060us : wake_up_process: entered
[ 2813.040289] migratio-46 6d.s1 2578023060us : try_to_wake_up: entered
[ 2813.040289] migratio-46 6d.s1 2578023060us : try_to_wake_up: entered
[ 2813.040289] migratio-46 6d.s1 2578023061us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-46 6d.s1 2578023061us : activate_task: entered
[ 2813.040289] migratio-46 6d.s1 2578023062us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-46 6d.s1 2578023062us : check_preempt_curr: entered
[ 2813.040289] <idle>-0 7d... 2578023758us : scheduler_ipi: entered
CPU 7 got its IPI, so CPUs 1-7 IPIed and CPUs 1-7 received IPI.
[ 2813.040289] <idle>-0 7d.h. 2578025037us : sched_ttwu_pending: entered
[ 2813.040289] <idle>-0 7d.h. 2578025038us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] <idle>-0 7d.h. 2578025038us : ttwu_do_activate.isra.108: entered
[ 2813.040289] <idle>-0 7d.h. 2578025038us : activate_task: entered
[ 2813.040289] <idle>-0 7d.h. 2578025043us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] <idle>-0 7d.h. 2578025043us : check_preempt_curr: entered
[ 2813.040289] <idle>-0 7d.h. 2578025043us : resched_curr: entered
[ 2813.040289] <idle>-0 7.N.. 2578025107us : sched_ttwu_pending: entered
[ 2813.040289] <idle>-0 7d... 2578025132us : sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=migration/7 next_pid=52 next_prio=0
CPUs 0-7 have all switched to their migration kthreads. So we
should be done, but we clearly are not. Almost two minutes later:
[ 2813.040289] migratio-33 4d..1 2689243033us : sched_ttwu_pending: entered
[ 2813.040289] migratio-11 0d.h1 2689243195us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.h1 2689243196us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.h1 2689243198us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.h1 2689243201us : try_to_wake_up: entered, CPU 5
[ 2813.040289] migratio-40 5d... 2689243204us : sched_switch: prev_comm=migration/5 prev_pid=40 prev_prio=0 prev_state=S ==> next_comm=rcu_torture_rea next_pid=125 next_prio=139
CPU 5 switches from its migration kthread.
[ 2813.040289] migratio-46 6d... 2689243222us : sched_switch: prev_comm=migration/6 prev_pid=46 prev_prio=0 prev_state=S ==> next_comm=kworker/6:1 next_pid=175 next_prio=120
CPU 6 switches from its migration kthread.
[ 2813.040289] migratio-21 2d.s1 2689243222us : activate_task: entered
[ 2813.040289] migratio-21 2d.s1 2689243225us : check_preempt_curr: entered
[ 2813.040289] migratio-27 3d.s1 2689243226us : activate_task: entered
[ 2813.040289] rcu_tort-125 5d... 2689243227us : scheduler_ipi: entered
[ 2813.040289] rcu_tort-125 5d.h. 2689243228us : sched_ttwu_pending: entered
[ 2813.040289] migratio-27 3d.s1 2689243228us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-125 5d.h. 2689243228us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] migratio-27 3d.s1 2689243229us : activate_task: entered
[ 2813.040289] rcu_tort-125 5d.h. 2689243229us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-11 0..s1 2689243229us : wake_up_process: entered
[ 2813.040289] rcu_tort-125 5d.h. 2689243229us : activate_task: entered
[ 2813.040289] migratio-27 3d.s1 2689243229us : check_preempt_curr: entered
[ 2813.040289] migratio-11 0..s1 2689243229us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243230us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243231us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-11 0d.s1 2689243231us : activate_task: entered
[ 2813.040289] migratio-21 2d... 2689243232us : sched_switch: prev_comm=migration/2 prev_pid=21 prev_prio=0 prev_state=S ==> next_comm=rcu_torture_rea next_pid=126 next_prio=139
CPU 2 switches from its migration kthread.
[ 2813.040289] migratio-11 0d.s1 2689243232us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] rcu_tort-125 5d.h. 2689243232us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-11 0d.s1 2689243232us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-125 5d.h. 2689243232us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-125 5d.h. 2689243233us : resched_curr: entered
[ 2813.040289] migratio-11 0..s1 2689243234us : wake_up_process: entered
[ 2813.040289] migratio-11 0..s1 2689243234us : try_to_wake_up: entered
[ 2813.040289] migratio-27 3d... 2689243234us : sched_switch: prev_comm=migration/3 prev_pid=27 prev_prio=0 prev_state=S ==> next_comm=rcu_torture_fak next_pid=122 next_prio=139
CPU 3 switches from its migration kthread.
[ 2813.040289] migratio-11 0d.s1 2689243235us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243235us : ttwu_do_activate.isra.108: entered
[ 2813.040289] kworker/-175 6d... 2689243235us : sched_switch: prev_comm=kworker/6:1 prev_pid=175 prev_prio=120 prev_state=I ==> next_comm=rcu_torture_fwd next_pid=136 next_prio=139
CPU 6 switches yet again.
[ 2813.040289] migratio-11 0d.s1 2689243235us : activate_task: entered
[ 2813.040289] migratio-11 0d.s1 2689243236us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-11 0d.s1 2689243237us : check_preempt_curr: entered
[ 2813.040289] migratio-11 0d.s1 2689243239us : wake_up_process: entered
[ 2813.040289] rcu_tort-126 2d... 2689243240us : sched_switch: prev_comm=rcu_torture_rea prev_pid=126 prev_prio=139 prev_state=S ==> next_comm=rcu_torture_rea next_pid=124 next_prio=139
CPU 2 switches yet again.
[ 2813.040289] migratio-11 0d.s1 2689243240us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243240us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243240us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-11 0d.s1 2689243240us : activate_task: entered
[ 2813.040289] migratio-11 0d.s1 2689243241us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-11 0d.s1 2689243241us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-125 5d... 2689243242us : sched_switch: prev_comm=rcu_torture_rea prev_pid=125 prev_prio=139 prev_state=S ==> next_comm=init next_pid=1 next_prio=120
CPU 5 switches yet again.
[ 2813.040289] migratio-11 0d.s1 2689243242us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243243us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243243us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243243us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243244us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243244us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-124 2d... 2689243244us : sched_switch: prev_comm=rcu_torture_rea prev_pid=124 prev_prio=139 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
CPU 2 switches yet again.
[ 2813.040289] migratio-11 0d.s1 2689243245us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243245us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243245us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243246us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243246us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243246us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0..s1 2689243247us : wake_up_process: entered
[ 2813.040289] migratio-11 0..s1 2689243247us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243248us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243248us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-11 0d.s1 2689243249us : activate_task: entered
[ 2813.040289] migratio-11 0d.s1 2689243249us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-11 0d.s1 2689243249us : check_preempt_curr: entered
[ 2813.040289] migratio-11 0d.s1 2689243251us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243251us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243251us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243252us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-11 0d.s1 2689243252us : activate_task: entered
[ 2813.040289] migratio-11 0d.s1 2689243252us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-11 0d.s1 2689243253us : check_preempt_curr: entered
[ 2813.040289] migratio-11 0d.s1 2689243263us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243263us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243264us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243264us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0..s1 2689243265us : wake_up_process: entered
[ 2813.040289] migratio-11 0..s1 2689243265us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243266us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243266us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-11 0d.s1 2689243266us : activate_task: entered
[ 2813.040289] migratio-11 0d.s1 2689243268us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-11 0d.s1 2689243268us : check_preempt_curr: entered
[ 2813.040289] migratio-11 0..s1 2689243269us : wake_up_process: entered
[ 2813.040289] migratio-11 0..s1 2689243269us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243270us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243270us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-11 0d.s1 2689243270us : activate_task: entered
[ 2813.040289] migratio-11 0d.s1 2689243271us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-11 0d.s1 2689243272us : check_preempt_curr: entered
[ 2813.040289] migratio-52 7d... 2689243291us : sched_switch: prev_comm=migration/7 prev_pid=52 prev_prio=0 prev_state=S ==> next_comm=swapper/7 next_pid=0 next_prio=120
CPU 7 switches from its migration kthread.
[ 2813.040289] migratio-11 0d.s1 2689243315us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243315us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243316us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243316us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243316us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243317us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d.s1 2689243317us : wake_up_process: entered
[ 2813.040289] migratio-11 0d.s1 2689243318us : try_to_wake_up: entered
[ 2813.040289] migratio-11 0d... 2689243323us : sched_switch: prev_comm=migration/0 prev_pid=11 prev_prio=0 prev_state=S ==> next_comm=kworker/0:3 next_pid=171 next_prio=120
CPU 0 switches from its migration kthread.
[ 2813.040289] kworker/-171 0d... 2689243327us : try_to_wake_up: entered
[ 2813.040289] kworker/-171 0d... 2689243327us : try_to_wake_up: entered
[ 2813.040289] kworker/-171 0d... 2689243328us : try_to_wake_up: entered, CPU 5
[ 2813.040289] init-1 5d... 2689243343us : scheduler_ipi: entered
[ 2813.040289] init-1 5d.h. 2689243344us : sched_ttwu_pending: entered
[ 2813.040289] init-1 5d.h. 2689243344us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] init-1 5d.h. 2689243351us : ttwu_do_activate.isra.108: entered
[ 2813.040289] init-1 5d.h. 2689243351us : activate_task: entered
[ 2813.040289] init-1 5d.h. 2689243353us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] init-1 5d.h. 2689243353us : check_preempt_curr: entered
[ 2813.040289] kworker/-171 0d... 2689243362us : sched_switch: prev_comm=kworker/0:3 prev_pid=171 prev_prio=120 prev_state=I ==> next_comm=rcu_sched next_pid=10 next_prio=120
CPU 0 switches again.
[ 2813.040289] rcu_sche-10 0d... 2689243365us : try_to_wake_up: entered
[ 2813.040289] rcu_sche-10 0d... 2689243366us : try_to_wake_up: entered
[ 2813.040289] rcu_sche-10 0d... 2689243366us : try_to_wake_up: entered, CPU 5
[ 2813.040289] rcu_sche-10 0d... 2689243379us : sched_switch: prev_comm=rcu_sched prev_pid=10 prev_prio=120 prev_state=I ==> next_comm=rcu_torture_fak next_pid=123 next_prio=139
CPU 0 switches again.
[ 2813.040289] init-1 5d... 2689243380us : scheduler_ipi: entered
[ 2813.040289] init-1 5d.h. 2689243380us : sched_ttwu_pending: entered
[ 2813.040289] init-1 5d.h. 2689243380us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] init-1 5d.h. 2689243380us : ttwu_do_activate.isra.108: entered
[ 2813.040289] init-1 5d.h. 2689243381us : activate_task: entered
[ 2813.040289] init-1 5d.h. 2689243382us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] init-1 5d.h. 2689243382us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-123 0d... 2689243509us : sched_switch: prev_comm=rcu_torture_fak prev_pid=123 prev_prio=139 prev_state=D ==> next_comm=kworker/u16:0 next_pid=181 next_prio=120
CPU 0 switches again.
[ 2813.040289] kworker/-181 0d... 2689243510us : wake_up_process: entered
[ 2813.040289] kworker/-181 0d... 2689243510us : try_to_wake_up: entered
[ 2813.040289] kworker/-181 0d... 2689243510us : try_to_wake_up: entered
[ 2813.040289] kworker/-181 0d... 2689243511us : ttwu_do_activate.isra.108: entered
[ 2813.040289] kworker/-181 0d... 2689243511us : activate_task: entered
[ 2813.040289] kworker/-181 0d... 2689243512us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] kworker/-181 0d... 2689243512us : check_preempt_curr: entered
[ 2813.040289] kworker/-181 0d... 2689243513us : wake_up_process: entered
[ 2813.040289] kworker/-181 0d... 2689243513us : try_to_wake_up: entered
[ 2813.040289] kworker/-181 0d... 2689243513us : wake_up_process: entered
[ 2813.040289] kworker/-181 0d... 2689243513us : try_to_wake_up: entered
[ 2813.040289] kworker/-181 0d... 2689243514us : wake_up_process: entered
[ 2813.040289] kworker/-181 0d... 2689243514us : try_to_wake_up: entered
[ 2813.040289] kworker/-181 0d... 2689243514us : wake_up_process: entered
[ 2813.040289] kworker/-181 0d... 2689243514us : try_to_wake_up: entered
[ 2813.040289] kworker/-181 0d... 2689243515us : wake_up_process: entered
[ 2813.040289] kworker/-181 0d... 2689243515us : try_to_wake_up: entered
[ 2813.040289] kworker/-181 0d... 2689243516us : sched_switch: prev_comm=kworker/u16:0 prev_pid=181 prev_prio=120 prev_state=I ==> next_comm=torture_shuffle next_pid=132 next_prio=120
CPU 0 switches again.
[ 2813.040289] torture_-132 0.... 2689243518us : wake_up_q: entered
[ 2813.040289] torture_-132 0d... 2689243519us : sched_switch: prev_comm=torture_shuffle prev_pid=132 prev_prio=120 prev_state=D ==> next_comm=kworker/0:1 next_pid=183 next_prio=120
CPU 0 switches again.
[ 2813.040289] kworker/-183 0d... 2689243521us : sched_switch: prev_comm=kworker/0:1 prev_pid=183 prev_prio=120 prev_state=I ==> next_comm=rcu_torture_sta next_pid=131 next_prio=120
CPU 0 switches again.
[ 2813.040289] rcu_tort-131 0d... 2689243559us : sched_switch: prev_comm=rcu_torture_sta prev_pid=131 prev_prio=120 prev_state=S ==> next_comm=torture_stutter next_pid=133 next_prio=120
CPU 0 switches again.
[ 2813.040289] torture_-133 0d... 2689243561us : sched_switch: prev_comm=torture_stutter prev_pid=133 prev_prio=120 prev_state=S ==> next_comm=kworker/u16:4 next_pid=161 next_prio=120
[ 2813.040289] kworker/-161 0d... 2689243566us : activate_task: entered
[ 2813.040289] kworker/-161 0d... 2689243567us : check_preempt_curr: entered
[ 2813.040289] kworker/-161 0d... 2689243568us : sched_switch: prev_comm=kworker/u16:4 prev_pid=161 prev_prio=120 prev_state=I ==> next_comm=rcu_torture_rea next_pid=130 next_prio=139
CPU 0 switches again.
[ 2813.040289] rcu_tort-130 0d... 2689243571us : activate_task: entered
[ 2813.040289] rcu_tort-130 0d... 2689243572us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-130 0d... 2689243572us : activate_task: entered
[ 2813.040289] rcu_tort-130 0d... 2689243572us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-130 0d... 2689243573us : sched_switch: prev_comm=rcu_torture_rea prev_pid=130 prev_prio=139 prev_state=S ==> next_comm=rcu_torture_rea next_pid=127 next_prio=139
CPU 0 switches again.
[ 2813.040289] rcu_tort-127 0d... 2689243585us : sched_switch: prev_comm=rcu_torture_rea prev_pid=127 prev_prio=139 prev_state=S ==> next_comm=rcu_torture_rea next_pid=128 next_prio=139
CPU 0 switches again.
[ 2813.040289] rcu_tort-128 0d... 2689243588us : activate_task: entered
[ 2813.040289] rcu_tort-128 0d... 2689243588us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-128 0d... 2689243588us : sched_switch: prev_comm=rcu_torture_rea prev_pid=128 prev_prio=139 prev_state=S ==> next_comm=rcu_torture_rea next_pid=129 next_prio=139
CPU 0 switches again.
[ 2813.040289] rcu_tort-129 0d... 2689243591us : sched_switch: prev_comm=rcu_torture_rea prev_pid=129 prev_prio=139 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
CPU 0 switches again.
[ 2813.040289] rcu_tort-122 3.... 2689243707us : wake_up_process: entered
[ 2813.040289] rcu_tort-122 3.... 2689243707us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-122 3d... 2689243711us : sched_switch: prev_comm=rcu_torture_fak prev_pid=122 prev_prio=139 prev_state=D ==> next_comm=swapper/3 next_pid=0 next_prio=120
CPU 3 switches again.
[ 2813.040289] <idle>-0 0d... 2689244073us : wake_up_process: entered
[ 2813.040289] <idle>-0 0d... 2689244074us : try_to_wake_up: entered
[ 2813.040289] <idle>-0 0d... 2689244074us : try_to_wake_up: entered
[ 2813.040289] <idle>-0 0d... 2689244074us : ttwu_do_activate.isra.108: entered
[ 2813.040289] <idle>-0 0d... 2689244075us : activate_task: entered
[ 2813.040289] <idle>-0 0d... 2689244076us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] <idle>-0 0d... 2689244076us : check_preempt_curr: entered
[ 2813.040289] <idle>-0 0d... 2689244076us : resched_curr: entered
[ 2813.040289] <idle>-0 0.N.. 2689244087us : sched_ttwu_pending: entered
[ 2813.040289] <idle>-0 0d... 2689244088us : sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/0 next_pid=9 next_prio=120
CPU 0 switches again.
[ 2813.040289] init-1 5d... 2689244336us : sched_switch: prev_comm=init prev_pid=1 prev_prio=120 prev_state=S ==> next_comm=rcu_torture_fak next_pid=120 next_prio=139
CPU 5 switches again.
[ 2813.040289] rcu_tort-120 5.... 2689244344us : wake_up_q: entered
[ 2813.040289] rcu_tort-120 5.... 2689244344us : wake_up_process: entered
[ 2813.040289] rcu_tort-120 5.... 2689244344us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-120 5d... 2689244345us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-120 5d... 2689244346us : try_to_wake_up: entered, CPU 0
[ 2813.040289] rcu_tort-120 5d... 2689244359us : sched_switch: prev_comm=rcu_torture_fak prev_pid=120 prev_prio=139 prev_state=S ==> next_comm=rcuog/1 next_pid=18 next_prio=120
CPU 5 switches again.
[ 2813.040289] rcuog/1-18 5d... 2689244361us : wake_up_process: entered
[ 2813.040289] rcuog/1-18 5d... 2689244362us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689244362us : scheduler_ipi: entered
[ 2813.040289] rcuog/1-18 5d... 2689244362us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244362us : sched_ttwu_pending: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244363us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] rcuog/1-18 5d... 2689244363us : try_to_wake_up: entered, CPU 0
[ 2813.040289] ksoftirq-9 0d.H. 2689244363us : ttwu_do_activate.isra.108: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244363us : activate_task: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244365us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244365us : check_preempt_curr: entered
[ 2813.040289] rcuog/1-18 5d... 2689244375us : sched_switch: prev_comm=rcuog/1 prev_pid=18 prev_prio=120 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
CPU 5 switches again.
[ 2813.040289] ksoftirq-9 0d.s. 2689244386us : scheduler_ipi: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244386us : sched_ttwu_pending: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244387us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] ksoftirq-9 0d.H. 2689244387us : ttwu_do_activate.isra.108: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244387us : activate_task: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244388us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689244388us : check_preempt_curr: entered
[ 2813.040289] ksoftirq-9 0..s. 2689245078us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689245078us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245079us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245079us : ttwu_do_activate.isra.108: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245080us : activate_task: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245080us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245080us : check_preempt_curr: entered
[ 2813.040289] ksoftirq-9 0..s. 2689245081us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689245081us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245081us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245082us : ttwu_do_activate.isra.108: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245082us : activate_task: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245082us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245083us : check_preempt_curr: entered
[ 2813.040289] ksoftirq-9 0..s. 2689245083us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689245083us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245084us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245084us : ttwu_do_activate.isra.108: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245084us : activate_task: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245084us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245085us : check_preempt_curr: entered
[ 2813.040289] ksoftirq-9 0..s. 2689245085us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689245085us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245086us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245086us : ttwu_do_activate.isra.108: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245086us : activate_task: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245087us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689245087us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-136 6.... 2689245087us : wake_up_process: entered
[ 2813.040289] rcu_tort-136 6.... 2689245087us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-136 6d... 2689245087us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-136 6d... 2689245087us : try_to_wake_up: entered, CPU 0
[ 2813.040289] ksoftirq-9 0d.s. 2689245639us : scheduler_ipi: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245639us : sched_ttwu_pending: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245639us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] ksoftirq-9 0d.H. 2689245639us : ttwu_do_activate.isra.108: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245640us : activate_task: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245640us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245640us : check_preempt_curr: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245640us : resched_curr: entered
[ 2813.040289] rcu_tort-136 6d... 2689245640us : activate_task: entered
[ 2813.040289] rcu_tort-136 6d... 2689245640us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-136 6d... 2689245640us : activate_task: entered
[ 2813.040289] rcu_tort-136 6d... 2689245640us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-136 6d... 2689245640us : resched_curr: entered
[ 2813.040289] rcu_tort-136 6dN.. 2689245640us : activate_task: entered
[ 2813.040289] rcu_tort-136 6dN.. 2689245640us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-136 6d... 2689245640us : sched_switch: prev_comm=rcu_torture_fwd prev_pid=136 prev_prio=139 prev_state=D ==> next_comm=rcuos/2 next_pid=25 next_prio=120
CPU 6 switches again.
[ 2813.040289] ksoftirq-9 0d... 2689245654us : sched_switch: prev_comm=ksoftirqd/0 prev_pid=9 prev_prio=120 prev_state=R+ ==> next_comm=rcuog/4 next_pid=37 next_prio=120
CPU 0 switches again.
[ 2813.040289] rcuog/4-37 0d... 2689245658us : sched_switch: prev_comm=rcuog/4 prev_pid=37 prev_prio=120 prev_state=S ==> next_comm=ksoftirqd/0 next_pid=9 next_prio=120
CPU 0 switches again.
[ 2813.040289] rcuos/2-25 6d... 2689245658us : try_to_wake_up: entered
[ 2813.040289] rcuos/2-25 6d... 2689245658us : try_to_wake_up: entered
[ 2813.040289] rcuos/2-25 6d... 2689245658us : try_to_wake_up: entered, CPU 2
[ 2813.040289] rcuos/2-25 6d... 2689245658us : sched_switch: prev_comm=rcuos/2 prev_pid=25 prev_prio=120 prev_state=S ==> next_comm=rcu_torture_fak next_pid=123 next_prio=139
CPU 6 switches again.
[ 2813.040289] rcu_tort-123 6d... 2689245658us : wake_up_process: entered
[ 2813.040289] rcu_tort-123 6d... 2689245658us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-123 6d... 2689245658us : try_to_wake_up: entered
[ 2813.040289] rcu_tort-123 6d... 2689245658us : try_to_wake_up: entered, CPU 0
[ 2813.040289] rcu_tort-123 6d... 2689245658us : sched_switch: prev_comm=rcu_torture_fak prev_pid=123 prev_prio=139 prev_state=D ==> next_comm=rcu_torture_rea next_pid=129 next_prio=139
CPU 6 switches again.
[ 2813.040289] rcu_tort-129 6d... 2689245658us : activate_task: entered
[ 2813.040289] rcu_tort-129 6d... 2689245658us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-129 6d... 2689245658us : sched_switch: prev_comm=rcu_torture_rea prev_pid=129 prev_prio=139 prev_state=S ==> next_comm=rcu_torture_rea next_pid=128 next_prio=139
CPU 6 switches again.
[ 2813.040289] ksoftirq-9 0d.s. 2689245781us : scheduler_ipi: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245781us : sched_ttwu_pending: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245781us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] ksoftirq-9 0d.H. 2689245781us : ttwu_do_activate.isra.108: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245782us : activate_task: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245782us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245782us : check_preempt_curr: entered
[ 2813.040289] ksoftirq-9 0d.H. 2689245783us : resched_curr: entered
[ 2813.040289] rcu_tort-128 6d... 2689245783us : activate_task: entered
[ 2813.040289] rcu_tort-128 6d... 2689245783us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-128 6d... 2689245783us : sched_switch: prev_comm=rcu_torture_rea prev_pid=128 prev_prio=139 prev_state=S ==> next_comm=rcu_torture_rea next_pid=127 next_prio=139
CPU 6 switches again.
[ 2813.040289] rcu_tort-127 6d... 2689245783us : activate_task: entered
[ 2813.040289] rcu_tort-127 6d... 2689245783us : check_preempt_curr: entered
[ 2813.040289] rcu_tort-127 6d... 2689245783us : sched_switch: prev_comm=rcu_torture_rea prev_pid=127 prev_prio=139 prev_state=S ==> next_comm=rcu_torture_rea next_pid=130 next_prio=139
CPU 6 switches again.
[ 2813.040289] rcu_tort-130 6d... 2689245783us : sched_switch: prev_comm=rcu_torture_rea prev_pid=130 prev_prio=139 prev_state=S ==> next_comm=swapper/6 next_pid=0 next_prio=120
CPU 6 switches again.
[ 2813.040289] ksoftirq-9 0d... 2689245805us : sched_switch: prev_comm=ksoftirqd/0 prev_pid=9 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:1 next_pid=183 next_prio=120
CPU 0 switches again.
[ 2813.040289] <idle>-0 2d... 2689245805us : scheduler_ipi: entered
[ 2813.040289] <idle>-0 2d.h. 2689246047us : sched_ttwu_pending: entered
[ 2813.040289] <idle>-0 2d.h. 2689246047us : sched_ttwu_pending: non-NULL llist
[ 2813.040289] <idle>-0 2d.h. 2689246048us : ttwu_do_activate.isra.108: entered
[ 2813.040289] <idle>-0 2d.h. 2689246048us : activate_task: entered
[ 2813.040289] <idle>-0 2d.h. 2689246050us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] <idle>-0 2d.h. 2689246050us : check_preempt_curr: entered
[ 2813.040289] <idle>-0 2d.h. 2689246050us : resched_curr: entered
[ 2813.040289] <idle>-0 2.N.. 2689246090us : sched_ttwu_pending: entered
[ 2813.040289] <idle>-0 2d... 2689246091us : sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_torture_wri next_pid=119 next_prio=120
CPU 2 switches again.
[ 2813.040289] rcu_tort-119 2d... 2689246096us : sched_switch: prev_comm=rcu_torture_wri prev_pid=119 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
CPU 2 switches again.
[ 2813.040289] kworker/-183 0d.h. 2689280510us : resched_curr: entered
[ 2813.040289] kworker/-183 0dNh. 2689285096us : resched_curr: entered
[ 2813.040289] kworker/-183 0dN.. 2689285103us : wake_up_process: entered
[ 2813.040289] kworker/-183 0dN.. 2689285103us : try_to_wake_up: entered
[ 2813.040289] kworker/-183 0dN.. 2689285104us : try_to_wake_up: entered
[ 2813.040289] kworker/-183 0dN.. 2689285105us : ttwu_do_activate.isra.108: entered
[ 2813.040289] kworker/-183 0dN.. 2689285105us : activate_task: entered
[ 2813.040289] kworker/-183 0dN.. 2689285106us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] kworker/-183 0dN.. 2689285106us : check_preempt_curr: entered
[ 2813.040289] kworker/-183 0d... 2689285109us : sched_switch: prev_comm=kworker/0:1 prev_pid=183 prev_prio=120 prev_state=D ==> next_comm=kworker/0:3 next_pid=171 next_prio=120
CPU 0 switches again.
[ 2813.040289] kworker/-171 0d... 2689285121us : try_to_wake_up: entered
[ 2813.040289] kworker/-171 0d... 2689285121us : try_to_wake_up: entered
[ 2813.040289] kworker/-171 0d... 2689285122us : ttwu_do_activate.isra.108: entered
[ 2813.040289] kworker/-171 0d... 2689285122us : activate_task: entered
[ 2813.040289] kworker/-171 0d... 2689285122us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] kworker/-171 0d... 2689285122us : check_preempt_curr: entered
[ 2813.040289] kworker/-171 0d... 2689285123us : sched_switch: prev_comm=kworker/0:3 prev_pid=171 prev_prio=120 prev_state=I ==> next_comm=ksoftirqd/0 next_pid=9 next_prio=120
CPU 0 switches again.
[ 2813.040289] ksoftirq-9 0..s. 2689285125us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689285126us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285126us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285127us : try_to_wake_up: entered, CPU 5
[ 2813.040289] ksoftirq-9 0..s. 2689285138us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689285138us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285138us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285138us : try_to_wake_up: entered, CPU 6
[ 2813.040289] migratio-14 1dN.1 2689285146us : try_to_wake_up: entered
[ 2813.040289] migratio-14 1dN.1 2689285148us : try_to_wake_up: entered
[ 2813.040289] migratio-14 1dN.1 2689285148us : ttwu_do_activate.isra.108: entered
[ 2813.040289] migratio-14 1dN.1 2689285148us : activate_task: entered
[ 2813.040289] migratio-14 1dN.1 2689285149us : ttwu_do_wakeup.isra.107: entered
[ 2813.040289] migratio-14 1dN.1 2689285149us : check_preempt_curr: entered
[ 2813.040289] ksoftirq-9 0..s. 2689285150us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689285150us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285150us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285151us : try_to_wake_up: entered, CPU 6
[ 2813.040289] ksoftirq-9 0..s. 2689285151us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689285151us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285152us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285152us : try_to_wake_up: entered, CPU 6
[ 2813.040289] ksoftirq-9 0..s. 2689285152us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689285152us : try_to_wake_up: entered
[ 2813.040289] migratio-14 1d... 2689285153us : sched_switch: prev_comm=migration/1 prev_pid=14 prev_prio=0 prev_state=S ==> next_comm=torture_onoff next_pid=135 next_prio=120
CPU 1 switches from its migration kthread.
[ 2813.040289] ksoftirq-9 0d.s. 2689285153us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285153us : try_to_wake_up: entered, CPU 6
[ 2813.040289] ksoftirq-9 0..s. 2689285153us : wake_up_process: entered
[ 2813.040289] ksoftirq-9 0..s. 2689285153us : try_to_wake_up: entered
[ 2813.040289] ksoftirq-9 0d.s. 2689285154us : try_to_wake_up: entered
[ 2813.040289] ---------------------------------
And finally, the trace ends and CPU 4 is announced as being offline:
[ 2813.040289] smpboot: CPU 4 is now offline
next prev parent reply other threads:[~2019-08-07 21:41 UTC|newest]
Thread overview: 57+ messages / expand[flat|nested] mbox.gz Atom feed top
2019-08-02 15:14 [PATCH tip/core/rcu 0/14] No-CBs bypass addition for v5.4 Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 01/14] rcu/nocb: Atomic ->len field in rcu_segcblist structure Paul E. McKenney
2019-08-04 14:50 ` Peter Zijlstra
2019-08-04 14:52 ` Peter Zijlstra
2019-08-04 18:45 ` Paul E. McKenney
2019-08-04 18:42 ` Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 02/14] rcu/nocb: Add bypass callback queueing Paul E. McKenney
2019-08-07 0:03 ` Joel Fernandes
2019-08-07 0:16 ` Joel Fernandes
2019-08-07 0:35 ` Paul E. McKenney
2019-08-07 0:40 ` Steven Rostedt
2019-08-07 1:17 ` Paul E. McKenney
2019-08-07 1:24 ` Steven Rostedt
2019-08-07 3:47 ` Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 03/14] rcu/nocb: EXP Check use and usefulness of ->nocb_lock_contended Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 04/14] rcu/nocb: Print no-CBs diagnostics when rcutorture writer unduly delayed Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 05/14] rcu/nocb: Avoid synchronous wakeup in __call_rcu_nocb_wake() Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 06/14] rcu/nocb: Advance CBs after merge in rcutree_migrate_callbacks() Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 07/14] rcu/nocb: Reduce nocb_cb_wait() leaf rcu_node ->lock contention Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 08/14] rcu/nocb: Reduce __call_rcu_nocb_wake() " Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 09/14] rcu/nocb: Don't wake no-CBs GP kthread if timer posted under overload Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 10/14] rcu: Allow rcu_do_batch() to dynamically adjust batch sizes Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 11/14] EXP nohz: Add TICK_DEP_BIT_RCU Paul E. McKenney
2019-08-02 15:14 ` [PATCH RFC tip/core/rcu 12/14] rcu/nohz: Force on tick when invoking lots of callbacks Paul E. McKenney
2019-08-02 15:15 ` [PATCH RFC tip/core/rcu 13/14] rcutorture: Force on tick for readers and callback flooders Paul E. McKenney
2019-08-02 15:15 ` [PATCH RFC tip/core/rcu 14/14] rcu/nohz: Make multi_cpu_stop() enable tick on all online CPUs Paul E. McKenney
2019-08-04 14:43 ` Peter Zijlstra
2019-08-04 14:48 ` Peter Zijlstra
2019-08-04 18:41 ` Paul E. McKenney
2019-08-04 20:24 ` Paul E. McKenney
2019-08-05 4:19 ` Paul E. McKenney
2019-08-05 8:07 ` Peter Zijlstra
2019-08-05 14:47 ` Paul E. McKenney
2019-08-05 8:05 ` Peter Zijlstra
2019-08-05 14:54 ` Paul E. McKenney
2019-08-05 15:50 ` Peter Zijlstra
2019-08-05 17:48 ` Paul E. McKenney
2019-08-06 18:08 ` Paul E. McKenney
2019-08-07 21:41 ` Paul E. McKenney [this message]
2019-08-08 20:35 ` Paul E. McKenney
2019-08-08 21:30 ` Paul E. McKenney
2019-08-09 16:51 ` Paul E. McKenney
2019-08-09 18:07 ` Joel Fernandes
2019-08-09 18:39 ` Paul E. McKenney
2019-08-12 21:02 ` Frederic Weisbecker
2019-08-12 23:23 ` Paul E. McKenney
2019-08-13 1:33 ` Joel Fernandes
2019-08-13 12:30 ` Frederic Weisbecker
2019-08-13 14:48 ` Paul E. McKenney
2019-08-14 17:55 ` Joel Fernandes
2019-08-14 22:05 ` Paul E. McKenney
2019-08-15 15:07 ` Joel Fernandes
2019-08-15 17:23 ` Paul E. McKenney
2019-08-15 18:15 ` Joel Fernandes
2019-08-15 18:39 ` Paul E. McKenney
2019-08-15 19:42 ` Joel Fernandes
2019-08-13 21:06 ` Paul E. McKenney
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20190807214131.GA15124@linux.ibm.com \
--to=paulmck@linux.ibm.com \
--cc=akpm@linux-foundation.org \
--cc=dhowells@redhat.com \
--cc=dipankar@in.ibm.com \
--cc=edumazet@google.com \
--cc=fweisbec@gmail.com \
--cc=jiangshanlai@gmail.com \
--cc=joel@joelfernandes.org \
--cc=josh@joshtriplett.org \
--cc=linux-kernel@vger.kernel.org \
--cc=mathieu.desnoyers@efficios.com \
--cc=mingo@kernel.org \
--cc=oleg@redhat.com \
--cc=peterz@infradead.org \
--cc=rcu@vger.kernel.org \
--cc=rostedt@goodmis.org \
--cc=tglx@linutronix.de \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.