* 3.8.10-rt6 : Observing high latency as timer_interrupt is taking longer to exit
@ 2013-05-14 10:40 Jain Priyanka-B32167
2013-05-15 10:19 ` Jain Priyanka-B32167
0 siblings, 1 reply; 6+ messages in thread
From: Jain Priyanka-B32167 @ 2013-05-14 10:40 UTC (permalink / raw)
To: linux-rt-users
Hi,
I am running PREEMPT_RT kernel on single-core PowerPC based platform and using cyclictest tool to measure latency.
Earlier I have used 2.6.33.9-rt31, With that kernel, latency has always remained below 50us irrespective of the traffic.
With 3.8.10-rt6, latency is shooting beyond 200us irrespective of the traffic - no load, heavy traffic conditions included. Issue is generally reproduced within 10 minutes of run
When I tried to debug the issue using ftrace, I am observing that it is taking 200us for transition from timer_interrupt_exit(interrupts disabled) to timer_start in Kworker/-297 thread.
I have tried multiple times and always observed similar trace. Please help me in debugging the issue.
Trace Logs:
cyclicte-3307 0d...2.. 104489596us+: hrtimer_start: hrtimer=dfee9e98 function=hrtimer_wakeup expires=1587365915748 softexpires=1587365865748
cyclicte-3307 0d...3.. 104489599us+: sched_stat_runtime: comm=cyclictest pid=3307 runtime=119552 [ns] vruntime=22040816169 [ns]
cyclicte-3307 0d...3.. 104489602us!: sched_switch: prev_comm=cyclictest prev_pid=3307 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
<idle>-0 0d..h2.. 104489732us+: timer_interrupt_entry: pt_regs=c086fed0
<idle>-0 0d..h3.. 104489733us : hrtimer_cancel: hrtimer=c0830240
<idle>-0 0d..h2.. 104489735us+: hrtimer_expire_entry: hrtimer=c0830240 function=tick_sched_timer now=1587356002980
<idle>-0 0d..h2.. 104489741us : softirq_raise: vec=1 [action=TIMER]
<idle>-0 0d..h2.. 104489743us+: softirq_raise: vec=9 [action=RCU]
<idle>-0 0d..h2.. 104489744us+: hrtimer_expire_exit: hrtimer=c0830240
<idle>-0 0d..h3.. 104489746us+: hrtimer_start: hrtimer=c0830240 function=tick_sched_timer expires=1587360000000 softexpires=1587360000000
<idle>-0 0d..h2.. 104489749us+: timer_interrupt_exit: pt_regs=c086fed0
<idle>-0 0d...5.. 104489751us+: sched_wakeup: comm=ksoftirqd/0 pid=3 prio=98 success=1 target_cpu=000
<idle>-0 0d...3.. 104489755us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/0 next_pid=3 next_prio=98
ksoftirq-3 0....1.. 104489758us+: softirq_entry: vec=1 [action=TIMER]
ksoftirq-3 0....1.. 104489761us+: timer_cancel: timer=eb260d9c
ksoftirq-3 0....1.. 104489762us+: timer_expire_entry: timer=eb260d9c function=delayed_work_timer_fn now=321839
ksoftirq-3 0....1.. 104489765us+: workqueue_queue_work: work struct=eb260d8c function=phy_state_machine workqueue=eb803bc0 req_cpu=1 cpu=0
ksoftirq-3 0....1.. 104489767us+: workqueue_activate_work: work struct eb260d8c
ksoftirq-3 0d...3.. 104489770us+: sched_wakeup: comm=kworker/0:1 pid=297 prio=120 success=1 target_cpu=000
ksoftirq-3 0....1.. 104489772us : timer_expire_exit: timer=eb260d9c
ksoftirq-3 0....1.. 104489773us : timer_cancel: timer=eb260b9c
ksoftirq-3 0....1.. 104489774us : timer_expire_entry: timer=eb260b9c function=delayed_work_timer_fn now=321839
ksoftirq-3 0....1.. 104489775us : workqueue_queue_work: work struct=eb260b8c function=phy_state_machine workqueue=eb803bc0 req_cpu=1 cpu=0
ksoftirq-3 0....1.. 104489775us : workqueue_activate_work: work struct eb260b8c
ksoftirq-3 0....1.. 104489777us : timer_expire_exit: timer=eb260b9c
ksoftirq-3 0....1.. 104489778us : softirq_exit: vec=1 [action=TIMER]
ksoftirq-3 0....1.. 104489779us+: softirq_entry: vec=9 [action=RCU]
ksoftirq-3 0....1.. 104489781us : kmem_cache_free: call_site=c00fd3e4 ptr=d4f9f780
ksoftirq-3 0....1.. 104489782us : kmem_cache_free: call_site=c0154bc0 ptr=eb7f8998
ksoftirq-3 0....1.. 104489783us : kmem_cache_free: call_site=c01123ec ptr=e9937b80
ksoftirq-3 0....1.. 104489784us+: softirq_exit: vec=9 [action=RCU]
ksoftirq-3 0d...3.. 104489788us+: sched_switch: prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=98 prev_state=S ==> next_comm=kworker/0:1 next_pid=297 next_prio=120
kworker/-297 0....1.. 104489793us!: workqueue_execute_start: work struct eb260d8c: function phy_state_machine
kworker/-297 0d..h1.. 104489916us+: irq_entry: pt_regs=eb917d50
kworker/-297 0d..h1.. 104489920us : irq_handler_entry: irq=18 name=serial
kworker/-297 0d..h1.. 104489921us+: irq_handler_exit: irq=18 ret=handled
kworker/-297 0d..h3.. 104489923us+: sched_wakeup: comm=irq/18-serial pid=3267 prio=49 success=1 target_cpu=000
kworker/-297 0dN.h1.. 104489925us+: irq_exit: pt_regs=eb917d50
kworker/-297 0dN.h1.. 104489985us+: timer_interrupt_entry: pt_regs=eb917d60
kworker/-297 0dN.h2.. 104489987us+: hrtimer_cancel: hrtimer=d4e8de78
kworker/-297 0dN.h1.. 104489989us+: hrtimer_expire_entry: hrtimer=d4e8de78 function=hrtimer_wakeup now=1319135162835780883
kworker/-297 0dN.h3.. 104489990us : sched_wakeup: comm=cyclictest pid=3308 prio=0 success=1 target_cpu=000
kworker/-297 0dN.h1.. 104489992us+: hrtimer_expire_exit: hrtimer=d4e8de78
kworker/-297 0dN.h1.. 104489993us!: timer_interrupt_exit: pt_regs=eb917d60
kworker/-297 0.N..1.. 104490188us+: timer_start: timer=eb260d9c function=delayed_work_timer_fn expires=322089 [timeout=250]
kworker/-297 0dN..3.. 104490190us+: sched_stat_runtime: comm=kworker/0:1 pid=297 runtime=136032 [ns] vruntime=22037952201 [ns]
kworker/-297 0d...3.. 104490192us+: sched_switch: prev_comm=kworker/0:1 prev_pid=297 prev_prio=120 prev_state=R+ ==> next_comm=cyclictest next_pid=3308 next_prio=0
cyclicte-3308 0....1.. 104490194us+: sys_exit: NR 248 = 0
cyclicte-3308 0....1.. 104490196us+: sys_enter: NR 246 (0, 487ff5e4, 0, 0, c8, f4240)
cyclicte-3308 0....1.. 104490199us+: sys_exit: NR 246 = 0
cyclicte-3308 0....1.. 104490228us+: mm_page_alloc: page=c0ed2920 pfn=195657 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
cyclicte-3308 0....1.. 104490240us+: sys_enter: NR 4 (5, 488003e4, 1f, 0, 0, 20)
cyclicte-3308 0....... 104490244us+: tracing_mark_write: hit latency threshold (213 > 0)
cyclicte-3308 0....1.. 104490247us+: sys_exit: NR 4 = 31
cyclicte-3308 0....1.. 104490249us : sys_enter: NR 4 (4, 100855c4, 1, 0, 0, 20)
Regards
Priyanka
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 6+ messages in thread
* RE: 3.8.10-rt6 : Observing high latency as timer_interrupt is taking longer to exit
2013-05-14 10:40 3.8.10-rt6 : Observing high latency as timer_interrupt is taking longer to exit Jain Priyanka-B32167
@ 2013-05-15 10:19 ` Jain Priyanka-B32167
2013-05-21 5:42 ` Jain Priyanka-B32167
0 siblings, 1 reply; 6+ messages in thread
From: Jain Priyanka-B32167 @ 2013-05-15 10:19 UTC (permalink / raw)
To: linux-rt-users
Hi,
I have further debug the issue.
The increase in latency issue is observed when kworker is in execution and timer_interrupt(hardirq) arrives.
Upon completion of timer_interrupt, previous context should have immediately got restored.
But a large time-gap (varying from 50us to 200us) is observed in restoration of kworker task.
e.g in below context, 195us gap is observed in timer_interrupt_exit and timer_start (kworker).
In complete trace, I have seen multiple entries of timer_interrupt.
But exit is taking large time gap only when it arrives in context of kworker.
Looking for some pointers as help to debug the issue.
Regards
Priyanka
> -----Original Message-----
> From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> Sent: Tuesday, May 14, 2013 4:10 PM
> To: linux-rt-users@vger.kernel.org
> Subject: 3.8.10-rt6 : Observing high latency as timer_interrupt is taking
> longer to exit
>
> Hi,
>
> I am running PREEMPT_RT kernel on single-core PowerPC based platform and
> using cyclictest tool to measure latency.
>
> Earlier I have used 2.6.33.9-rt31, With that kernel, latency has always
> remained below 50us irrespective of the traffic.
> With 3.8.10-rt6, latency is shooting beyond 200us irrespective of the
> traffic - no load, heavy traffic conditions included. Issue is generally
> reproduced within 10 minutes of run
>
> When I tried to debug the issue using ftrace, I am observing that it is
> taking 200us for transition from timer_interrupt_exit(interrupts
> disabled) to timer_start in Kworker/-297 thread.
> I have tried multiple times and always observed similar trace. Please
> help me in debugging the issue.
>
> Trace Logs:
>
> cyclicte-3307 0d...2.. 104489596us+: hrtimer_start: hrtimer=dfee9e98
> function=hrtimer_wakeup expires=1587365915748 softexpires=1587365865748
> cyclicte-3307 0d...3.. 104489599us+: sched_stat_runtime:
> comm=cyclictest pid=3307 runtime=119552 [ns] vruntime=22040816169 [ns]
> cyclicte-3307 0d...3.. 104489602us!: sched_switch:
> prev_comm=cyclictest prev_pid=3307 prev_prio=120 prev_state=S ==>
> next_comm=swapper next_pid=0 next_prio=120
> <idle>-0 0d..h2.. 104489732us+: timer_interrupt_entry:
> pt_regs=c086fed0
> <idle>-0 0d..h3.. 104489733us : hrtimer_cancel: hrtimer=c0830240
> <idle>-0 0d..h2.. 104489735us+: hrtimer_expire_entry:
> hrtimer=c0830240 function=tick_sched_timer now=1587356002980
> <idle>-0 0d..h2.. 104489741us : softirq_raise: vec=1
> [action=TIMER]
> <idle>-0 0d..h2.. 104489743us+: softirq_raise: vec=9 [action=RCU]
> <idle>-0 0d..h2.. 104489744us+: hrtimer_expire_exit:
> hrtimer=c0830240
> <idle>-0 0d..h3.. 104489746us+: hrtimer_start: hrtimer=c0830240
> function=tick_sched_timer expires=1587360000000 softexpires=1587360000000
> <idle>-0 0d..h2.. 104489749us+: timer_interrupt_exit:
> pt_regs=c086fed0
> <idle>-0 0d...5.. 104489751us+: sched_wakeup: comm=ksoftirqd/0
> pid=3 prio=98 success=1 target_cpu=000
> <idle>-0 0d...3.. 104489755us+: sched_switch: prev_comm=swapper
> prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/0
> next_pid=3 next_prio=98
> ksoftirq-3 0....1.. 104489758us+: softirq_entry: vec=1
> [action=TIMER]
> ksoftirq-3 0....1.. 104489761us+: timer_cancel: timer=eb260d9c
> ksoftirq-3 0....1.. 104489762us+: timer_expire_entry:
> timer=eb260d9c function=delayed_work_timer_fn now=321839
> ksoftirq-3 0....1.. 104489765us+: workqueue_queue_work: work
> struct=eb260d8c function=phy_state_machine workqueue=eb803bc0 req_cpu=1
> cpu=0
> ksoftirq-3 0....1.. 104489767us+: workqueue_activate_work: work
> struct eb260d8c
> ksoftirq-3 0d...3.. 104489770us+: sched_wakeup: comm=kworker/0:1
> pid=297 prio=120 success=1 target_cpu=000
> ksoftirq-3 0....1.. 104489772us : timer_expire_exit: timer=eb260d9c
> ksoftirq-3 0....1.. 104489773us : timer_cancel: timer=eb260b9c
> ksoftirq-3 0....1.. 104489774us : timer_expire_entry:
> timer=eb260b9c function=delayed_work_timer_fn now=321839
> ksoftirq-3 0....1.. 104489775us : workqueue_queue_work: work
> struct=eb260b8c function=phy_state_machine workqueue=eb803bc0 req_cpu=1
> cpu=0
> ksoftirq-3 0....1.. 104489775us : workqueue_activate_work: work
> struct eb260b8c
> ksoftirq-3 0....1.. 104489777us : timer_expire_exit: timer=eb260b9c
> ksoftirq-3 0....1.. 104489778us : softirq_exit: vec=1
> [action=TIMER]
> ksoftirq-3 0....1.. 104489779us+: softirq_entry: vec=9 [action=RCU]
> ksoftirq-3 0....1.. 104489781us : kmem_cache_free:
> call_site=c00fd3e4 ptr=d4f9f780
> ksoftirq-3 0....1.. 104489782us : kmem_cache_free:
> call_site=c0154bc0 ptr=eb7f8998
> ksoftirq-3 0....1.. 104489783us : kmem_cache_free:
> call_site=c01123ec ptr=e9937b80
> ksoftirq-3 0....1.. 104489784us+: softirq_exit: vec=9 [action=RCU]
> ksoftirq-3 0d...3.. 104489788us+: sched_switch:
> prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=98 prev_state=S ==>
> next_comm=kworker/0:1 next_pid=297 next_prio=120
> kworker/-297 0....1.. 104489793us!: workqueue_execute_start: work
> struct eb260d8c: function phy_state_machine
> kworker/-297 0d..h1.. 104489916us+: irq_entry: pt_regs=eb917d50
> kworker/-297 0d..h1.. 104489920us : irq_handler_entry: irq=18
> name=serial
> kworker/-297 0d..h1.. 104489921us+: irq_handler_exit: irq=18
> ret=handled
> kworker/-297 0d..h3.. 104489923us+: sched_wakeup: comm=irq/18-serial
> pid=3267 prio=49 success=1 target_cpu=000
> kworker/-297 0dN.h1.. 104489925us+: irq_exit: pt_regs=eb917d50
> kworker/-297 0dN.h1.. 104489985us+: timer_interrupt_entry:
> pt_regs=eb917d60
> kworker/-297 0dN.h2.. 104489987us+: hrtimer_cancel: hrtimer=d4e8de78
> kworker/-297 0dN.h1.. 104489989us+: hrtimer_expire_entry:
> hrtimer=d4e8de78 function=hrtimer_wakeup now=1319135162835780883
> kworker/-297 0dN.h3.. 104489990us : sched_wakeup: comm=cyclictest
> pid=3308 prio=0 success=1 target_cpu=000
> kworker/-297 0dN.h1.. 104489992us+: hrtimer_expire_exit:
> hrtimer=d4e8de78
> kworker/-297 0dN.h1.. 104489993us!: timer_interrupt_exit:
> pt_regs=eb917d60
> kworker/-297 0.N..1.. 104490188us+: timer_start: timer=eb260d9c
> function=delayed_work_timer_fn expires=322089 [timeout=250]
> kworker/-297 0dN..3.. 104490190us+: sched_stat_runtime:
> comm=kworker/0:1 pid=297 runtime=136032 [ns] vruntime=22037952201 [ns]
> kworker/-297 0d...3.. 104490192us+: sched_switch:
> prev_comm=kworker/0:1 prev_pid=297 prev_prio=120 prev_state=R+ ==>
> next_comm=cyclictest next_pid=3308 next_prio=0
> cyclicte-3308 0....1.. 104490194us+: sys_exit: NR 248 = 0
> cyclicte-3308 0....1.. 104490196us+: sys_enter: NR 246 (0, 487ff5e4,
> 0, 0, c8, f4240)
> cyclicte-3308 0....1.. 104490199us+: sys_exit: NR 246 = 0
> cyclicte-3308 0....1.. 104490228us+: mm_page_alloc: page=c0ed2920
> pfn=195657 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
> cyclicte-3308 0....1.. 104490240us+: sys_enter: NR 4 (5, 488003e4, 1f,
> 0, 0, 20)
> cyclicte-3308 0....... 104490244us+: tracing_mark_write: hit latency
> threshold (213 > 0)
> cyclicte-3308 0....1.. 104490247us+: sys_exit: NR 4 = 31
> cyclicte-3308 0....1.. 104490249us : sys_enter: NR 4 (4, 100855c4, 1,
> 0, 0, 20)
>
> Regards
> Priyanka
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-rt-users"
> in the body of a message to majordomo@vger.kernel.org More majordomo info
> at http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 6+ messages in thread
* RE: 3.8.10-rt6 : Observing high latency as timer_interrupt is taking longer to exit
2013-05-15 10:19 ` Jain Priyanka-B32167
@ 2013-05-21 5:42 ` Jain Priyanka-B32167
2013-05-21 7:01 ` 3.8.10-rt6 : Observing high latency as preempt_schedule_irq:__schedule is not getting called Jain Priyanka-B32167
0 siblings, 1 reply; 6+ messages in thread
From: Jain Priyanka-B32167 @ 2013-05-21 5:42 UTC (permalink / raw)
To: linux-rt-users, Steven Rostedt
[-- Attachment #1: Type: text/plain, Size: 9226 bytes --]
Furthur debug analysis
I am running cylictest with following settings:
./cyclictest -a -n -p 99 -c 1 -d 0 -O latency-format -b 600 --tracer=function_graph
It seems that even if 'N' (need rescheduled bit) is set in current task and preemption disabled count is zero, context switching to highest priority task which is cyclictest thread in this case is not happening immediately. It is getting delayed adding to latency. Trace capture attached.
Please help me in identifying what can be the issue.
Regards
Priyanka
> -----Original Message-----
> From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> Sent: Wednesday, May 15, 2013 3:49 PM
> To: linux-rt-users@vger.kernel.org
> Subject: RE: 3.8.10-rt6 : Observing high latency as timer_interrupt is
> taking longer to exit
>
> Hi,
>
> I have further debug the issue.
>
> The increase in latency issue is observed when kworker is in execution
> and timer_interrupt(hardirq) arrives.
> Upon completion of timer_interrupt, previous context should have
> immediately got restored.
> But a large time-gap (varying from 50us to 200us) is observed in
> restoration of kworker task.
> e.g in below context, 195us gap is observed in timer_interrupt_exit and
> timer_start (kworker).
>
> In complete trace, I have seen multiple entries of timer_interrupt.
> But exit is taking large time gap only when it arrives in context of
> kworker.
>
> Looking for some pointers as help to debug the issue.
>
> Regards
> Priyanka
>
> > -----Original Message-----
> > From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> > owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> > Sent: Tuesday, May 14, 2013 4:10 PM
> > To: linux-rt-users@vger.kernel.org
> > Subject: 3.8.10-rt6 : Observing high latency as timer_interrupt is
> > taking longer to exit
> >
> > Hi,
> >
> > I am running PREEMPT_RT kernel on single-core PowerPC based platform
> > and using cyclictest tool to measure latency.
> >
> > Earlier I have used 2.6.33.9-rt31, With that kernel, latency has
> > always remained below 50us irrespective of the traffic.
> > With 3.8.10-rt6, latency is shooting beyond 200us irrespective of the
> > traffic - no load, heavy traffic conditions included. Issue is
> > generally reproduced within 10 minutes of run
> >
> > When I tried to debug the issue using ftrace, I am observing that it
> > is taking 200us for transition from timer_interrupt_exit(interrupts
> > disabled) to timer_start in Kworker/-297 thread.
> > I have tried multiple times and always observed similar trace. Please
> > help me in debugging the issue.
> >
> > Trace Logs:
> >
> > cyclicte-3307 0d...2.. 104489596us+: hrtimer_start:
> > hrtimer=dfee9e98 function=hrtimer_wakeup expires=1587365915748
> > softexpires=1587365865748
> > cyclicte-3307 0d...3.. 104489599us+: sched_stat_runtime:
> > comm=cyclictest pid=3307 runtime=119552 [ns] vruntime=22040816169 [ns]
> > cyclicte-3307 0d...3.. 104489602us!: sched_switch:
> > prev_comm=cyclictest prev_pid=3307 prev_prio=120 prev_state=S ==>
> > next_comm=swapper next_pid=0 next_prio=120
> > <idle>-0 0d..h2.. 104489732us+: timer_interrupt_entry:
> > pt_regs=c086fed0
> > <idle>-0 0d..h3.. 104489733us : hrtimer_cancel:
> > hrtimer=c0830240
> > <idle>-0 0d..h2.. 104489735us+: hrtimer_expire_entry:
> > hrtimer=c0830240 function=tick_sched_timer now=1587356002980
> > <idle>-0 0d..h2.. 104489741us : softirq_raise: vec=1
> > [action=TIMER]
> > <idle>-0 0d..h2.. 104489743us+: softirq_raise: vec=9
> > [action=RCU]
> > <idle>-0 0d..h2.. 104489744us+: hrtimer_expire_exit:
> > hrtimer=c0830240
> > <idle>-0 0d..h3.. 104489746us+: hrtimer_start:
> > hrtimer=c0830240 function=tick_sched_timer expires=1587360000000
> > softexpires=1587360000000
> > <idle>-0 0d..h2.. 104489749us+: timer_interrupt_exit:
> > pt_regs=c086fed0
> > <idle>-0 0d...5.. 104489751us+: sched_wakeup: comm=ksoftirqd/0
> > pid=3 prio=98 success=1 target_cpu=000
> > <idle>-0 0d...3.. 104489755us+: sched_switch:
> > prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==>
> > next_comm=ksoftirqd/0
> > next_pid=3 next_prio=98
> > ksoftirq-3 0....1.. 104489758us+: softirq_entry: vec=1
> > [action=TIMER]
> > ksoftirq-3 0....1.. 104489761us+: timer_cancel: timer=eb260d9c
> > ksoftirq-3 0....1.. 104489762us+: timer_expire_entry:
> > timer=eb260d9c function=delayed_work_timer_fn now=321839
> > ksoftirq-3 0....1.. 104489765us+: workqueue_queue_work: work
> > struct=eb260d8c function=phy_state_machine workqueue=eb803bc0
> > req_cpu=1 cpu=0
> > ksoftirq-3 0....1.. 104489767us+: workqueue_activate_work: work
> > struct eb260d8c
> > ksoftirq-3 0d...3.. 104489770us+: sched_wakeup: comm=kworker/0:1
> > pid=297 prio=120 success=1 target_cpu=000
> > ksoftirq-3 0....1.. 104489772us : timer_expire_exit:
> > timer=eb260d9c
> > ksoftirq-3 0....1.. 104489773us : timer_cancel: timer=eb260b9c
> > ksoftirq-3 0....1.. 104489774us : timer_expire_entry:
> > timer=eb260b9c function=delayed_work_timer_fn now=321839
> > ksoftirq-3 0....1.. 104489775us : workqueue_queue_work: work
> > struct=eb260b8c function=phy_state_machine workqueue=eb803bc0
> > req_cpu=1 cpu=0
> > ksoftirq-3 0....1.. 104489775us : workqueue_activate_work: work
> > struct eb260b8c
> > ksoftirq-3 0....1.. 104489777us : timer_expire_exit:
> > timer=eb260b9c
> > ksoftirq-3 0....1.. 104489778us : softirq_exit: vec=1
> > [action=TIMER]
> > ksoftirq-3 0....1.. 104489779us+: softirq_entry: vec=9
> > [action=RCU]
> > ksoftirq-3 0....1.. 104489781us : kmem_cache_free:
> > call_site=c00fd3e4 ptr=d4f9f780
> > ksoftirq-3 0....1.. 104489782us : kmem_cache_free:
> > call_site=c0154bc0 ptr=eb7f8998
> > ksoftirq-3 0....1.. 104489783us : kmem_cache_free:
> > call_site=c01123ec ptr=e9937b80
> > ksoftirq-3 0....1.. 104489784us+: softirq_exit: vec=9
> > [action=RCU]
> > ksoftirq-3 0d...3.. 104489788us+: sched_switch:
> > prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=98 prev_state=S ==>
> > next_comm=kworker/0:1 next_pid=297 next_prio=120
> > kworker/-297 0....1.. 104489793us!: workqueue_execute_start: work
> > struct eb260d8c: function phy_state_machine
> > kworker/-297 0d..h1.. 104489916us+: irq_entry: pt_regs=eb917d50
> > kworker/-297 0d..h1.. 104489920us : irq_handler_entry: irq=18
> > name=serial
> > kworker/-297 0d..h1.. 104489921us+: irq_handler_exit: irq=18
> > ret=handled
> > kworker/-297 0d..h3.. 104489923us+: sched_wakeup:
> > comm=irq/18-serial
> > pid=3267 prio=49 success=1 target_cpu=000
> > kworker/-297 0dN.h1.. 104489925us+: irq_exit: pt_regs=eb917d50
> > kworker/-297 0dN.h1.. 104489985us+: timer_interrupt_entry:
> > pt_regs=eb917d60
> > kworker/-297 0dN.h2.. 104489987us+: hrtimer_cancel:
> > hrtimer=d4e8de78
> > kworker/-297 0dN.h1.. 104489989us+: hrtimer_expire_entry:
> > hrtimer=d4e8de78 function=hrtimer_wakeup now=1319135162835780883
> > kworker/-297 0dN.h3.. 104489990us : sched_wakeup: comm=cyclictest
> > pid=3308 prio=0 success=1 target_cpu=000
> > kworker/-297 0dN.h1.. 104489992us+: hrtimer_expire_exit:
> > hrtimer=d4e8de78
> > kworker/-297 0dN.h1.. 104489993us!: timer_interrupt_exit:
> > pt_regs=eb917d60
> > kworker/-297 0.N..1.. 104490188us+: timer_start: timer=eb260d9c
> > function=delayed_work_timer_fn expires=322089 [timeout=250]
> > kworker/-297 0dN..3.. 104490190us+: sched_stat_runtime:
> > comm=kworker/0:1 pid=297 runtime=136032 [ns] vruntime=22037952201 [ns]
> > kworker/-297 0d...3.. 104490192us+: sched_switch:
> > prev_comm=kworker/0:1 prev_pid=297 prev_prio=120 prev_state=R+ ==>
> > next_comm=cyclictest next_pid=3308 next_prio=0
> > cyclicte-3308 0....1.. 104490194us+: sys_exit: NR 248 = 0
> > cyclicte-3308 0....1.. 104490196us+: sys_enter: NR 246 (0,
> > 487ff5e4, 0, 0, c8, f4240)
> > cyclicte-3308 0....1.. 104490199us+: sys_exit: NR 246 = 0
> > cyclicte-3308 0....1.. 104490228us+: mm_page_alloc: page=c0ed2920
> > pfn=195657 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
> > cyclicte-3308 0....1.. 104490240us+: sys_enter: NR 4 (5, 488003e4,
> > 1f, 0, 0, 20)
> > cyclicte-3308 0....... 104490244us+: tracing_mark_write: hit
> > latency threshold (213 > 0)
> > cyclicte-3308 0....1.. 104490247us+: sys_exit: NR 4 = 31
> > cyclicte-3308 0....1.. 104490249us : sys_enter: NR 4 (4, 100855c4,
> > 1, 0, 0, 20)
> >
> > Regards
> > Priyanka
> >
> >
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-rt-
> users"
> > in the body of a message to majordomo@vger.kernel.org More majordomo
> > info at http://vger.kernel.org/majordomo-info.html
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-rt-users"
> in the body of a message to majordomo@vger.kernel.org More majordomo info
> at http://vger.kernel.org/majordomo-info.html
[-- Attachment #2: trace_21may_fg_600.tgz --]
[-- Type: application/x-compressed, Size: 53198 bytes --]
^ permalink raw reply [flat|nested] 6+ messages in thread
* 3.8.10-rt6 : Observing high latency as preempt_schedule_irq:__schedule is not getting called
2013-05-21 5:42 ` Jain Priyanka-B32167
@ 2013-05-21 7:01 ` Jain Priyanka-B32167
2013-05-28 4:01 ` Jain Priyanka-B32167
0 siblings, 1 reply; 6+ messages in thread
From: Jain Priyanka-B32167 @ 2013-05-21 7:01 UTC (permalink / raw)
To: Jain Priyanka-B32167, linux-rt-users, Steven Rostedt, tglx,
Sebastian Andrzej Siewior
Cc: Dev Manish-R65866, Aggrwal Poonam-B10812, Srivastava Rajan-B34330
Setup: Single core PowerPC, 32-bit platform , Linux3.8.10-rt6
'preempt_schedule_irq()' is a function which generally gets called while exiting from IRQ context to call __schedule so that preemption opportunities do not get missed.
I have added print just above call to __schedule()
(START)
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 3891f97..1f423c5 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3350,6 +3350,7 @@ asmlinkage void __sched preempt_schedule_irq(void)
do {
add_preempt_count(PREEMPT_ACTIVE);
local_irq_enable();
+ printk("%s\n",__FUNCTION__);
__schedule();
local_irq_disable();
sub_preempt_count(PREEMPT_ACTIVE);
(END)
As none of instance of this print is coming in kernel dump, it seems that 'preempt_schedule_irq:__schedule' is not getting called.
So preemption opportunities while exiting from IRQ context(exception handling) are getting missed leading to increase in latencies.
There are several changes in Kernel around this code specially the LAZY_PREEMPT feature, so I am not able to root-cause the exact issue. Please help me in fixing this.
Regards
Priyanka
> -----Original Message-----
> From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> Sent: Tuesday, May 21, 2013 11:13 AM
> To: linux-rt-users@vger.kernel.org; Steven Rostedt
> Subject: RE: 3.8.10-rt6 : Observing high latency as timer_interrupt is
> taking longer to exit
>
> Furthur debug analysis
>
> I am running cylictest with following settings:
> ./cyclictest -a -n -p 99 -c 1 -d 0 -O latency-format -b 600 --
> tracer=function_graph
>
>
> It seems that even if 'N' (need rescheduled bit) is set in current task
> and preemption disabled count is zero, context switching to highest
> priority task which is cyclictest thread in this case is not happening
> immediately. It is getting delayed adding to latency. Trace capture
> attached.
>
> Please help me in identifying what can be the issue.
>
> Regards
> Priyanka
>
> > -----Original Message-----
> > From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> > owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> > Sent: Wednesday, May 15, 2013 3:49 PM
> > To: linux-rt-users@vger.kernel.org
> > Subject: RE: 3.8.10-rt6 : Observing high latency as timer_interrupt is
> > taking longer to exit
> >
> > Hi,
> >
> > I have further debug the issue.
> >
> > The increase in latency issue is observed when kworker is in execution
> > and timer_interrupt(hardirq) arrives.
> > Upon completion of timer_interrupt, previous context should have
> > immediately got restored.
> > But a large time-gap (varying from 50us to 200us) is observed in
> > restoration of kworker task.
> > e.g in below context, 195us gap is observed in timer_interrupt_exit
> > and timer_start (kworker).
> >
> > In complete trace, I have seen multiple entries of timer_interrupt.
> > But exit is taking large time gap only when it arrives in context of
> > kworker.
> >
> > Looking for some pointers as help to debug the issue.
> >
> > Regards
> > Priyanka
> >
> > > -----Original Message-----
> > > From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> > > owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> > > Sent: Tuesday, May 14, 2013 4:10 PM
> > > To: linux-rt-users@vger.kernel.org
> > > Subject: 3.8.10-rt6 : Observing high latency as timer_interrupt is
> > > taking longer to exit
> > >
> > > Hi,
> > >
> > > I am running PREEMPT_RT kernel on single-core PowerPC based
> > > platform and using cyclictest tool to measure latency.
> > >
> > > Earlier I have used 2.6.33.9-rt31, With that kernel, latency has
> > > always remained below 50us irrespective of the traffic.
> > > With 3.8.10-rt6, latency is shooting beyond 200us irrespective of
> > > the traffic - no load, heavy traffic conditions included. Issue is
> > > generally reproduced within 10 minutes of run
> > >
> > > When I tried to debug the issue using ftrace, I am observing that it
> > > is taking 200us for transition from timer_interrupt_exit(interrupts
> > > disabled) to timer_start in Kworker/-297 thread.
> > > I have tried multiple times and always observed similar trace.
> > > Please help me in debugging the issue.
> > >
> > > Trace Logs:
> > >
> > > cyclicte-3307 0d...2.. 104489596us+: hrtimer_start:
> > > hrtimer=dfee9e98 function=hrtimer_wakeup expires=1587365915748
> > > softexpires=1587365865748
> > > cyclicte-3307 0d...3.. 104489599us+: sched_stat_runtime:
> > > comm=cyclictest pid=3307 runtime=119552 [ns] vruntime=22040816169
> > > [ns]
> > > cyclicte-3307 0d...3.. 104489602us!: sched_switch:
> > > prev_comm=cyclictest prev_pid=3307 prev_prio=120 prev_state=S ==>
> > > next_comm=swapper next_pid=0 next_prio=120
> > > <idle>-0 0d..h2.. 104489732us+: timer_interrupt_entry:
> > > pt_regs=c086fed0
> > > <idle>-0 0d..h3.. 104489733us : hrtimer_cancel:
> > > hrtimer=c0830240
> > > <idle>-0 0d..h2.. 104489735us+: hrtimer_expire_entry:
> > > hrtimer=c0830240 function=tick_sched_timer now=1587356002980
> > > <idle>-0 0d..h2.. 104489741us : softirq_raise: vec=1
> > > [action=TIMER]
> > > <idle>-0 0d..h2.. 104489743us+: softirq_raise: vec=9
> > > [action=RCU]
> > > <idle>-0 0d..h2.. 104489744us+: hrtimer_expire_exit:
> > > hrtimer=c0830240
> > > <idle>-0 0d..h3.. 104489746us+: hrtimer_start:
> > > hrtimer=c0830240 function=tick_sched_timer expires=1587360000000
> > > softexpires=1587360000000
> > > <idle>-0 0d..h2.. 104489749us+: timer_interrupt_exit:
> > > pt_regs=c086fed0
> > > <idle>-0 0d...5.. 104489751us+: sched_wakeup:
> > > comm=ksoftirqd/0
> > > pid=3 prio=98 success=1 target_cpu=000
> > > <idle>-0 0d...3.. 104489755us+: sched_switch:
> > > prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==>
> > > next_comm=ksoftirqd/0
> > > next_pid=3 next_prio=98
> > > ksoftirq-3 0....1.. 104489758us+: softirq_entry: vec=1
> > > [action=TIMER]
> > > ksoftirq-3 0....1.. 104489761us+: timer_cancel: timer=eb260d9c
> > > ksoftirq-3 0....1.. 104489762us+: timer_expire_entry:
> > > timer=eb260d9c function=delayed_work_timer_fn now=321839
> > > ksoftirq-3 0....1.. 104489765us+: workqueue_queue_work: work
> > > struct=eb260d8c function=phy_state_machine workqueue=eb803bc0
> > > req_cpu=1 cpu=0
> > > ksoftirq-3 0....1.. 104489767us+: workqueue_activate_work:
> > > work struct eb260d8c
> > > ksoftirq-3 0d...3.. 104489770us+: sched_wakeup:
> > > comm=kworker/0:1
> > > pid=297 prio=120 success=1 target_cpu=000
> > > ksoftirq-3 0....1.. 104489772us : timer_expire_exit:
> > > timer=eb260d9c
> > > ksoftirq-3 0....1.. 104489773us : timer_cancel: timer=eb260b9c
> > > ksoftirq-3 0....1.. 104489774us : timer_expire_entry:
> > > timer=eb260b9c function=delayed_work_timer_fn now=321839
> > > ksoftirq-3 0....1.. 104489775us : workqueue_queue_work: work
> > > struct=eb260b8c function=phy_state_machine workqueue=eb803bc0
> > > req_cpu=1 cpu=0
> > > ksoftirq-3 0....1.. 104489775us : workqueue_activate_work:
> > > work struct eb260b8c
> > > ksoftirq-3 0....1.. 104489777us : timer_expire_exit:
> > > timer=eb260b9c
> > > ksoftirq-3 0....1.. 104489778us : softirq_exit: vec=1
> > > [action=TIMER]
> > > ksoftirq-3 0....1.. 104489779us+: softirq_entry: vec=9
> > > [action=RCU]
> > > ksoftirq-3 0....1.. 104489781us : kmem_cache_free:
> > > call_site=c00fd3e4 ptr=d4f9f780
> > > ksoftirq-3 0....1.. 104489782us : kmem_cache_free:
> > > call_site=c0154bc0 ptr=eb7f8998
> > > ksoftirq-3 0....1.. 104489783us : kmem_cache_free:
> > > call_site=c01123ec ptr=e9937b80
> > > ksoftirq-3 0....1.. 104489784us+: softirq_exit: vec=9
> > > [action=RCU]
> > > ksoftirq-3 0d...3.. 104489788us+: sched_switch:
> > > prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=98 prev_state=S ==>
> > > next_comm=kworker/0:1 next_pid=297 next_prio=120
> > > kworker/-297 0....1.. 104489793us!: workqueue_execute_start:
> > > work struct eb260d8c: function phy_state_machine
> > > kworker/-297 0d..h1.. 104489916us+: irq_entry: pt_regs=eb917d50
> > > kworker/-297 0d..h1.. 104489920us : irq_handler_entry: irq=18
> > > name=serial
> > > kworker/-297 0d..h1.. 104489921us+: irq_handler_exit: irq=18
> > > ret=handled
> > > kworker/-297 0d..h3.. 104489923us+: sched_wakeup:
> > > comm=irq/18-serial
> > > pid=3267 prio=49 success=1 target_cpu=000
> > > kworker/-297 0dN.h1.. 104489925us+: irq_exit: pt_regs=eb917d50
> > > kworker/-297 0dN.h1.. 104489985us+: timer_interrupt_entry:
> > > pt_regs=eb917d60
> > > kworker/-297 0dN.h2.. 104489987us+: hrtimer_cancel:
> > > hrtimer=d4e8de78
> > > kworker/-297 0dN.h1.. 104489989us+: hrtimer_expire_entry:
> > > hrtimer=d4e8de78 function=hrtimer_wakeup now=1319135162835780883
> > > kworker/-297 0dN.h3.. 104489990us : sched_wakeup:
> > > comm=cyclictest
> > > pid=3308 prio=0 success=1 target_cpu=000
> > > kworker/-297 0dN.h1.. 104489992us+: hrtimer_expire_exit:
> > > hrtimer=d4e8de78
> > > kworker/-297 0dN.h1.. 104489993us!: timer_interrupt_exit:
> > > pt_regs=eb917d60
> > > kworker/-297 0.N..1.. 104490188us+: timer_start: timer=eb260d9c
> > > function=delayed_work_timer_fn expires=322089 [timeout=250]
> > > kworker/-297 0dN..3.. 104490190us+: sched_stat_runtime:
> > > comm=kworker/0:1 pid=297 runtime=136032 [ns] vruntime=22037952201
> > > [ns]
> > > kworker/-297 0d...3.. 104490192us+: sched_switch:
> > > prev_comm=kworker/0:1 prev_pid=297 prev_prio=120 prev_state=R+ ==>
> > > next_comm=cyclictest next_pid=3308 next_prio=0
> > > cyclicte-3308 0....1.. 104490194us+: sys_exit: NR 248 = 0
> > > cyclicte-3308 0....1.. 104490196us+: sys_enter: NR 246 (0,
> > > 487ff5e4, 0, 0, c8, f4240)
> > > cyclicte-3308 0....1.. 104490199us+: sys_exit: NR 246 = 0
> > > cyclicte-3308 0....1.. 104490228us+: mm_page_alloc: page=c0ed2920
> > > pfn=195657 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
> > > cyclicte-3308 0....1.. 104490240us+: sys_enter: NR 4 (5,
> > > 488003e4, 1f, 0, 0, 20)
> > > cyclicte-3308 0....... 104490244us+: tracing_mark_write: hit
> > > latency threshold (213 > 0)
> > > cyclicte-3308 0....1.. 104490247us+: sys_exit: NR 4 = 31
> > > cyclicte-3308 0....1.. 104490249us : sys_enter: NR 4 (4,
> > > 100855c4, 1, 0, 0, 20)
> > >
> > > Regards
> > > Priyanka
> > >
> > >
> > > --
> > > To unsubscribe from this list: send the line "unsubscribe linux-rt-
> > users"
> > > in the body of a message to majordomo@vger.kernel.org More majordomo
> > > info at http://vger.kernel.org/majordomo-info.html
> >
> >
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-rt-
> users"
> > in the body of a message to majordomo@vger.kernel.org More majordomo
> > info at http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply related [flat|nested] 6+ messages in thread
* RE: 3.8.10-rt6 : Observing high latency as preempt_schedule_irq:__schedule is not getting called
2013-05-21 7:01 ` 3.8.10-rt6 : Observing high latency as preempt_schedule_irq:__schedule is not getting called Jain Priyanka-B32167
@ 2013-05-28 4:01 ` Jain Priyanka-B32167
2013-05-31 11:11 ` Sebastian Andrzej Siewior
0 siblings, 1 reply; 6+ messages in thread
From: Jain Priyanka-B32167 @ 2013-05-28 4:01 UTC (permalink / raw)
To: linux-rt-users, Steven Rostedt, tglx, Sebastian Andrzej Siewior
Found the issue in arch/powerpc/kernel/entry_32.S.
Submitted below patch to linuxppc-dev@lists.ozlabs.org to fix this issue
--------------------------------------------------
[PATCH] powerpc/32bit:Store temporary result in r0 instead of r8
While returning from exception handling in case of PREEMPT enabled, _TIF_NEED_RESCHED bit is checked in TI_FLAGS (thread_info flag) of current task. Only if this bit is set, it should continue with the process of calling preempt_schedule_irq() to schedule highest priority task if available.
Current code assumes that r8 contains TI_FLAGS and check this for _TIF_NEED_RESCHED, but as r8 is modified in the code which executes before this check, r8 no longer contains the expected TI_FLAGS information.
As a result check for comparison with _TIF_NEED_RESCHED was failing even if NEED_RESCHED bit is set in the current thread_info flag. Due to this,
preempt_schedule_irq() and in turn scheduler was not getting called even if highest priority task is ready for execution.
So, store temporary results in r0 instead of r8 to prevent r8 from getting modified as subsequent code is dependent on its value.
Signed-off-by: Priyanka Jain <Priyanka.Jain@freescale.com>
---
arch/powerpc/kernel/entry_32.S | 2 +-
1 files changed, 1 insertions(+), 1 deletions(-)
diff --git a/arch/powerpc/kernel/entry_32.S b/arch/powerpc/kernel/entry_32.S index d22e73e..22b45a4 100644
--- a/arch/powerpc/kernel/entry_32.S
+++ b/arch/powerpc/kernel/entry_32.S
@@ -849,7 +849,7 @@ resume_kernel:
/* check current_thread_info, _TIF_EMULATE_STACK_STORE */
CURRENT_THREAD_INFO(r9, r1)
lwz r8,TI_FLAGS(r9)
- andis. r8,r8,_TIF_EMULATE_STACK_STORE@h
+ andis. r0,r8,_TIF_EMULATE_STACK_STORE@h
beq+ 1f
addi r8,r1,INT_FRAME_SIZE /* Get the kprobed function entry */
-----------------------------------------------------------------------------
> -----Original Message-----
> From: Jain Priyanka-B32167
> Sent: Tuesday, May 21, 2013 12:31 PM
> To: Jain Priyanka-B32167; linux-rt-users@vger.kernel.org; Steven Rostedt;
> tglx@linutronix.de; Sebastian Andrzej Siewior
> Cc: Dev Manish-R65866; Aggrwal Poonam-B10812; Srivastava Rajan-B34330
> Subject: 3.8.10-rt6 : Observing high latency as
> preempt_schedule_irq:__schedule is not getting called
>
>
> Setup: Single core PowerPC, 32-bit platform , Linux3.8.10-rt6
>
> 'preempt_schedule_irq()' is a function which generally gets called while
> exiting from IRQ context to call __schedule so that preemption
> opportunities do not get missed.
> I have added print just above call to __schedule()
>
> (START)
> diff --git a/kernel/sched/core.c b/kernel/sched/core.c index
> 3891f97..1f423c5 100644
> --- a/kernel/sched/core.c
> +++ b/kernel/sched/core.c
> @@ -3350,6 +3350,7 @@ asmlinkage void __sched preempt_schedule_irq(void)
> do {
> add_preempt_count(PREEMPT_ACTIVE);
> local_irq_enable();
> + printk("%s\n",__FUNCTION__);
> __schedule();
> local_irq_disable();
> sub_preempt_count(PREEMPT_ACTIVE);
> (END)
>
> As none of instance of this print is coming in kernel dump, it seems that
> 'preempt_schedule_irq:__schedule' is not getting called.
> So preemption opportunities while exiting from IRQ context(exception
> handling) are getting missed leading to increase in latencies.
>
> There are several changes in Kernel around this code specially the
> LAZY_PREEMPT feature, so I am not able to root-cause the exact issue.
> Please help me in fixing this.
>
> Regards
> Priyanka
>
>
> > -----Original Message-----
> > From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> > owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> > Sent: Tuesday, May 21, 2013 11:13 AM
> > To: linux-rt-users@vger.kernel.org; Steven Rostedt
> > Subject: RE: 3.8.10-rt6 : Observing high latency as timer_interrupt is
> > taking longer to exit
> >
> > Furthur debug analysis
> >
> > I am running cylictest with following settings:
> > ./cyclictest -a -n -p 99 -c 1 -d 0 -O latency-format -b 600 --
> > tracer=function_graph
> >
> >
> > It seems that even if 'N' (need rescheduled bit) is set in current
> > task and preemption disabled count is zero, context switching to
> > highest priority task which is cyclictest thread in this case is not
> > happening immediately. It is getting delayed adding to latency. Trace
> > capture attached.
> >
> > Please help me in identifying what can be the issue.
> >
> > Regards
> > Priyanka
> >
> > > -----Original Message-----
> > > From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> > > owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> > > Sent: Wednesday, May 15, 2013 3:49 PM
> > > To: linux-rt-users@vger.kernel.org
> > > Subject: RE: 3.8.10-rt6 : Observing high latency as timer_interrupt
> > > is taking longer to exit
> > >
> > > Hi,
> > >
> > > I have further debug the issue.
> > >
> > > The increase in latency issue is observed when kworker is in
> > > execution and timer_interrupt(hardirq) arrives.
> > > Upon completion of timer_interrupt, previous context should have
> > > immediately got restored.
> > > But a large time-gap (varying from 50us to 200us) is observed in
> > > restoration of kworker task.
> > > e.g in below context, 195us gap is observed in timer_interrupt_exit
> > > and timer_start (kworker).
> > >
> > > In complete trace, I have seen multiple entries of timer_interrupt.
> > > But exit is taking large time gap only when it arrives in context of
> > > kworker.
> > >
> > > Looking for some pointers as help to debug the issue.
> > >
> > > Regards
> > > Priyanka
> > >
> > > > -----Original Message-----
> > > > From: linux-rt-users-owner@vger.kernel.org [mailto:linux-rt-users-
> > > > owner@vger.kernel.org] On Behalf Of Jain Priyanka-B32167
> > > > Sent: Tuesday, May 14, 2013 4:10 PM
> > > > To: linux-rt-users@vger.kernel.org
> > > > Subject: 3.8.10-rt6 : Observing high latency as timer_interrupt is
> > > > taking longer to exit
> > > >
> > > > Hi,
> > > >
> > > > I am running PREEMPT_RT kernel on single-core PowerPC based
> > > > platform and using cyclictest tool to measure latency.
> > > >
> > > > Earlier I have used 2.6.33.9-rt31, With that kernel, latency has
> > > > always remained below 50us irrespective of the traffic.
> > > > With 3.8.10-rt6, latency is shooting beyond 200us irrespective of
> > > > the traffic - no load, heavy traffic conditions included. Issue is
> > > > generally reproduced within 10 minutes of run
> > > >
> > > > When I tried to debug the issue using ftrace, I am observing that
> > > > it is taking 200us for transition from
> > > > timer_interrupt_exit(interrupts
> > > > disabled) to timer_start in Kworker/-297 thread.
> > > > I have tried multiple times and always observed similar trace.
> > > > Please help me in debugging the issue.
> > > >
> > > > Trace Logs:
> > > >
> > > > cyclicte-3307 0d...2.. 104489596us+: hrtimer_start:
> > > > hrtimer=dfee9e98 function=hrtimer_wakeup expires=1587365915748
> > > > softexpires=1587365865748
> > > > cyclicte-3307 0d...3.. 104489599us+: sched_stat_runtime:
> > > > comm=cyclictest pid=3307 runtime=119552 [ns] vruntime=22040816169
> > > > [ns]
> > > > cyclicte-3307 0d...3.. 104489602us!: sched_switch:
> > > > prev_comm=cyclictest prev_pid=3307 prev_prio=120 prev_state=S ==>
> > > > next_comm=swapper next_pid=0 next_prio=120
> > > > <idle>-0 0d..h2.. 104489732us+: timer_interrupt_entry:
> > > > pt_regs=c086fed0
> > > > <idle>-0 0d..h3.. 104489733us : hrtimer_cancel:
> > > > hrtimer=c0830240
> > > > <idle>-0 0d..h2.. 104489735us+: hrtimer_expire_entry:
> > > > hrtimer=c0830240 function=tick_sched_timer now=1587356002980
> > > > <idle>-0 0d..h2.. 104489741us : softirq_raise: vec=1
> > > > [action=TIMER]
> > > > <idle>-0 0d..h2.. 104489743us+: softirq_raise: vec=9
> > > > [action=RCU]
> > > > <idle>-0 0d..h2.. 104489744us+: hrtimer_expire_exit:
> > > > hrtimer=c0830240
> > > > <idle>-0 0d..h3.. 104489746us+: hrtimer_start:
> > > > hrtimer=c0830240 function=tick_sched_timer expires=1587360000000
> > > > softexpires=1587360000000
> > > > <idle>-0 0d..h2.. 104489749us+: timer_interrupt_exit:
> > > > pt_regs=c086fed0
> > > > <idle>-0 0d...5.. 104489751us+: sched_wakeup:
> > > > comm=ksoftirqd/0
> > > > pid=3 prio=98 success=1 target_cpu=000
> > > > <idle>-0 0d...3.. 104489755us+: sched_switch:
> > > > prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==>
> > > > next_comm=ksoftirqd/0
> > > > next_pid=3 next_prio=98
> > > > ksoftirq-3 0....1.. 104489758us+: softirq_entry: vec=1
> > > > [action=TIMER]
> > > > ksoftirq-3 0....1.. 104489761us+: timer_cancel:
> > > > timer=eb260d9c
> > > > ksoftirq-3 0....1.. 104489762us+: timer_expire_entry:
> > > > timer=eb260d9c function=delayed_work_timer_fn now=321839
> > > > ksoftirq-3 0....1.. 104489765us+: workqueue_queue_work: work
> > > > struct=eb260d8c function=phy_state_machine workqueue=eb803bc0
> > > > req_cpu=1 cpu=0
> > > > ksoftirq-3 0....1.. 104489767us+: workqueue_activate_work:
> > > > work struct eb260d8c
> > > > ksoftirq-3 0d...3.. 104489770us+: sched_wakeup:
> > > > comm=kworker/0:1
> > > > pid=297 prio=120 success=1 target_cpu=000
> > > > ksoftirq-3 0....1.. 104489772us : timer_expire_exit:
> > > > timer=eb260d9c
> > > > ksoftirq-3 0....1.. 104489773us : timer_cancel:
> > > > timer=eb260b9c
> > > > ksoftirq-3 0....1.. 104489774us : timer_expire_entry:
> > > > timer=eb260b9c function=delayed_work_timer_fn now=321839
> > > > ksoftirq-3 0....1.. 104489775us : workqueue_queue_work: work
> > > > struct=eb260b8c function=phy_state_machine workqueue=eb803bc0
> > > > req_cpu=1 cpu=0
> > > > ksoftirq-3 0....1.. 104489775us : workqueue_activate_work:
> > > > work struct eb260b8c
> > > > ksoftirq-3 0....1.. 104489777us : timer_expire_exit:
> > > > timer=eb260b9c
> > > > ksoftirq-3 0....1.. 104489778us : softirq_exit: vec=1
> > > > [action=TIMER]
> > > > ksoftirq-3 0....1.. 104489779us+: softirq_entry: vec=9
> > > > [action=RCU]
> > > > ksoftirq-3 0....1.. 104489781us : kmem_cache_free:
> > > > call_site=c00fd3e4 ptr=d4f9f780
> > > > ksoftirq-3 0....1.. 104489782us : kmem_cache_free:
> > > > call_site=c0154bc0 ptr=eb7f8998
> > > > ksoftirq-3 0....1.. 104489783us : kmem_cache_free:
> > > > call_site=c01123ec ptr=e9937b80
> > > > ksoftirq-3 0....1.. 104489784us+: softirq_exit: vec=9
> > > > [action=RCU]
> > > > ksoftirq-3 0d...3.. 104489788us+: sched_switch:
> > > > prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=98 prev_state=S ==>
> > > > next_comm=kworker/0:1 next_pid=297 next_prio=120
> > > > kworker/-297 0....1.. 104489793us!: workqueue_execute_start:
> > > > work struct eb260d8c: function phy_state_machine
> > > > kworker/-297 0d..h1.. 104489916us+: irq_entry:
> > > > pt_regs=eb917d50
> > > > kworker/-297 0d..h1.. 104489920us : irq_handler_entry: irq=18
> > > > name=serial
> > > > kworker/-297 0d..h1.. 104489921us+: irq_handler_exit: irq=18
> > > > ret=handled
> > > > kworker/-297 0d..h3.. 104489923us+: sched_wakeup:
> > > > comm=irq/18-serial
> > > > pid=3267 prio=49 success=1 target_cpu=000
> > > > kworker/-297 0dN.h1.. 104489925us+: irq_exit: pt_regs=eb917d50
> > > > kworker/-297 0dN.h1.. 104489985us+: timer_interrupt_entry:
> > > > pt_regs=eb917d60
> > > > kworker/-297 0dN.h2.. 104489987us+: hrtimer_cancel:
> > > > hrtimer=d4e8de78
> > > > kworker/-297 0dN.h1.. 104489989us+: hrtimer_expire_entry:
> > > > hrtimer=d4e8de78 function=hrtimer_wakeup now=1319135162835780883
> > > > kworker/-297 0dN.h3.. 104489990us : sched_wakeup:
> > > > comm=cyclictest
> > > > pid=3308 prio=0 success=1 target_cpu=000
> > > > kworker/-297 0dN.h1.. 104489992us+: hrtimer_expire_exit:
> > > > hrtimer=d4e8de78
> > > > kworker/-297 0dN.h1.. 104489993us!: timer_interrupt_exit:
> > > > pt_regs=eb917d60
> > > > kworker/-297 0.N..1.. 104490188us+: timer_start:
> > > > timer=eb260d9c function=delayed_work_timer_fn expires=322089
> > > > [timeout=250]
> > > > kworker/-297 0dN..3.. 104490190us+: sched_stat_runtime:
> > > > comm=kworker/0:1 pid=297 runtime=136032 [ns] vruntime=22037952201
> > > > [ns]
> > > > kworker/-297 0d...3.. 104490192us+: sched_switch:
> > > > prev_comm=kworker/0:1 prev_pid=297 prev_prio=120 prev_state=R+ ==>
> > > > next_comm=cyclictest next_pid=3308 next_prio=0
> > > > cyclicte-3308 0....1.. 104490194us+: sys_exit: NR 248 = 0
> > > > cyclicte-3308 0....1.. 104490196us+: sys_enter: NR 246 (0,
> > > > 487ff5e4, 0, 0, c8, f4240)
> > > > cyclicte-3308 0....1.. 104490199us+: sys_exit: NR 246 = 0
> > > > cyclicte-3308 0....1.. 104490228us+: mm_page_alloc:
> > > > page=c0ed2920
> > > > pfn=195657 order=0 migratetype=2 gfp_flags=GFP_HIGHUSER_MOVABLE
> > > > cyclicte-3308 0....1.. 104490240us+: sys_enter: NR 4 (5,
> > > > 488003e4, 1f, 0, 0, 20)
> > > > cyclicte-3308 0....... 104490244us+: tracing_mark_write: hit
> > > > latency threshold (213 > 0)
> > > > cyclicte-3308 0....1.. 104490247us+: sys_exit: NR 4 = 31
> > > > cyclicte-3308 0....1.. 104490249us : sys_enter: NR 4 (4,
> > > > 100855c4, 1, 0, 0, 20)
> > > >
> > > > Regards
> > > > Priyanka
> > > >
> > > >
> > > > --
> > > > To unsubscribe from this list: send the line "unsubscribe
> > > > linux-rt-
> > > users"
> > > > in the body of a message to majordomo@vger.kernel.org More
> > > > majordomo info at http://vger.kernel.org/majordomo-info.html
> > >
> > >
> > > --
> > > To unsubscribe from this list: send the line "unsubscribe linux-rt-
> > users"
> > > in the body of a message to majordomo@vger.kernel.org More majordomo
> > > info at http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: 3.8.10-rt6 : Observing high latency as preempt_schedule_irq:__schedule is not getting called
2013-05-28 4:01 ` Jain Priyanka-B32167
@ 2013-05-31 11:11 ` Sebastian Andrzej Siewior
0 siblings, 0 replies; 6+ messages in thread
From: Sebastian Andrzej Siewior @ 2013-05-31 11:11 UTC (permalink / raw)
To: Jain Priyanka-B32167; +Cc: linux-rt-users, Steven Rostedt, tglx
On 05/28/2013 06:01 AM, Jain Priyanka-B32167 wrote:
> Submitted below patch to linuxppc-dev@lists.ozlabs.org to fix this issue
Thank you very much. The problem was introduced in v3.7-rc1 so it is a
v3.8-rt problem only.
Sebastian
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2013-05-31 11:11 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-05-14 10:40 3.8.10-rt6 : Observing high latency as timer_interrupt is taking longer to exit Jain Priyanka-B32167
2013-05-15 10:19 ` Jain Priyanka-B32167
2013-05-21 5:42 ` Jain Priyanka-B32167
2013-05-21 7:01 ` 3.8.10-rt6 : Observing high latency as preempt_schedule_irq:__schedule is not getting called Jain Priyanka-B32167
2013-05-28 4:01 ` Jain Priyanka-B32167
2013-05-31 11:11 ` Sebastian Andrzej Siewior
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.