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@xxxxxxxxxxxxxxx [mailto:linux-rt-users- > owner@xxxxxxxxxxxxxxx] On Behalf Of Jain Priyanka-B32167 > Sent: Tuesday, May 14, 2013 4:10 PM > To: linux-rt-users@xxxxxxxxxxxxxxx > 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@xxxxxxxxxxxxxxx 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@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
