[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Message-ID: <20230116234528.40646b2a@rorschach.local.home>
Date: Mon, 16 Jan 2023 23:45:28 -0500
From: Steven Rostedt <rostedt@...dmis.org>
To: linux-kernel@...r.kernel.org, linux-trace-kernel@...r.kernel.org
Cc: Masami Hiramatsu <mhiramat@...nel.org>,
Andrew Morton <akpm@...ux-foundation.org>,
Ross Zwisler <zwisler@...gle.com>,
Tom Zanussi <zanussi@...nel.org>
Subject: Re: [PATCH 0/5] tracing/histograms: Pass stacktrace from synthetic
start event to end event
Bah, I forgot to Cc, Tom.
Tom, here's the lore link:
https://lore.kernel.org/linux-trace-kernel/20230117044010.838685230@goodmis.org/T/#m116ab617cc475b68589f42a0cfd6c1b2029b0e39
-- Steve
On Mon, 16 Jan 2023 23:40:10 -0500
Steven Rostedt <rostedt@...dmis.org> 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 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
>
> Steven Rostedt (Google) (5):
> 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: Document variable stacktrace
> tracing/histogram: Add simple tests for stacktrace usage of synthetic events
>
> ----
> Documentation/trace/histogram.rst | 49 +++++++++++++
> kernel/trace/trace.c | 2 +-
> kernel/trace/trace.h | 4 ++
> kernel/trace/trace_events_hist.c | 42 ++++++++---
> 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, 196 insertions(+), 15 deletions(-)
> create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-stack.tc
Powered by blists - more mailing lists