* [PATCH 0/4] tracing/histogram: Some fixes for new stacktrace variables
@ 2023-02-10 21:33 Tom Zanussi
2023-02-10 21:33 ` [PATCH 1/4] tracing/histogram: Don't use strlen to find length of " Tom Zanussi
` (3 more replies)
0 siblings, 4 replies; 8+ messages in thread
From: Tom Zanussi @ 2023-02-10 21:33 UTC (permalink / raw)
To: rostedt
Cc: mhiramat, linux-kernel, linux-trace-kernel, akpm, zwisler, chinglinyu
Hi Steve,
Here are a few fixes for some problems I saw when playing around
with the new stacktrace variable/synthetic event patches.
Thanks,
Tom
Tom Zanussi (4):
tracing/histogram: Don't use strlen to find length of stacktrace
variables
tracing/histogram: Fix a few problems with stacktrace variable
printing
tracing/histogram: Fix stacktrace key
tracing/histogram: Fix stacktrace histogram Documententation
Documentation/trace/histogram.rst | 156 +++++++++++++++++-------------
kernel/trace/trace_events_hist.c | 72 +++++++++++---
kernel/trace/trace_events_synth.c | 7 +-
3 files changed, 153 insertions(+), 82 deletions(-)
--
2.34.1
^ permalink raw reply [flat|nested] 8+ messages in thread
* [PATCH 1/4] tracing/histogram: Don't use strlen to find length of stacktrace variables
2023-02-10 21:33 [PATCH 0/4] tracing/histogram: Some fixes for new stacktrace variables Tom Zanussi
@ 2023-02-10 21:33 ` Tom Zanussi
2023-02-13 15:24 ` Masami Hiramatsu
2023-02-10 21:33 ` [PATCH 2/4] tracing/histogram: Fix a few problems with stacktrace variable printing Tom Zanussi
` (2 subsequent siblings)
3 siblings, 1 reply; 8+ messages in thread
From: Tom Zanussi @ 2023-02-10 21:33 UTC (permalink / raw)
To: rostedt
Cc: mhiramat, linux-kernel, linux-trace-kernel, akpm, zwisler, chinglinyu
Because stacktraces are saved in dynamic strings,
trace_event_raw_event_synth() uses strlen to determine the length of
the stack. Stacktraces may contain 0-bytes, though, in the saved
addresses, so the length found and passed to reserve() will be too
small.
Fix this by using the first unsigned long in the stack variables to
store the actual number of elements in the stack and have
trace_event_raw_event_synth() use that to determine the length of the
stack.
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
kernel/trace/trace_events_hist.c | 12 ++++++++----
kernel/trace/trace_events_synth.c | 7 ++++++-
2 files changed, 14 insertions(+), 5 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 888b7a394ce5..76bd105988c6 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -3135,13 +3135,15 @@ static inline void __update_field_vars(struct tracing_map_elt *elt,
size = min(val->size, STR_VAR_LEN_MAX);
strscpy(str, val_str, size);
} else {
+ char *stack_start = str + sizeof(unsigned long);
int e;
- e = stack_trace_save((void *)str,
+ e = stack_trace_save((void *)stack_start,
HIST_STACKTRACE_DEPTH,
HIST_STACKTRACE_SKIP);
if (e < HIST_STACKTRACE_DEPTH - 1)
- ((unsigned long *)str)[e] = 0;
+ ((unsigned long *)stack_start)[e] = 0;
+ *((unsigned long *)str) = e;
}
var_val = (u64)(uintptr_t)str;
}
@@ -5133,13 +5135,15 @@ static void hist_trigger_elt_update(struct hist_trigger_data *hist_data,
size = min(hist_field->size, STR_VAR_LEN_MAX);
strscpy(str, val_str, size);
} else {
+ char *stack_start = str + sizeof(unsigned long);
int e;
- e = stack_trace_save((void *)str,
+ e = stack_trace_save((void *)stack_start,
HIST_STACKTRACE_DEPTH,
HIST_STACKTRACE_SKIP);
if (e < HIST_STACKTRACE_DEPTH - 1)
- ((unsigned long *)str)[e] = 0;
+ ((unsigned long *)stack_start)[e] = 0;
+ *((unsigned long *)str) = e;
}
hist_val = (u64)(uintptr_t)str;
}
diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
index d458d7a0dfd7..6209b23c863f 100644
--- a/kernel/trace/trace_events_synth.c
+++ b/kernel/trace/trace_events_synth.c
@@ -538,7 +538,12 @@ static notrace void trace_event_raw_event_synth(void *__data,
val_idx = var_ref_idx[field_pos];
str_val = (char *)(long)var_ref_vals[val_idx];
- len = kern_fetch_store_strlen((unsigned long)str_val);
+ if (event->dynamic_fields[i]->is_stack) {
+ len = *((unsigned long *)str_val);
+ len *= sizeof(unsigned long);
+ } else {
+ len = kern_fetch_store_strlen((unsigned long)str_val);
+ }
fields_size += len;
}
--
2.34.1
^ permalink raw reply related [flat|nested] 8+ messages in thread
* [PATCH 2/4] tracing/histogram: Fix a few problems with stacktrace variable printing
2023-02-10 21:33 [PATCH 0/4] tracing/histogram: Some fixes for new stacktrace variables Tom Zanussi
2023-02-10 21:33 ` [PATCH 1/4] tracing/histogram: Don't use strlen to find length of " Tom Zanussi
@ 2023-02-10 21:33 ` Tom Zanussi
2023-02-10 21:33 ` [PATCH 3/4] tracing/histogram: Fix stacktrace key Tom Zanussi
2023-02-10 21:33 ` [PATCH 4/4] tracing/histogram: Fix stacktrace histogram Documententation Tom Zanussi
3 siblings, 0 replies; 8+ messages in thread
From: Tom Zanussi @ 2023-02-10 21:33 UTC (permalink / raw)
To: rostedt
Cc: mhiramat, linux-kernel, linux-trace-kernel, akpm, zwisler, chinglinyu
Currently, there are a few problems when printing hist triggers and
trace output when using stacktrace variables. This fixes the problems
seen below:
# echo 'hist:keys=delta.buckets=100,stack.stacktrace:sort=delta' > /sys/kernel/debug/tracing/events/synthetic/block_lat/trigger
# cat /sys/kernel/debug/tracing/events/synthetic/block_lat/trigger
hist:keys=delta.buckets=100,stacktrace:vals=hitcount:sort=delta.buckets=100:size=2048 [active]
# echo 'hist:keys=next_pid:ts=common_timestamp.usecs,st=stacktrace if prev_state == 2' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
# cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
hist:keys=next_pid:vals=hitcount:ts=common_timestamp.usecs,st=stacktrace.stacktrace:sort=hitcount:size=2048:clock=global if prev_state == 2 [active]
and also in the trace output (should be stack.stacktrace):
{ delta: ~ 100-199, stacktrace __schedule+0xa19/0x1520
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
kernel/trace/trace_events_hist.c | 26 ++++++++++++++++++--------
1 file changed, 18 insertions(+), 8 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 76bd105988c6..a58380702491 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1356,9 +1356,12 @@ static const char *hist_field_name(struct hist_field *field,
field_name = field->name;
} else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
field_name = "common_timestamp";
- else if (field->flags & HIST_FIELD_FL_STACKTRACE)
- field_name = "stacktrace";
- else if (field->flags & HIST_FIELD_FL_HITCOUNT)
+ else if (field->flags & HIST_FIELD_FL_STACKTRACE) {
+ if (field->field)
+ field_name = field->field->name;
+ else
+ field_name = "stacktrace";
+ } else if (field->flags & HIST_FIELD_FL_HITCOUNT)
field_name = "hitcount";
if (field_name == NULL)
@@ -5334,7 +5337,10 @@ static void hist_trigger_print_key(struct seq_file *m,
seq_printf(m, "%s: %-30s[%3llu]", field_name,
syscall_name, uval);
} else if (key_field->flags & HIST_FIELD_FL_STACKTRACE) {
- seq_puts(m, "stacktrace:\n");
+ if (key_field->field)
+ seq_printf(m, "%s.stacktrace", key_field->field->name);
+ else
+ seq_puts(m, "stacktrace:\n");
hist_trigger_stacktrace_print(m,
key + key_field->offset,
HIST_STACKTRACE_DEPTH);
@@ -5879,7 +5885,8 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
if (hist_field->flags) {
if (!(hist_field->flags & HIST_FIELD_FL_VAR_REF) &&
- !(hist_field->flags & HIST_FIELD_FL_EXPR)) {
+ !(hist_field->flags & HIST_FIELD_FL_EXPR) &&
+ !(hist_field->flags & HIST_FIELD_FL_STACKTRACE)) {
const char *flags = get_hist_field_flags(hist_field);
if (flags)
@@ -5912,9 +5919,12 @@ static int event_hist_trigger_print(struct seq_file *m,
if (i > hist_data->n_vals)
seq_puts(m, ",");
- if (field->flags & HIST_FIELD_FL_STACKTRACE)
- seq_puts(m, "stacktrace");
- else
+ if (field->flags & HIST_FIELD_FL_STACKTRACE) {
+ if (field->field)
+ seq_printf(m, "%s.stacktrace", field->field->name);
+ else
+ seq_puts(m, "stacktrace");
+ } else
hist_field_print(m, field);
}
--
2.34.1
^ permalink raw reply related [flat|nested] 8+ messages in thread
* [PATCH 3/4] tracing/histogram: Fix stacktrace key
2023-02-10 21:33 [PATCH 0/4] tracing/histogram: Some fixes for new stacktrace variables Tom Zanussi
2023-02-10 21:33 ` [PATCH 1/4] tracing/histogram: Don't use strlen to find length of " Tom Zanussi
2023-02-10 21:33 ` [PATCH 2/4] tracing/histogram: Fix a few problems with stacktrace variable printing Tom Zanussi
@ 2023-02-10 21:33 ` Tom Zanussi
2023-02-10 23:07 ` kernel test robot
2023-02-10 21:33 ` [PATCH 4/4] tracing/histogram: Fix stacktrace histogram Documententation Tom Zanussi
3 siblings, 1 reply; 8+ messages in thread
From: Tom Zanussi @ 2023-02-10 21:33 UTC (permalink / raw)
To: rostedt
Cc: mhiramat, linux-kernel, linux-trace-kernel, akpm, zwisler, chinglinyu
The current code will always use the current stacktrace as a key even
if a stacktrace contained in a specific event field was specified.
For example, we expect to use the 'unsigned long[] stack' field in the
below event in the histogram:
# echo 's:block_lat pid_t pid; u64 delta; unsigned long[] stack;' > /sys/kernel/debug/tracing/dynamic_events
# echo 'hist:keys=delta.buckets=100,stack.stacktrace:sort=delta' > /sys/kernel/debug/tracing/events/synthetic/block_lat/trigger
But in fact, when we type out the trigger, we see that it's using the
plain old global 'stacktrace' as the key, which is just the stacktrace
when the event was hit and not the stacktrace contained in the event,
which is what we want:
# cat /sys/kernel/debug/tracing/events/synthetic/block_lat/trigger
hist:keys=delta.buckets=100,stacktrace:vals=hitcount:sort=delta.buckets=100:size=2048 [active]
And in fact, there's no code to actually retrieve it from the event,
so we need to add HIST_FIELD_FN_STACK and hist_field_stack() to get it
and hook it into the trigger code. For now, since the stack is just
using dynamic strings, this could just use the dynamic string
function, but it seems cleaner to have a dedicated function an be able
to tweak independently as necessary.
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
kernel/trace/trace_events_hist.c | 34 +++++++++++++++++++++++++++++---
1 file changed, 31 insertions(+), 3 deletions(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index a58380702491..eb812cfdaa88 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -135,6 +135,7 @@ enum hist_field_fn {
HIST_FIELD_FN_DIV_NOT_POWER2,
HIST_FIELD_FN_DIV_MULT_SHIFT,
HIST_FIELD_FN_EXECNAME,
+ HIST_FIELD_FN_STACK,
};
/*
@@ -1982,7 +1983,10 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
}
if (flags & HIST_FIELD_FL_STACKTRACE) {
- hist_field->fn_num = HIST_FIELD_FN_NOP;
+ if (field)
+ hist_field->fn_num = HIST_FIELD_FN_STACK;
+ else
+ hist_field->fn_num = HIST_FIELD_FN_NOP;
hist_field->size = HIST_STACKTRACE_SIZE;
hist_field->type = kstrdup_const("unsigned long[]", GFP_KERNEL);
if (!hist_field->type)
@@ -4269,6 +4273,19 @@ static u64 hist_field_execname(struct hist_field *hist_field,
return (u64)(unsigned long)(elt_data->comm);
}
+static u64 hist_field_stack(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct trace_buffer *buffer,
+ struct ring_buffer_event *rbe,
+ void *event)
+{
+ u32 str_item = *(u32 *)(event + hist_field->field->offset);
+ int str_loc = str_item & 0xffff;
+ char *addr = (char *)(event + str_loc);
+
+ return (u64)(unsigned long)addr;
+}
+
static u64 hist_fn_call(struct hist_field *hist_field,
struct tracing_map_elt *elt,
struct trace_buffer *buffer,
@@ -4332,6 +4349,8 @@ static u64 hist_fn_call(struct hist_field *hist_field,
return div_by_mult_and_shift(hist_field, elt, buffer, rbe, event);
case HIST_FIELD_FN_EXECNAME:
return hist_field_execname(hist_field, elt, buffer, rbe, event);
+ case HIST_FIELD_FN_STACK:
+ return hist_field_stack(hist_field, elt, buffer, rbe, event);
default:
return 0;
}
@@ -5233,8 +5252,17 @@ static void event_hist_trigger(struct event_trigger_data *data,
if (key_field->flags & HIST_FIELD_FL_STACKTRACE) {
memset(entries, 0, HIST_STACKTRACE_SIZE);
- stack_trace_save(entries, HIST_STACKTRACE_DEPTH,
- HIST_STACKTRACE_SKIP);
+ if (key_field->field) {
+ unsigned long *stack, n_entries;
+
+ field_contents = hist_fn_call(key_field, elt, buffer, rbe, rec);
+ stack = (unsigned long *)field_contents;
+ n_entries = *stack;
+ memcpy(entries, ++stack, n_entries * sizeof(unsigned long));
+ } else {
+ stack_trace_save(entries, HIST_STACKTRACE_DEPTH,
+ HIST_STACKTRACE_SKIP);
+ }
key = entries;
} else {
field_contents = hist_fn_call(key_field, elt, buffer, rbe, rec);
--
2.34.1
^ permalink raw reply related [flat|nested] 8+ messages in thread
* [PATCH 4/4] tracing/histogram: Fix stacktrace histogram Documententation
2023-02-10 21:33 [PATCH 0/4] tracing/histogram: Some fixes for new stacktrace variables Tom Zanussi
` (2 preceding siblings ...)
2023-02-10 21:33 ` [PATCH 3/4] tracing/histogram: Fix stacktrace key Tom Zanussi
@ 2023-02-10 21:33 ` Tom Zanussi
3 siblings, 0 replies; 8+ messages in thread
From: Tom Zanussi @ 2023-02-10 21:33 UTC (permalink / raw)
To: rostedt
Cc: mhiramat, linux-kernel, linux-trace-kernel, akpm, zwisler, chinglinyu
Fix a small problem with the histogram specification in the
Documentation, and change the example to show output using a
stacktrace field rather than the global stacktrace.
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
Documentation/trace/histogram.rst | 156 +++++++++++++++++-------------
1 file changed, 90 insertions(+), 66 deletions(-)
diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histogram.rst
index 5c391328b9bb..d024cdae4fbd 100644
--- a/Documentation/trace/histogram.rst
+++ b/Documentation/trace/histogram.rst
@@ -1992,82 +1992,106 @@ uninterruptible state:
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
+ # echo 'hist:keys=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]
+ # trigger info: hist:keys=delta.buckets=100,stack.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
+ { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
+ schedule+0x6b/0x110
+ io_schedule+0x46/0x80
+ bit_wait_io+0x11/0x80
+ __wait_on_bit+0x4e/0x120
+ out_of_line_wait_on_bit+0x8d/0xb0
+ __wait_on_buffer+0x33/0x40
+ jbd2_journal_commit_transaction+0x155a/0x19b0
+ kjournald2+0xab/0x270
+ kthread+0xfa/0x130
+ ret_from_fork+0x29/0x50
+ } hitcount: 1
+ { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
+ schedule+0x6b/0x110
+ io_schedule+0x46/0x80
+ rq_qos_wait+0xd0/0x170
+ wbt_wait+0x9e/0xf0
+ __rq_qos_throttle+0x25/0x40
+ blk_mq_submit_bio+0x2c3/0x5b0
+ __submit_bio+0xff/0x190
+ submit_bio_noacct_nocheck+0x25b/0x2b0
+ submit_bio_noacct+0x20b/0x600
+ submit_bio+0x28/0x90
+ ext4_bio_write_page+0x1e0/0x8c0
+ mpage_submit_page+0x60/0x80
+ mpage_process_page_bufs+0x16c/0x180
+ mpage_prepare_extent_to_map+0x23f/0x530
+ } hitcount: 1
+ { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
+ schedule+0x6b/0x110
+ schedule_hrtimeout_range_clock+0x97/0x110
+ schedule_hrtimeout_range+0x13/0x20
+ usleep_range_state+0x65/0x90
+ __intel_wait_for_register+0x1c1/0x230 [i915]
+ intel_psr_wait_for_idle_locked+0x171/0x2a0 [i915]
+ intel_pipe_update_start+0x169/0x360 [i915]
+ intel_update_crtc+0x112/0x490 [i915]
+ skl_commit_modeset_enables+0x199/0x600 [i915]
+ intel_atomic_commit_tail+0x7c4/0x1080 [i915]
+ intel_atomic_commit_work+0x12/0x20 [i915]
+ process_one_work+0x21c/0x3f0
+ worker_thread+0x50/0x3e0
+ kthread+0xfa/0x130
} 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
+ { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
+ schedule+0x6b/0x110
+ schedule_timeout+0x11e/0x160
+ __wait_for_common+0x8f/0x190
+ wait_for_completion+0x24/0x30
+ __flush_work.isra.0+0x1cc/0x360
+ flush_work+0xe/0x20
+ drm_mode_rmfb+0x18b/0x1d0 [drm]
+ drm_mode_rmfb_ioctl+0x10/0x20 [drm]
+ drm_ioctl_kernel+0xb8/0x150 [drm]
+ drm_ioctl+0x243/0x560 [drm]
+ __x64_sys_ioctl+0x92/0xd0
+ do_syscall_64+0x59/0x90
+ entry_SYSCALL_64_after_hwframe+0x72/0xdc
} 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
+ { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
+ schedule+0x6b/0x110
+ schedule_timeout+0x87/0x160
+ __wait_for_common+0x8f/0x190
+ wait_for_completion_timeout+0x1d/0x30
+ drm_atomic_helper_wait_for_flip_done+0x57/0x90 [drm_kms_helper]
+ intel_atomic_commit_tail+0x8ce/0x1080 [i915]
+ intel_atomic_commit_work+0x12/0x20 [i915]
+ process_one_work+0x21c/0x3f0
+ worker_thread+0x50/0x3e0
+ kthread+0xfa/0x130
+ ret_from_fork+0x29/0x50
+ } hitcount: 1
+ { delta: ~ 100-199, stack.stacktrace __schedule+0xa19/0x1520
+ schedule+0x6b/0x110
+ schedule_hrtimeout_range_clock+0x97/0x110
+ schedule_hrtimeout_range+0x13/0x20
+ usleep_range_state+0x65/0x90
+ pci_set_low_power_state+0x17f/0x1f0
+ pci_set_power_state+0x49/0x250
+ pci_finish_runtime_suspend+0x4a/0x90
+ pci_pm_runtime_suspend+0xcb/0x1b0
+ __rpm_callback+0x48/0x120
+ rpm_callback+0x67/0x70
+ rpm_suspend+0x167/0x780
+ rpm_idle+0x25a/0x380
+ pm_runtime_work+0x93/0xc0
+ process_one_work+0x21c/0x3f0
} hitcount: 1
Totals:
- Hits: 89
- Entries: 11
- Dropped: 0
+ Hits: 10
+ Entries: 7
+ Dropped: 0
2.2.3 Hist trigger 'handlers' and 'actions'
-------------------------------------------
--
2.34.1
^ permalink raw reply related [flat|nested] 8+ messages in thread
* Re: [PATCH 3/4] tracing/histogram: Fix stacktrace key
2023-02-10 21:33 ` [PATCH 3/4] tracing/histogram: Fix stacktrace key Tom Zanussi
@ 2023-02-10 23:07 ` kernel test robot
0 siblings, 0 replies; 8+ messages in thread
From: kernel test robot @ 2023-02-10 23:07 UTC (permalink / raw)
To: Tom Zanussi, rostedt
Cc: oe-kbuild-all, mhiramat, linux-kernel, linux-trace-kernel, akpm,
zwisler, chinglinyu
Hi Tom,
Thank you for the patch! Perhaps something to improve:
[auto build test WARNING on next-20230210]
[cannot apply to linus/master rostedt-trace/for-next rostedt-trace/for-next-urgent v6.2-rc7 v6.2-rc6 v6.2-rc5 v6.2-rc7]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]
url: https://github.com/intel-lab-lkp/linux/commits/Tom-Zanussi/tracing-histogram-Don-t-use-strlen-to-find-length-of-stacktrace-variables/20230211-053647
patch link: https://lore.kernel.org/r/11aa614c82976adbfa4ea763dbe885b5fb01d59c.1676063532.git.zanussi%40kernel.org
patch subject: [PATCH 3/4] tracing/histogram: Fix stacktrace key
config: parisc-allyesconfig (https://download.01.org/0day-ci/archive/20230211/202302110636.O2hlhbxt-lkp@intel.com/config)
compiler: hppa-linux-gcc (GCC) 12.1.0
reproduce (this is a W=1 build):
wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
chmod +x ~/bin/make.cross
# https://github.com/intel-lab-lkp/linux/commit/797160b4aa615acf656dc6c8ef6fe41b3c2b84a2
git remote add linux-review https://github.com/intel-lab-lkp/linux
git fetch --no-tags linux-review Tom-Zanussi/tracing-histogram-Don-t-use-strlen-to-find-length-of-stacktrace-variables/20230211-053647
git checkout 797160b4aa615acf656dc6c8ef6fe41b3c2b84a2
# save the config file
mkdir build_dir && cp config build_dir/.config
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-12.1.0 make.cross W=1 O=build_dir ARCH=parisc olddefconfig
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-12.1.0 make.cross W=1 O=build_dir ARCH=parisc SHELL=/bin/bash kernel/trace/
If you fix the issue, kindly add following tag where applicable
| Reported-by: kernel test robot <lkp@intel.com>
| Link: https://lore.kernel.org/oe-kbuild-all/202302110636.O2hlhbxt-lkp@intel.com/
All warnings (new ones prefixed by >>):
kernel/trace/trace_events_hist.c: In function 'event_hist_trigger':
>> kernel/trace/trace_events_hist.c:5261:41: warning: cast to pointer from integer of different size [-Wint-to-pointer-cast]
5261 | stack = (unsigned long *)field_contents;
| ^
vim +5261 kernel/trace/trace_events_hist.c
5231
5232 static void event_hist_trigger(struct event_trigger_data *data,
5233 struct trace_buffer *buffer, void *rec,
5234 struct ring_buffer_event *rbe)
5235 {
5236 struct hist_trigger_data *hist_data = data->private_data;
5237 bool use_compound_key = (hist_data->n_keys > 1);
5238 unsigned long entries[HIST_STACKTRACE_DEPTH];
5239 u64 var_ref_vals[TRACING_MAP_VARS_MAX];
5240 char compound_key[HIST_KEY_SIZE_MAX];
5241 struct tracing_map_elt *elt = NULL;
5242 struct hist_field *key_field;
5243 u64 field_contents;
5244 void *key = NULL;
5245 unsigned int i;
5246
5247 if (unlikely(!rbe))
5248 return;
5249
5250 memset(compound_key, 0, hist_data->key_size);
5251
5252 for_each_hist_key_field(i, hist_data) {
5253 key_field = hist_data->fields[i];
5254
5255 if (key_field->flags & HIST_FIELD_FL_STACKTRACE) {
5256 memset(entries, 0, HIST_STACKTRACE_SIZE);
5257 if (key_field->field) {
5258 unsigned long *stack, n_entries;
5259
5260 field_contents = hist_fn_call(key_field, elt, buffer, rbe, rec);
> 5261 stack = (unsigned long *)field_contents;
5262 n_entries = *stack;
5263 memcpy(entries, ++stack, n_entries * sizeof(unsigned long));
5264 } else {
5265 stack_trace_save(entries, HIST_STACKTRACE_DEPTH,
5266 HIST_STACKTRACE_SKIP);
5267 }
5268 key = entries;
5269 } else {
5270 field_contents = hist_fn_call(key_field, elt, buffer, rbe, rec);
5271 if (key_field->flags & HIST_FIELD_FL_STRING) {
5272 key = (void *)(unsigned long)field_contents;
5273 use_compound_key = true;
5274 } else
5275 key = (void *)&field_contents;
5276 }
5277
5278 if (use_compound_key)
5279 add_to_key(compound_key, key, key_field, rec);
5280 }
5281
5282 if (use_compound_key)
5283 key = compound_key;
5284
5285 if (hist_data->n_var_refs &&
5286 !resolve_var_refs(hist_data, key, var_ref_vals, false))
5287 return;
5288
5289 elt = tracing_map_insert(hist_data->map, key);
5290 if (!elt)
5291 return;
5292
5293 hist_trigger_elt_update(hist_data, elt, buffer, rec, rbe, var_ref_vals);
5294
5295 if (resolve_var_refs(hist_data, key, var_ref_vals, true))
5296 hist_trigger_actions(hist_data, elt, buffer, rec, rbe, key, var_ref_vals);
5297 }
5298
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [PATCH 1/4] tracing/histogram: Don't use strlen to find length of stacktrace variables
2023-02-10 21:33 ` [PATCH 1/4] tracing/histogram: Don't use strlen to find length of " Tom Zanussi
@ 2023-02-13 15:24 ` Masami Hiramatsu
2023-02-13 15:56 ` Steven Rostedt
0 siblings, 1 reply; 8+ messages in thread
From: Masami Hiramatsu @ 2023-02-13 15:24 UTC (permalink / raw)
To: Tom Zanussi
Cc: rostedt, mhiramat, linux-kernel, linux-trace-kernel, akpm,
zwisler, chinglinyu
On Fri, 10 Feb 2023 15:33:03 -0600
Tom Zanussi <zanussi@kernel.org> wrote:
> Because stacktraces are saved in dynamic strings,
> trace_event_raw_event_synth() uses strlen to determine the length of
> the stack. Stacktraces may contain 0-bytes, though, in the saved
> addresses, so the length found and passed to reserve() will be too
> small.
Good catch!
>
> Fix this by using the first unsigned long in the stack variables to
> store the actual number of elements in the stack and have
> trace_event_raw_event_synth() use that to determine the length of the
> stack.
>
> Signed-off-by: Tom Zanussi <zanussi@kernel.org>
> ---
> kernel/trace/trace_events_hist.c | 12 ++++++++----
> kernel/trace/trace_events_synth.c | 7 ++++++-
> 2 files changed, 14 insertions(+), 5 deletions(-)
>
> diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
> index 888b7a394ce5..76bd105988c6 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -3135,13 +3135,15 @@ static inline void __update_field_vars(struct tracing_map_elt *elt,
> size = min(val->size, STR_VAR_LEN_MAX);
> strscpy(str, val_str, size);
> } else {
> + char *stack_start = str + sizeof(unsigned long);
> int e;
>
> - e = stack_trace_save((void *)str,
> + e = stack_trace_save((void *)stack_start,
> HIST_STACKTRACE_DEPTH,
> HIST_STACKTRACE_SKIP);
BTW, the size of "str" is enough to store HIST_STACKTRACE_DEPTH?
In string case,
size = min(val->size, STR_VAR_LEN_MAX);
will limit the max size.
Thank you,
> if (e < HIST_STACKTRACE_DEPTH - 1)
> - ((unsigned long *)str)[e] = 0;
> + ((unsigned long *)stack_start)[e] = 0;
> + *((unsigned long *)str) = e;
> }
> var_val = (u64)(uintptr_t)str;
> }
> @@ -5133,13 +5135,15 @@ static void hist_trigger_elt_update(struct hist_trigger_data *hist_data,
> size = min(hist_field->size, STR_VAR_LEN_MAX);
> strscpy(str, val_str, size);
> } else {
> + char *stack_start = str + sizeof(unsigned long);
> int e;
>
> - e = stack_trace_save((void *)str,
> + e = stack_trace_save((void *)stack_start,
> HIST_STACKTRACE_DEPTH,
> HIST_STACKTRACE_SKIP);
> if (e < HIST_STACKTRACE_DEPTH - 1)
> - ((unsigned long *)str)[e] = 0;
> + ((unsigned long *)stack_start)[e] = 0;
> + *((unsigned long *)str) = e;
> }
> hist_val = (u64)(uintptr_t)str;
> }
> diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
> index d458d7a0dfd7..6209b23c863f 100644
> --- a/kernel/trace/trace_events_synth.c
> +++ b/kernel/trace/trace_events_synth.c
> @@ -538,7 +538,12 @@ static notrace void trace_event_raw_event_synth(void *__data,
> val_idx = var_ref_idx[field_pos];
> str_val = (char *)(long)var_ref_vals[val_idx];
>
> - len = kern_fetch_store_strlen((unsigned long)str_val);
> + if (event->dynamic_fields[i]->is_stack) {
> + len = *((unsigned long *)str_val);
> + len *= sizeof(unsigned long);
> + } else {
> + len = kern_fetch_store_strlen((unsigned long)str_val);
> + }
>
> fields_size += len;
> }
> --
> 2.34.1
>
--
Masami Hiramatsu (Google) <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [PATCH 1/4] tracing/histogram: Don't use strlen to find length of stacktrace variables
2023-02-13 15:24 ` Masami Hiramatsu
@ 2023-02-13 15:56 ` Steven Rostedt
0 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2023-02-13 15:56 UTC (permalink / raw)
To: Masami Hiramatsu (Google)
Cc: Tom Zanussi, linux-kernel, linux-trace-kernel, akpm, zwisler, chinglinyu
On Tue, 14 Feb 2023 00:24:18 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:
> > - e = stack_trace_save((void *)str,
> > + e = stack_trace_save((void *)stack_start,
> > HIST_STACKTRACE_DEPTH,
> > HIST_STACKTRACE_SKIP);
>
> BTW, the size of "str" is enough to store HIST_STACKTRACE_DEPTH?
> In string case,
>
> size = min(val->size, STR_VAR_LEN_MAX);
>
> will limit the max size.
Well, we have:
#define HIST_STACKTRACE_DEPTH 16
And 16 * 8 = 128
#define STR_VAR_LEN_MAX MAX_FILTER_STR_VAL
#define MAX_FILTER_STR_VAL 256U
So 128 < 256, with plenty of room. I wouldn't do this runtime, but we
should add here:
BUILD_BUG_ON((HIST_STACKTRACE_DEPTH + 1) * sizeof(long) >= STR_VAR_LEN_MAX);
-- Steve
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2023-02-13 15:57 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2023-02-10 21:33 [PATCH 0/4] tracing/histogram: Some fixes for new stacktrace variables Tom Zanussi
2023-02-10 21:33 ` [PATCH 1/4] tracing/histogram: Don't use strlen to find length of " Tom Zanussi
2023-02-13 15:24 ` Masami Hiramatsu
2023-02-13 15:56 ` Steven Rostedt
2023-02-10 21:33 ` [PATCH 2/4] tracing/histogram: Fix a few problems with stacktrace variable printing Tom Zanussi
2023-02-10 21:33 ` [PATCH 3/4] tracing/histogram: Fix stacktrace key Tom Zanussi
2023-02-10 23:07 ` kernel test robot
2023-02-10 21:33 ` [PATCH 4/4] tracing/histogram: Fix stacktrace histogram Documententation Tom Zanussi
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.