From: Jain Priyanka-B32167 <B32167@freescale.com>
To: "linux-rt-users@vger.kernel.org" <linux-rt-users@vger.kernel.org>
Subject: 3.8.10-rt6 : Observing high latency as timer_interrupt is taking longer to exit
Date: Tue, 14 May 2013 10:40:29 +0000 [thread overview]
Message-ID: <AC83832D6324604BB08FAE5A33553F190B386F60@039-SN2MPN1-013.039d.mgd.msft.net> (raw)
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
next reply other threads:[~2013-05-14 10:40 UTC|newest]
Thread overview: 6+ messages / expand[flat|nested] mbox.gz Atom feed top
2013-05-14 10:40 Jain Priyanka-B32167 [this message]
2013-05-15 10:19 ` 3.8.10-rt6 : Observing high latency as timer_interrupt is taking longer to exit 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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=AC83832D6324604BB08FAE5A33553F190B386F60@039-SN2MPN1-013.039d.mgd.msft.net \
--to=b32167@freescale.com \
--cc=linux-rt-users@vger.kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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.