lkml.org 
[lkml]   [2019]   [Jan]   [15]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
From
SubjectRe: [PATCH 4/5] sched/tracing: Show stacktrace for wakeup tracers
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);

\
 
 \ /
  Last update: 2019-01-16 04:26    [W:0.083 / U:3.632 seconds]
©2003-2018 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site