On Tue, 1 Jan 2019 23:46:13 +0800
Changbin Du <changbin...@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...@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);
