tracing/histogram: Some fixes for new stacktrace variables

PATCH In review Tom Zanussi 4 participants 8 messages Feb 10, 2023 – Feb 13, 2023

Subsystems (2)

Documentation Tracing

lore

Share & tools

lore

Tom Zanussi

author

2023-02-10 21:33 UTC #0 lore raw

cover tracing/histogram: Some fixes for new stacktrace variables

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(-)

Signature · 1 line

2.34.1

Tom Zanussi

author

2023-02-10 21:33 UTC #1 lore raw

PATCH 1/4 tracing/histogram: Don't use strlen to find length of stacktrace variables

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 <[email protected]>

---
 kernel/trace/trace_events_hist.c  | 12 ++++++++----
 kernel/trace/trace_events_synth.c |  7 ++++++-
 2 files changed, 14 insertions(+), 5 deletions(-)

kernel/trace/trace_events_hist.c +8 -4

index 888b7a394ce5..76bd105988c6 100644
@@ -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;
 			}

kernel/trace/trace_events_synth.c +6 -1

index d458d7a0dfd7..6209b23c863f 100644
@@ -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;
 	}

Signature · 1 line

2.34.1

Masami Hiramatsu (Google)

maintainer

2023-02-13 15:24 UTC #2 lore raw

Re: [PATCH 1/4] tracing/histogram: Don't use strlen to find length of stacktrace variables

Quoted 5 lines · On Fri, 10 Feb 2023 15:33:03 -0600 Tom Zanussi <[email protected]> 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!

Quoted 17 lines

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 <[email protected]>
---
 kernel/trace/trace_events_hist.c  | 12 ++++++++----
 kernel/trace/trace_events_synth.c |  7 ++++++-
 2 files changed, 14 insertions(+), 5 deletions(-)
kernel/trace/trace_events_hist.c +0 -0
index 888b7a394ce5..76bd105988c6 100644

kernel/trace/trace_events_hist.c static inline void __update_field_vars(struct tracing_map_elt *elt, · line 3143

Quoted 10 lines

kernel/trace/trace_events_hist.c +2 -1

@@ -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,

Quoted 46 lines

kernel/trace/trace_events_hist.c +6 -3

 				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;
 			}

kernel/trace/trace_events_synth.c +6 -1

index d458d7a0dfd7..6209b23c863f 100644
@@ -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;
 	}

Signature · 1 line

2.34.1

Signature · 1 line

Masami Hiramatsu (Google) <[email protected]>

Steven Rostedt

maintainer

2023-02-13 15:57 UTC #3 lore raw

Re: [PATCH 1/4] tracing/histogram: Don't use strlen to find length of stacktrace variables

Quoted 11 lines · On Tue, 14 Feb 2023 00:24:18 +0900 Masami Hiramatsu (Google)…

kernel/trace/trace_events_hist.c static inline void __update_field_vars(struct tracing_map_elt *elt, · line 3143
Quoted 4 lines
kernel/trace/trace_events_hist.c +1 -1
-				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

Tom Zanussi

author

2023-02-10 21:33 UTC #4 lore raw

PATCH 2/4 tracing/histogram: Fix a few problems with stacktrace variable printing

In reply to Tom Zanussi

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 <[email protected]>

---
 kernel/trace/trace_events_hist.c | 26 ++++++++++++++++++--------
 1 file changed, 18 insertions(+), 8 deletions(-)

kernel/trace/trace_events_hist.c +18 -8

index 76bd105988c6..a58380702491 100644
@@ -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);
 	}

Signature · 1 line

2.34.1

Tom Zanussi

author

2023-02-10 21:33 UTC #5 lore raw

PATCH 3/4 tracing/histogram: Fix stacktrace key

In reply to Tom Zanussi

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 <[email protected]>

---
 kernel/trace/trace_events_hist.c | 34 +++++++++++++++++++++++++++++---
 1 file changed, 31 insertions(+), 3 deletions(-)

kernel/trace/trace_events_hist.c +31 -3

index a58380702491..eb812cfdaa88 100644
@@ -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);

Signature · 1 line

2.34.1

kernel test robot

build bot

2023-02-10 23:08 UTC #6 lore raw

Re: [PATCH 3/4] tracing/histogram: Fix stacktrace key

Thank you for the patch! Perhaps something to improve:

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/[email protected]/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 <[email protected]>
| Link: https://lore.kernel.org/oe-kbuild-all/[email protected]/

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

Signature · 2 lines

0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests

Tom Zanussi

author

2023-02-10 21:33 UTC #7 lore raw

PATCH 4/4 tracing/histogram: Fix stacktrace histogram Documententation

In reply to Tom Zanussi

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 <[email protected]>

---
 Documentation/trace/histogram.rst | 156 +++++++++++++++++-------------
 1 file changed, 90 insertions(+), 66 deletions(-)

Documentation/trace/histogram.rst +90 ~~-66~~

index 5c391328b9bb..d024cdae4fbd 100644
@@ -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'
 -------------------------------------------

Signature · 1 line

2.34.1