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

quoted

-----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"

quoted

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