Re: Preemptionirqsoff latency issue

Re: Preemptionirqsoff latency issue

[Peter Zijlstra]

On Fri, Jan 09, 2015 at 02:31:35PM +0530, Vaibhav Shinde wrote:
> Hi All,
> 
> I have been checking preemption/irqs off latency with ftrace to find out
> the reason for scheduling latency for my application -
> 
> echo 0 > options/function-trace
> echo preemptirqsoff > current_tracer
> echo 1 > tracing_on
> echo 0 > tracing_max_latency
> ./a.out                          /* Running my application */
> echo 0 > tracing_on
> 
> #
> # preemptirqsoff latency trace v1.1.5 on 3.10.33-g36cc57c-dirty
> # --------------------------------------------------------------------
> # latency: 5184 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:1)
> #    -----------------
> #    | task: kworker/0:3-67 (uid:0 nice:0 policy:0 rt_prio:0)
> #    -----------------
> #  => started at: __mutex_lock_slowpath
> #  => ended at:   schedule_preempt_disabled
> #
> #
> #                  _------=> CPU#
> #                 / _-----=> irqs-off
> #                | / _----=> need-resched
> #                || / _---=> hardirq/softirq
> #                ||| / _--=> preempt-depth
> #                |||| /     delay
> #  cmd     pid   ||||| time  |   caller
> #     \   /      |||||  \    |   /
> kworker/-67      0...1    1us!: __mutex_lock_slowpath
> kworker/-67      0.N.1 5183us+: schedule_preempt_disabled
> kworker/-67      0.N.1 5186us+: trace_preempt_on <-schedule_preempt_disabled
> kworker/-67      0.N.1 5223us : <stack trace>
> => sub_preempt_count
> => schedule_preempt_disabled
> => __mutex_lock_slowpath
> => mutex_lock
> 
> 
> - As per the traces, I am getting a preemption off in mutex_lock for
> 5184ms, which is really big value.
> - The mutext lock is called from my code,
> - what could be the issue that caused such a big latency ?

mutex_lock will spin wait for the owner of the lock IFF the owner is on
(another) CPU and the current CPU doesn't need to resched. And from the
trace we can see N (need_resched) is only set at the 5ms and then we
call schedule_preempt_disable() almost immediately.

If you're interested in scheduling latency you should be looking at the
delay between tasks waking up and tasks getting on the CPU. The above
few lines simply do not provide enough information.

Re: Preemptionirqsoff latency issue

[Steven Rostedt]

On Fri, 9 Jan 2015 20:19:51 +0530
Vaibhav Shinde <v.bhav.shinde@gmail.com> wrote:

> Hi Peter,
> 
> Thanks for you reply.
> 
> I am interested in scheduling latency, and using ftrace I see for my
> application suffering from it, that's why I am digging in preemption/irq
> disable time which might cause the latency.
> 
> My app runs on cpu0, while other cpus looks idle; as per my understanding
> from your comment owner of the mutex is on the cpu other than cpu0, and
> which is causing wait spin on cpu0.
> Can this be the reason why latency is caused ?
> If so, then I think I need to take care of the mutex lock which is called
> from my code.
> 

If you download and install the latest trace-cmd, you may be able to
get more information with its new command "profile".

 # trace-cmd profile -o  file  workload

Then look at the output in file.

To limit the running to tracing only the workload:

 # trace-cmd profile -o file -F -c workload

You'll need to use the latest that's in my repo. Use the master branch,
as it has all the above features.

 git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

-- Steve

Re: Preemptionirqsoff latency issue

[Davidlohr Bueso]

On Fri, 2015-01-09 at 20:19 +0530, Vaibhav Shinde wrote:
> My app runs on cpu0, while other cpus looks idle; as per my
> understanding from your comment owner of the mutex is on the cpu other
> than cpu0, and which is causing wait spin on cpu0.

The thing is, cpu0 is rescheduling too often, so you're falling out of
the spinning step.

Thanks,
Davidlohr