From: Steven Rostedt <rostedt@goodmis.org>
To: linux-kernel@vger.kernel.org, linux-trace-kernel@vger.kernel.org
Cc: Masami Hiramatsu <mhiramat@kernel.org>,
Andrew Morton <akpm@linux-foundation.org>,
Tom Zanussi <zanussi@kernel.org>,
Ross Zwisler <zwisler@google.com>,
Ching-lin Yu <chinglinyu@google.com>
Subject: [PATCH 5/6 v2] tracing/histogram: Document variable stacktrace
Date: Tue, 17 Jan 2023 10:21:30 -0500 [thread overview]
Message-ID: <20230117152236.320181354@goodmis.org> (raw)
In-Reply-To: 20230117152125.268986282@goodmis.org
From: "Steven Rostedt (Google)" <rostedt@goodmis.org>
Add a little documentation (and a useful example) of how a stacktrace can
be used within a histogram variable and synthetic event.
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
Documentation/trace/histogram.rst | 129 ++++++++++++++++++++++++++++++
1 file changed, 129 insertions(+)
diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histogram.rst
index f95459aa984f..5c391328b9bb 100644
--- a/Documentation/trace/histogram.rst
+++ b/Documentation/trace/histogram.rst
@@ -81,6 +81,7 @@ Documentation written by Tom Zanussi
.usecs display a common_timestamp in microseconds
.percent display a number of percentage value
.graph display a bar-graph of a value
+ .stacktrace display as a stacktrace (must by a long[] type)
============= =================================================
Note that in general the semantics of a given field aren't
@@ -1786,6 +1787,8 @@ or assigned to a variable and referenced in a subsequent expression::
# echo 'hist:keys=next_pid:us_per_sec=1000000 ...' >> event/trigger
# echo 'hist:keys=next_pid:timestamp_secs=common_timestamp/$us_per_sec ...' >> event/trigger
+Variables can even hold stacktraces, which are useful with synthetic events.
+
2.2.2 Synthetic Events
----------------------
@@ -1940,6 +1943,132 @@ the ".buckets" modifier and specify a size (in this case groups of 10).
Entries: 16
Dropped: 0
+To save stacktraces, create a synthetic event with a field of type "unsigned long[]"
+or even just "long[]". For example, to see how long a task is blocked in an
+uninterruptible state:
+
+ # cd /sys/kernel/tracing
+ # 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
+ # echo 1 > events/synthetic/block_lat/enable
+ # 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
+
+A synthetic event that has a stacktrace field may use it as a key in histogram:
+
+ # 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: ~ 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+0x5a/0xb0
+ worker_thread+0xaf/0x380
+ kthread+0xe9/0x110
+ ret_from_fork+0x2c/0x50
+ } hitcount: 1
+ { delta: ~ 100-199, 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: 15
+ [..]
+ { 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
+
2.2.3 Hist trigger 'handlers' and 'actions'
-------------------------------------------
--
2.39.0
next prev parent reply other threads:[~2023-01-17 15:22 UTC|newest]
Thread overview: 8+ messages / expand[flat|nested] mbox.gz Atom feed top
2023-01-17 15:21 [PATCH 0/6 v2] tracing/histograms: Pass stacktrace from synthetic start event to end event Steven Rostedt
2023-01-17 15:21 ` [PATCH 1/6 v2] tracing: Simplify calculating entry size using struct_size() Steven Rostedt
2023-01-17 15:21 ` [PATCH 2/6 v2] tracing: Allow stacktraces to be saved as histogram variables Steven Rostedt
2023-01-17 15:21 ` [PATCH 3/6 v2] tracing: Allow synthetic events to pass around stacktraces Steven Rostedt
2023-01-17 15:21 ` [PATCH 4/6 v2] tracing/histogram: Add stacktrace type Steven Rostedt
2023-01-17 15:21 ` Steven Rostedt [this message]
2023-01-17 15:21 ` [PATCH 6/6 v2] tracing/histogram: Add simple tests for stacktrace usage of synthetic events Steven Rostedt
2023-02-10 21:25 ` [PATCH 0/6 v2] tracing/histograms: Pass stacktrace from synthetic start event to end event Tom Zanussi
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20230117152236.320181354@goodmis.org \
--to=rostedt@goodmis.org \
--cc=akpm@linux-foundation.org \
--cc=chinglinyu@google.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-trace-kernel@vger.kernel.org \
--cc=mhiramat@kernel.org \
--cc=zanussi@kernel.org \
--cc=zwisler@google.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.