| Message ID | 20230117152125.268986282@goodmis.org (mailing list archive) |
|---|---|
| Headers | show |
| Series | tracing/histograms: Pass stacktrace from synthetic start event to end event | expand |
Hi Steve, On Tue, 2023-01-17 at 10:21 -0500, Steven Rostedt wrote: > I finally got around to implementing what I've been wanting to do for > a long > time! That is to pass stacktraces from the start to the end event of > a > synthetic event. Specifically, I need to get the stacktrace of a task Hey, this is really great! Thanks for doing this, and sorry I haven't gotten around to looking at it until now. Anyway, while playing with it I found a few things that didn't work as expected, and will send a few patches with some fixes shortly. Thanks again, this is really useful! Tom > as it > schedules out, but I don't want to see it until it schedules back in > and I > check the timings to show that it is longer than normal. That is now > done > with: > > # echo 's:block_lat pid_t pid; u64 delta; unsigned long[] stack;' > > dynamic_events > # echo 'hist:keys=next_pid:ts=common_timestamp.usecs,st=stacktrace > if prev_state == 2' >> events/sched/sched_switch/trigger > # echo 'hist:keys=prev_pid:delta=common_timestamp.usecs- > $ts,s=$st:onmax($delta).trace(block_lat,prev_pid,$delta,$s)' >> > events/sched/sched_switch/trigger > > The above creates a synthetic event that will trigger on the max > delta of a > task blocked in an uninterruptible state. It will show you the stack > trace > of where that occurred! > > # echo 1 > events/synthetic/block_lat/enable > # ls -lR > /dev/null > # cat trace > > # tracer: nop > # > # entries-in-buffer/entries-written: 2/2 #P:8 > # > # _-----=> irqs-off/BH-disabled > # / _----=> need-resched > # | / _---=> hardirq/softirq > # || / _--=> preempt-depth > # ||| / _-=> migrate-disable > # |||| / delay > # TASK-PID CPU# ||||| TIMESTAMP FUNCTION > # | | | ||||| | | > <idle>-0 [005] d..4. 521.164922: block_lat: pid=0 > delta=8322 stack=STACK: > => __schedule+0x448/0x7b0 > => schedule+0x5a/0xb0 > => io_schedule+0x42/0x70 > => bit_wait_io+0xd/0x60 > => __wait_on_bit+0x4b/0x140 > => out_of_line_wait_on_bit+0x91/0xb0 > => jbd2_journal_commit_transaction+0x1679/0x1a70 > => kjournald2+0xa9/0x280 > => kthread+0xe9/0x110 > => ret_from_fork+0x2c/0x50 > > <...>-2 [004] d..4. 525.184257: block_lat: pid=2 > delta=76 stack=STACK: > => __schedule+0x448/0x7b0 > => schedule+0x5a/0xb0 > => schedule_timeout+0x11a/0x150 > => wait_for_completion_killable+0x144/0x1f0 > => __kthread_create_on_node+0xe7/0x1e0 > => kthread_create_on_node+0x51/0x70 > => create_worker+0xcc/0x1a0 > => worker_thread+0x2ad/0x380 > => kthread+0xe9/0x110 > => ret_from_fork+0x2c/0x50 > > Changes since v1: > https://lore.kernel.org/linux-trace-kernel/20230117044010.838685230@goodmis.org/ > > - Fixed an issue with passing a stacktrace variable to another > variable. > > - Can now use the stacktrace in the histogram as well: > > # echo 'hist:delta.buckets=100,stack.stacktrace:sort=delta' > > events/synthetic/block_lat/trigger > # cat events/synthetic/block_lat/hist > > # event histogram > # > # trigger info: > hist:keys=delta.buckets=100,stacktrace:vals=hitcount:sort=delta.bucke > ts=100:size=2048 [active] > # > > { delta: ~ 0-99, stacktrace: > event_hist_trigger+0x464/0x480 > event_triggers_call+0x52/0xe0 > trace_event_buffer_commit+0x193/0x250 > trace_event_raw_event_sched_switch+0xfc/0x150 > __traceiter_sched_switch+0x41/0x60 > __schedule+0x448/0x7b0 > schedule_idle+0x26/0x40 > cpu_startup_entry+0x19/0x20 > start_secondary+0xed/0xf0 > secondary_startup_64_no_verify+0xe0/0xeb > } hitcount: 6 > { delta: ~ 0-99, stacktrace: > event_hist_trigger+0x464/0x480 > event_triggers_call+0x52/0xe0 > trace_event_buffer_commit+0x193/0x250 > trace_event_raw_event_sched_switch+0xfc/0x150 > __traceiter_sched_switch+0x41/0x60 > __schedule+0x448/0x7b0 > schedule_idle+0x26/0x40 > cpu_startup_entry+0x19/0x20 > __pfx_kernel_init+0x0/0x10 > arch_call_rest_init+0xa/0x24 > start_kernel+0x964/0x98d > secondary_startup_64_no_verify+0xe0/0xeb > } hitcount: 3 > [..] > { delta: ~ 8500-8599, stacktrace: > event_hist_trigger+0x464/0x480 > event_triggers_call+0x52/0xe0 > trace_event_buffer_commit+0x193/0x250 > trace_event_raw_event_sched_switch+0xfc/0x150 > __traceiter_sched_switch+0x41/0x60 > __schedule+0x448/0x7b0 > schedule_idle+0x26/0x40 > cpu_startup_entry+0x19/0x20 > start_secondary+0xed/0xf0 > secondary_startup_64_no_verify+0xe0/0xeb > } hitcount: 1 > > Totals: > Hits: 89 > Entries: 11 > Dropped: 0 > > > > Steven Rostedt (Google) (6): > tracing: Simplify calculating entry size using struct_size() > tracing: Allow stacktraces to be saved as histogram variables > tracing: Allow synthetic events to pass around stacktraces > tracing/histogram: Add stacktrace type > tracing/histogram: Document variable stacktrace > tracing/histogram: Add simple tests for stacktrace usage of > synthetic events > > ---- > Documentation/trace/histogram.rst | 129 > +++++++++++++++++++++ > kernel/trace/trace.c | 2 +- > kernel/trace/trace.h | 4 + > kernel/trace/trace_events_hist.c | 63 +++++++--- > kernel/trace/trace_events_synth.c | 83 > ++++++++++++- > kernel/trace/trace_synth.h | 1 + > .../inter-event/trigger-synthetic-event-stack.tc | 24 ++++ > .../inter-event/trigger-synthetic-event-syntax.tc | 6 + > 8 files changed, 294 insertions(+), 18 deletions(-) > create mode 100644 > tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger- > synthetic-event-stack.tc
I finally got around to implementing what I've been wanting to do for a long time! That is to pass stacktraces from the start to the end event of a synthetic event. Specifically, I need to get the stacktrace of a task as it schedules out, but I don't want to see it until it schedules back in and I check the timings to show that it is longer than normal. That is now done with: # echo 's:block_lat pid_t pid; u64 delta; unsigned long[] stack;' > dynamic_events # echo 'hist:keys=next_pid:ts=common_timestamp.usecs,st=stacktrace if prev_state == 2' >> events/sched/sched_switch/trigger # echo 'hist:keys=prev_pid:delta=common_timestamp.usecs-$ts,s=$st:onmax($delta).trace(block_lat,prev_pid,$delta,$s)' >> events/sched/sched_switch/trigger The above creates a synthetic event that will trigger on the max delta of a task blocked in an uninterruptible state. It will show you the stack trace of where that occurred! # echo 1 > events/synthetic/block_lat/enable # ls -lR > /dev/null # cat trace # tracer: nop # # entries-in-buffer/entries-written: 2/2 #P:8 # # _-----=> irqs-off/BH-disabled # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / _-=> migrate-disable # |||| / delay # TASK-PID CPU# ||||| TIMESTAMP FUNCTION # | | | ||||| | | <idle>-0 [005] d..4. 521.164922: block_lat: pid=0 delta=8322 stack=STACK: => __schedule+0x448/0x7b0 => schedule+0x5a/0xb0 => io_schedule+0x42/0x70 => bit_wait_io+0xd/0x60 => __wait_on_bit+0x4b/0x140 => out_of_line_wait_on_bit+0x91/0xb0 => jbd2_journal_commit_transaction+0x1679/0x1a70 => kjournald2+0xa9/0x280 => kthread+0xe9/0x110 => ret_from_fork+0x2c/0x50 <...>-2 [004] d..4. 525.184257: block_lat: pid=2 delta=76 stack=STACK: => __schedule+0x448/0x7b0 => schedule+0x5a/0xb0 => schedule_timeout+0x11a/0x150 => wait_for_completion_killable+0x144/0x1f0 => __kthread_create_on_node+0xe7/0x1e0 => kthread_create_on_node+0x51/0x70 => create_worker+0xcc/0x1a0 => worker_thread+0x2ad/0x380 => kthread+0xe9/0x110 => ret_from_fork+0x2c/0x50 Changes since v1: https://lore.kernel.org/linux-trace-kernel/20230117044010.838685230@goodmis.org/ - Fixed an issue with passing a stacktrace variable to another variable. - Can now use the stacktrace in the histogram as well: # echo 'hist:delta.buckets=100,stack.stacktrace:sort=delta' > events/synthetic/block_lat/trigger # cat events/synthetic/block_lat/hist # event histogram # # trigger info: hist:keys=delta.buckets=100,stacktrace:vals=hitcount:sort=delta.buckets=100:size=2048 [active] # { delta: ~ 0-99, stacktrace: event_hist_trigger+0x464/0x480 event_triggers_call+0x52/0xe0 trace_event_buffer_commit+0x193/0x250 trace_event_raw_event_sched_switch+0xfc/0x150 __traceiter_sched_switch+0x41/0x60 __schedule+0x448/0x7b0 schedule_idle+0x26/0x40 cpu_startup_entry+0x19/0x20 start_secondary+0xed/0xf0 secondary_startup_64_no_verify+0xe0/0xeb } hitcount: 6 { delta: ~ 0-99, stacktrace: event_hist_trigger+0x464/0x480 event_triggers_call+0x52/0xe0 trace_event_buffer_commit+0x193/0x250 trace_event_raw_event_sched_switch+0xfc/0x150 __traceiter_sched_switch+0x41/0x60 __schedule+0x448/0x7b0 schedule_idle+0x26/0x40 cpu_startup_entry+0x19/0x20 __pfx_kernel_init+0x0/0x10 arch_call_rest_init+0xa/0x24 start_kernel+0x964/0x98d secondary_startup_64_no_verify+0xe0/0xeb } hitcount: 3 [..] { delta: ~ 8500-8599, stacktrace: event_hist_trigger+0x464/0x480 event_triggers_call+0x52/0xe0 trace_event_buffer_commit+0x193/0x250 trace_event_raw_event_sched_switch+0xfc/0x150 __traceiter_sched_switch+0x41/0x60 __schedule+0x448/0x7b0 schedule_idle+0x26/0x40 cpu_startup_entry+0x19/0x20 start_secondary+0xed/0xf0 secondary_startup_64_no_verify+0xe0/0xeb } hitcount: 1 Totals: Hits: 89 Entries: 11 Dropped: 0 Steven Rostedt (Google) (6): tracing: Simplify calculating entry size using struct_size() tracing: Allow stacktraces to be saved as histogram variables tracing: Allow synthetic events to pass around stacktraces tracing/histogram: Add stacktrace type tracing/histogram: Document variable stacktrace tracing/histogram: Add simple tests for stacktrace usage of synthetic events ---- Documentation/trace/histogram.rst | 129 +++++++++++++++++++++ kernel/trace/trace.c | 2 +- kernel/trace/trace.h | 4 + kernel/trace/trace_events_hist.c | 63 +++++++--- kernel/trace/trace_events_synth.c | 83 ++++++++++++- kernel/trace/trace_synth.h | 1 + .../inter-event/trigger-synthetic-event-stack.tc | 24 ++++ .../inter-event/trigger-synthetic-event-syntax.tc | 6 + 8 files changed, 294 insertions(+), 18 deletions(-) create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc