RE: 3.8.10-rt6 : Observing high latency as timer_interrupt is taking longer to exit

[Jain Priyanka-B32167 <B32167@freescale.com>]

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