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