Re: [PATCH 4/5] sched/tracing: Show stacktrace for wakeup tracers

[Changbin Du]

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@xxxxxxxxx> 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@xxxxxxxxx>
> > ---
> >  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