On Mon, Dec 07, 2020 at 04:25:33PM +0100, Sebastian Andrzej Siewior wrote:
> On 2020-12-07 15:29:50 [+0100], Thomas Gleixner wrote:
> > On Mon, Dec 07 2020 at 14:07, Sebastian Andrzej Siewior wrote:
> > > One thing I noticed while testing it is that the "corner" case in
> > > timer_sync_wait_running() is quite reliably hit by rcu_preempt
> > > rcu_gp_fqs_loop() -> swait_event_idle_timeout_exclusive() invocation.
> >
> > I assume it's something like this:
> >
> > timeout -> wakeup
> >
> > ->preemption
> > del_timer_sync()
> > .....
>
> Yes, but it triggers frequently. Like `rcuc' is somehow is aligned with
> the timeout.
Given that a lot of RCU processing is event-driven based on timers,
and given that the scheduling-clock interrupts are synchronized for
energy-efficiency reasons on many configs, maybe this alignment is
expected behavior?
Thanx, Paul
> | <idle>-0 [007] dN.h4.. 46.299705: sched_wakeup:
> comm=rcuc/7 pid=53 prio=98 target_cpu=007
> | <idle>-0 [007] d...2.. 46.299728: sched_switch:
> prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==>
> next_comm=rcuc/7 next_pid=53 next_prio=98
> | rcuc/7-53 [007] d...2.. 46.299742: sched_switch:
> prev_comm=rcuc/7 prev_pid=53 prev_prio=98 prev_state=S ==>
> next_comm=ksoftirqd/7 next_pid=54 next_prio=120
> | ksoftirqd/7-54 [007] .....13 46.299750: timer_expire_entry:
> timer=000000003bd1e045 function=process_timeout now=4294903802
> baseclk=4294903802
> | ksoftirqd/7-54 [007] d...213 46.299750: sched_waking:
> comm=rcu_preempt pid=11 prio=98 target_cpu=007
> | ksoftirqd/7-54 [007] dN..313 46.299754: sched_wakeup:
> comm=rcu_preempt pid=11 prio=98 target_cpu=007
> | ksoftirqd/7-54 [007] dN..213 46.299756: sched_stat_runtime:
> comm=ksoftirqd/7 pid=54 runtime=13265 [ns] vruntime=3012610540 [ns]
> | ksoftirqd/7-54 [007] d...213 46.299760: sched_switch:
> prev_comm=ksoftirqd/7 prev_pid=54 prev_prio=120 prev_state=R+ ==>
> next_comm=rcu_preempt next_pid=11 next_prio=98
> | rcu_preempt-11 [007] d...311 46.299766: sched_pi_setprio:
> comm=ksoftirqd/7 pid=54 oldprio=120 newprio=98
> del_timer_sync()
> | rcu_preempt-11 [007] d...211 46.299773: sched_switch:
> prev_comm=rcu_preempt prev_pid=11 prev_prio=98 prev_state=R+ ==>
> next_comm=ksoftirqd/7 next_pid=54 next_prio=98
> | ksoftirqd/7-54 [007] .....13 46.299774: timer_expire_exit:
> timer=000000003bd1e045
> | ksoftirqd/7-54 [007] dN..311 46.299784: sched_pi_setprio:
> comm=ksoftirqd/7 pid=54 oldprio=98 newprio=120
> | ksoftirqd/7-54 [007] dN..311 46.299788: sched_waking:
> comm=rcu_preempt pid=11 prio=98 target_cpu=007
> | ksoftirqd/7-54 [007] dN..411 46.299790: sched_wakeup:
> comm=rcu_preempt pid=11 prio=98 target_cpu=007
> | ksoftirqd/7-54 [007] dN..311 46.299792: sched_stat_runtime:
> comm=ksoftirqd/7 pid=54 runtime=7404 [ns] vruntime=3012617944 [ns]
> | ksoftirqd/7-54 [007] d...2.. 46.299797: sched_switch:
> prev_comm=ksoftirqd/7 prev_pid=54 prev_prio=120 prev_state=S ==>
> next_comm=rcu_preempt next_pid=11 next_prio=98
>
>
> > Thanks,
> >
> > tglx
>
> Sebastian
