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
