lkml.org 
[lkml]   [2019]   [Jan]   [16]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH 4/5] sched/tracing: Show stacktrace for wakeup tracers
Steven, I just send v2 of this one that has applied your 2 suggestions.
Please check. Thanks!

On Tue, Jan 15, 2019 at 10:25:00PM -0500, Steven Rostedt wrote:
> On Tue, 1 Jan 2019 23:46:13 +0800
> Changbin Du <changbin.du@gmail.com> wrote:
>
> > This align the behavior of wakeup tracers with irqsoff latency tracer
> > that we record stacktrace at the beginning and end of waking up. The
> > stacktrace shows us what is happening in the kernel.
>
> OK, so I've applied (locally) all of the patches in this series except
> this one.
>
> >
> > Signed-off-by: Changbin Du <changbin.du@gmail.com>
> > ---
> > kernel/trace/trace_sched_wakeup.c | 4 ++++
> > 1 file changed, 4 insertions(+)
> >
> > diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
> > index da5b6e012840..0ec136d408ff 100644
> > --- a/kernel/trace/trace_sched_wakeup.c
> > +++ b/kernel/trace/trace_sched_wakeup.c
> > @@ -474,6 +474,8 @@ probe_wakeup_sched_switch(void *ignore, bool preempt,
> > data = per_cpu_ptr(wakeup_trace->trace_buffer.data, wakeup_cpu);
> >
> > __trace_function(wakeup_trace, CALLER_ADDR0, CALLER_ADDR1, flags, pc);
> > + /* Skip 2 functions to get to the task switch function */
> > + __trace_stack(wakeup_trace, flags, 2, pc);
>
> 1) Just put in zero for skip. I found that with all the new updates to
> the unwinders, you can never get this number right :-(, as well as with
> gcc playing games, and retpolines and all that jazz.
>
> > tracing_sched_switch_trace(wakeup_trace, prev, next, flags, pc);
>
> 2) Have the stack trace go after the sched_switch trace, otherwise it
> looks funny:
>
> 285 us | 5) <idle>-0 | dN.2 | 1.632 us | }
> 286 us | 5) <idle>-0 | d..3 | 0.000 us | __schedule();
> <idle>-0 5d..3 299us : <stack trace>
> => schedule_idle
> => do_idle
> => cpu_startup_entry
> => start_secondary
> => secondary_startup_64
> 299 us | 5) <idle>-0 | d..3 | | /* 0:120:R ==> [005] 811: 98:R i915/signal:0 */
>
> Note, I removed the skip and moved the trace and it looks like this:
>
> 180 us | 3) <idle>-0 | dN.2 | 0.944 us | }
> 181 us | 3) <idle>-0 | d..3 | 0.000 us | __schedule();
> 181 us | 3) <idle>-0 | d..3 | | /* 0:120:R ==> [003] 25: 0:R migration/3 */
> <idle>-0 3d..3 195us : <stack trace>
> => probe_wakeup_sched_switch
> => __schedule
> => schedule_idle
> => do_idle
> => cpu_startup_entry
> => start_secondary
> => secondary_startup_64
>
> Yeah, it shows the "probe_wakeup_sched" but its better to show too much
> than not enough. I've had a hard time debugging some kernels because
> the skip was too high.
>
> Please resend this patch with the above updates. Just this patch.
>
> Thanks!
>
> -- Steve
>
> >
> > T0 = data->preempt_timestamp;
> > @@ -593,6 +595,8 @@ probe_wakeup(void *ignore, struct task_struct *p)
> > * it should be safe to use it here.
> > */
> > __trace_function(wakeup_trace, CALLER_ADDR1, CALLER_ADDR2, flags, pc);
> > + /* Skip 2 functions to get to the task wakeup function */
> > + __trace_stack(wakeup_trace, flags, 2, pc);
> >
> > out_locked:
> > arch_spin_unlock(&wakeup_lock);
>

--
Cheers,
Changbin Du

\
 
 \ /
  Last update: 2019-01-16 17:05    [W:0.076 / U:0.272 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site