Re: [PATCH 4/5] sched/tracing: Show stacktrace for wakeup tracers
From: Steven Rostedt <rostedt@goodmis.org>
Date: 2019-01-16 03:25:12
Also in:
lkml
On Tue, 1 Jan 2019 23:46:13 +0800 Changbin Du [off-list ref] 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.
quoted hunk ↗ jump to hunk
Signed-off-by: Changbin Du <redacted> --- 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
quoted hunk ↗ jump to hunk
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);