[PATCH v4 0/7] tracing: Add dynamic strings for synthetic events

[PATCH v4 0/7] tracing: Add dynamic strings for synthetic events

[Tom Zanussi]

Hi,

This is v4 of the dynamic string support for synthetic events.

This version adds several patches addressing previous comments - a new
testcase for the dynamic synth event strings along with a patch adding
a blurb about the synthetic_events file, which should have been there
in any case, Steve's patch for preventing string printing overruns
(tracing: Change synthetic event string format to limit printed
length).

There's also a new patch (tracing: Save normal string variables) that
fixes a bug I found when adding the test case.  The problem it fixes
is only apparent when using the dynamic strings, although it could
also happen with static strings.  I wasn't able to produce the problem
with static strings, in any case.

Other changes include adding the BUILD_BUG_ON() to the (tracing:
Change STR_VAR_MAX_LEN) patch, and folding in Steve's
__set_synth_event_print_fmt() adding __get_str() calls for trace-cmd.

Thanks,

Tom


Previous versions text:

Hi,

This is v3 of the dynamic string support for synthetic events.

No code changes since v2, just added Fixes: tag for 'tracing: Fix
parse_synth_field() error handling' as suggested by Masami along with
his Reviewed-by, and Axel's Tested-bys.

Thanks,

Tom


Hi,

This is v2 of the dynamic string support for synthetic events.

v1 was missing some very important code in the in-kernel API functions
that should have reserved room for dynamic strings.  This adds it
along also some additional test code in the synth_event_gen_test
module that tests the dynamic strings for those APIs.

I also added Axel's changelog text to the 'tracing: Fix
parse_synth_field() error handling' patch and used ssize_t as he also
suggested.  Thanks, Axel!  I also noticed that the original patch
didn't use <= as it should have, so changed that as well.

Neither my command-line tests or the synth_event_gen_test module are
showing any problems at this point for me...

Tom

Original v1 text:

This patchset adds support for dynamic strings for synthetic events,
as requested by Axel Rasmussen.

Actually, the first two patches should be applied in any case - the
first just changes the current max string length and the second fixes
a bug I found while testing.

It works fine for my simple test cases, but I still need to do a lot
more testing, especially of the in-kernel API parts, which don't
affect Axel's use case.

Anyway, Axel, please try it out and send me your Tested-by: if it
works for you, and your broken testcase(s) if it doesn't. ;-)

Thanks,

Tom

The following changes since commit fdb46faeab2f3fa2b43a55059b33b8f98b2e1442:

  x86: Use tracepoint_enabled() for msr tracepoints instead of open coding it (2020-09-28 10:36:02 -0400)

are available in the Git repository at:

  git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/synth-dynstring-v4

Steven Rostedt (1):
  tracing: Change synthetic event string format to limit printed length

Tom Zanussi (6):
  tracing: Change STR_VAR_MAX_LEN
  tracing: Fix parse_synth_field() error handling
  tracing: Save normal string variables
  tracing: Add support for dynamic strings to synthetic events
  tracing: Add README information for synthetic_events file
  selftests/ftrace: Add test case for synthetic event dynamic strings

 Documentation/trace/events.rst                |  15 +-
 Documentation/trace/histogram.rst             |  18 ++
 kernel/trace/synth_event_gen_test.c           |  18 +-
 kernel/trace/trace.c                          |   7 +-
 kernel/trace/trace_events_hist.c              |  45 ++-
 kernel/trace/trace_events_synth.c             | 256 +++++++++++++++---
 kernel/trace/trace_synth.h                    |   6 +-
 .../trigger-synthetic-event-dynstring.tc      |  31 +++
 8 files changed, 350 insertions(+), 46 deletions(-)
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc

-- 
2.17.1

[PATCH v4 1/7] tracing: Change STR_VAR_MAX_LEN

[Tom Zanussi]

32 is too small for this value, and anyway it makes more sense to use
MAX_FILTER_STR_VAL, as this is also the value used for variable-length
__strings.

Tested-by: Axel Rasmussen <axelrasmussen@google.com>
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
 kernel/trace/trace_events_hist.c | 2 ++
 kernel/trace/trace_synth.h       | 2 +-
 2 files changed, 3 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 1b2ef6490229..3b22e2122d1a 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1398,6 +1398,8 @@ static int hist_trigger_elt_data_alloc(struct tracing_map_elt *elt)
 
 	n_str = hist_data->n_field_var_str + hist_data->n_save_var_str;
 
+	BUILD_BUG_ON(STR_VAR_LEN_MAX & (sizeof(u64) - 1));
+
 	size = STR_VAR_LEN_MAX;
 
 	for (i = 0; i < n_str; i++) {
diff --git a/kernel/trace/trace_synth.h b/kernel/trace/trace_synth.h
index ac35c45207c4..5166705d1556 100644
--- a/kernel/trace/trace_synth.h
+++ b/kernel/trace/trace_synth.h
@@ -7,7 +7,7 @@
 #define SYNTH_SYSTEM		"synthetic"
 #define SYNTH_FIELDS_MAX	32
 
-#define STR_VAR_LEN_MAX		32 /* must be multiple of sizeof(u64) */
+#define STR_VAR_LEN_MAX		MAX_FILTER_STR_VAL /* must be multiple of sizeof(u64) */
 
 struct synth_field {
 	char *type;
-- 
2.17.1

[PATCH v4 2/7] tracing: Fix parse_synth_field() error handling

[Tom Zanussi]

synth_field_size() returns either a positive size or an error (zero or
a negative value). However, the existing code assumes the only error
value is 0. It doesn't handle negative error codes, as it assigns
directly to field->size (a size_t; unsigned), thereby interpreting the
error code as a valid size instead.

Do the test before assignment to field->size.

[ axelrasmussen@google.com: changelog addition, first paragraph above ]

Fixes: 4b147936fa50 (tracing: Add support for 'synthetic' events)
Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>
Tested-by: Axel Rasmussen <axelrasmussen@google.com>
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
 kernel/trace/trace_events_synth.c | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
index a9cd7793f7ea..fa8a99828f41 100644
--- a/kernel/trace/trace_events_synth.c
+++ b/kernel/trace/trace_events_synth.c
@@ -465,6 +465,7 @@ static struct synth_field *parse_synth_field(int argc, const char **argv,
 	struct synth_field *field;
 	const char *prefix = NULL, *field_type = argv[0], *field_name, *array;
 	int len, ret = 0;
+	ssize_t size;
 
 	if (field_type[0] == ';')
 		field_type++;
@@ -520,11 +521,12 @@ static struct synth_field *parse_synth_field(int argc, const char **argv,
 			field->type[len - 1] = '\0';
 	}
 
-	field->size = synth_field_size(field->type);
-	if (!field->size) {
+	size = synth_field_size(field->type);
+	if (size <= 0) {
 		ret = -EINVAL;
 		goto free;
 	}
+	field->size = size;
 
 	if (synth_field_is_string(field->type))
 		field->is_string = true;
-- 
2.17.1

[PATCH v4 3/7] tracing: Save normal string variables

[Tom Zanussi]

String variables created as field variables and save variables are
already handled properly by having their values copied when set.  The
same isn't done for normal variables, but needs to be - simply saving
a pointer to a string contained in an old event isn't sufficient,
since that event's data may quickly become overwritten and therefore a
string pointer to it could yield garbage.

This change uses the same mechanism as field variables and simply
appends the new strings to the existing per-element field_var_str[]
array allocated for that purpose.

Fixes: 02205a6752f2 (tracing: Add support for 'field variables')
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
 kernel/trace/trace_events_hist.c | 34 ++++++++++++++++++++++++++++++--
 1 file changed, 32 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 3b22e2122d1a..812bc5f94b5c 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -147,6 +147,8 @@ struct hist_field {
 	 */
 	unsigned int			var_ref_idx;
 	bool                            read_once;
+
+	unsigned int			var_str_idx;
 };
 
 static u64 hist_field_none(struct hist_field *field,
@@ -349,6 +351,7 @@ struct hist_trigger_data {
 	unsigned int			n_keys;
 	unsigned int			n_fields;
 	unsigned int			n_vars;
+	unsigned int			n_var_str;
 	unsigned int			key_size;
 	struct tracing_map_sort_key	sort_keys[TRACING_MAP_SORT_KEYS_MAX];
 	unsigned int			n_sort_keys;
@@ -1396,7 +1399,12 @@ static int hist_trigger_elt_data_alloc(struct tracing_map_elt *elt)
 		}
 	}
 
-	n_str = hist_data->n_field_var_str + hist_data->n_save_var_str;
+	n_str = hist_data->n_field_var_str + hist_data->n_save_var_str +
+		hist_data->n_var_str;
+	if (n_str > SYNTH_FIELDS_MAX) {
+		hist_elt_data_free(elt_data);
+		return -EINVAL;
+	}
 
 	BUILD_BUG_ON(STR_VAR_LEN_MAX & (sizeof(u64) - 1));
 
@@ -3653,6 +3661,7 @@ static int create_var_field(struct hist_trigger_data *hist_data,
 {
 	struct trace_array *tr = hist_data->event_file->tr;
 	unsigned long flags = 0;
+	int ret;
 
 	if (WARN_ON(val_idx >= TRACING_MAP_VALS_MAX + TRACING_MAP_VARS_MAX))
 		return -EINVAL;
@@ -3667,7 +3676,12 @@ static int create_var_field(struct hist_trigger_data *hist_data,
 	if (WARN_ON(hist_data->n_vars > TRACING_MAP_VARS_MAX))
 		return -EINVAL;
 
-	return __create_val_field(hist_data, val_idx, file, var_name, expr_str, flags);
+	ret = __create_val_field(hist_data, val_idx, file, var_name, expr_str, flags);
+
+	if (hist_data->fields[val_idx]->flags & HIST_FIELD_FL_STRING)
+		hist_data->fields[val_idx]->var_str_idx = hist_data->n_var_str++;
+
+	return ret;
 }
 
 static int create_val_fields(struct hist_trigger_data *hist_data,
@@ -4394,6 +4408,22 @@ static void hist_trigger_elt_update(struct hist_trigger_data *hist_data,
 		hist_val = hist_field->fn(hist_field, elt, rbe, rec);
 		if (hist_field->flags & HIST_FIELD_FL_VAR) {
 			var_idx = hist_field->var.idx;
+
+			if (hist_field->flags & HIST_FIELD_FL_STRING) {
+				unsigned int str_start, var_str_idx, idx;
+				char *str, *val_str;
+
+				str_start = hist_data->n_field_var_str +
+					hist_data->n_save_var_str;
+				var_str_idx = hist_field->var_str_idx;
+				idx = str_start + var_str_idx;
+
+				str = elt_data->field_var_str[idx];
+				val_str = (char *)(uintptr_t)hist_val;
+				strscpy(str, val_str, STR_VAR_LEN_MAX);
+
+				hist_val = (u64)(uintptr_t)str;
+			}
 			tracing_map_set_var(elt, var_idx, hist_val);
 			continue;
 		}
-- 
2.17.1

[PATCH v4 4/7] tracing: Add support for dynamic strings to synthetic events

[Tom Zanussi]

Currently, sythetic events only support static string fields such as:

  # echo 'test_latency u64 lat; char somename[32]' > /sys/kernel/debug/tracing/synthetic_events

Which is fine, but wastes a lot of space in the event.

It also prevents the most commonly-defined strings in the existing
trace events e.g. those defined using __string(), from being passed to
synthetic events via the trace() action.

With this change, synthetic events with dynamic fields can be defined:

  # echo 'test_latency u64 lat; char somename[]' > /sys/kernel/debug/tracing/synthetic_events

And the trace() action can be used to generate events using either
dynamic or static strings:

  # echo 'hist:keys=name:lat=common_timestamp.usecs-$ts0:onmatch(sys.event).test_latency($lat,name)' > /sys/kernel/debug/tracing/events

The synthetic event dynamic strings are implemented in the same way as
the existing __data_loc strings and appear as such in the format file.

[ <rostedt@goodmis.org>: added __set_synth_event_print_fmt() changes:

  I added the following to make it work with trace-cmd. Dynamic strings
  must have __get_str() for events in the print_fmt otherwise it can't be
  parsed correctly. ]

Tested-by: Axel Rasmussen <axelrasmussen@google.com>
Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
 Documentation/trace/events.rst      |  15 +-
 Documentation/trace/histogram.rst   |  18 ++
 kernel/trace/synth_event_gen_test.c |  18 +-
 kernel/trace/trace_events_hist.c    |   9 +
 kernel/trace/trace_events_synth.c   | 248 ++++++++++++++++++++++++----
 kernel/trace/trace_synth.h          |   4 +
 6 files changed, 272 insertions(+), 40 deletions(-)

diff --git a/Documentation/trace/events.rst b/Documentation/trace/events.rst
index f792b1959a33..2a5aa48eff6c 100644
--- a/Documentation/trace/events.rst
+++ b/Documentation/trace/events.rst
@@ -589,8 +589,19 @@ name::
         { .type = "int",                .name = "my_int_field" },
   };
 
-See synth_field_size() for available types. If field_name contains [n]
-the field is considered to be an array.
+See synth_field_size() for available types.
+
+If field_name contains [n], the field is considered to be a static array.
+
+If field_names contains[] (no subscript), the field is considered to
+be a dynamic array, which will only take as much space in the event as
+is required to hold the array.
+
+Because space for an event is reserved before assigning field values
+to the event, using dynamic arrays implies that the piecewise
+in-kernel API described below can't be used with dynamic arrays.  The
+other non-piecewise in-kernel APIs can, however, be used with dynamic
+arrays.
 
 If the event is created from within a module, a pointer to the module
 must be passed to synth_event_create().  This will ensure that the
diff --git a/Documentation/trace/histogram.rst b/Documentation/trace/histogram.rst
index 8408670d0328..b573604deabd 100644
--- a/Documentation/trace/histogram.rst
+++ b/Documentation/trace/histogram.rst
@@ -1776,6 +1776,24 @@ consisting of the name of the new event along with one or more
 variables and their types, which can be any valid field type,
 separated by semicolons, to the tracing/synthetic_events file.
 
+See synth_field_size() for available types.
+
+If field_name contains [n], the field is considered to be a static array.
+
+If field_names contains[] (no subscript), the field is considered to
+be a dynamic array, which will only take as much space in the event as
+is required to hold the array.
+
+A string field can be specified using either the static notation:
+
+  char name[32];
+
+Or the dynamic:
+
+  char name[];
+
+The size limit for either is 256.
+
 For instance, the following creates a new event named 'wakeup_latency'
 with 3 fields: lat, pid, and prio.  Each of those fields is simply a
 variable reference to a variable on another event::
diff --git a/kernel/trace/synth_event_gen_test.c b/kernel/trace/synth_event_gen_test.c
index 7d56d621ffea..edd912cd14aa 100644
--- a/kernel/trace/synth_event_gen_test.c
+++ b/kernel/trace/synth_event_gen_test.c
@@ -242,9 +242,11 @@ static struct synth_field_desc create_synth_test_fields[] = {
 	{ .type = "pid_t",		.name = "next_pid_field" },
 	{ .type = "char[16]",		.name = "next_comm_field" },
 	{ .type = "u64",		.name = "ts_ns" },
+	{ .type = "char[]",		.name = "dynstring_field_1" },
 	{ .type = "u64",		.name = "ts_ms" },
 	{ .type = "unsigned int",	.name = "cpu" },
 	{ .type = "char[64]",		.name = "my_string_field" },
+	{ .type = "char[]",		.name = "dynstring_field_2" },
 	{ .type = "int",		.name = "my_int_field" },
 };
 
@@ -254,7 +256,7 @@ static struct synth_field_desc create_synth_test_fields[] = {
  */
 static int __init test_create_synth_event(void)
 {
-	u64 vals[7];
+	u64 vals[9];
 	int ret;
 
 	/* Create the create_synth_test event with the fields above */
@@ -292,10 +294,12 @@ static int __init test_create_synth_event(void)
 	vals[0] = 777;			/* next_pid_field */
 	vals[1] = (u64)(long)"tiddlywinks";	/* next_comm_field */
 	vals[2] = 1000000;		/* ts_ns */
-	vals[3] = 1000;			/* ts_ms */
-	vals[4] = raw_smp_processor_id(); /* cpu */
-	vals[5] = (u64)(long)"thneed";	/* my_string_field */
-	vals[6] = 398;			/* my_int_field */
+	vals[3] = (u64)(long)"xrayspecs";	/* dynstring_field_1 */
+	vals[4] = 1000;			/* ts_ms */
+	vals[5] = raw_smp_processor_id(); /* cpu */
+	vals[6] = (u64)(long)"thneed";	/* my_string_field */
+	vals[7] = (u64)(long)"kerplunk";	/* dynstring_field_2 */
+	vals[8] = 398;			/* my_int_field */
 
 	/* Now generate a create_synth_test event */
 	ret = synth_event_trace_array(create_synth_test, vals, ARRAY_SIZE(vals));
@@ -422,13 +426,15 @@ static int __init test_trace_synth_event(void)
 	int ret;
 
 	/* Trace some bogus values just for testing */
-	ret = synth_event_trace(create_synth_test, 7,	/* number of values */
+	ret = synth_event_trace(create_synth_test, 9,	/* number of values */
 				(u64)444,		/* next_pid_field */
 				(u64)(long)"clackers",	/* next_comm_field */
 				(u64)1000000,		/* ts_ns */
+				(u64)(long)"viewmaster",/* dynstring_field_1 */
 				(u64)1000,		/* ts_ms */
 				(u64)raw_smp_processor_id(), /* cpu */
 				(u64)(long)"Thneed",	/* my_string_field */
+				(u64)(long)"yoyos",	/* dynstring_field_2 */
 				(u64)999);		/* my_int_field */
 	return ret;
 }
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 812bc5f94b5c..c74a7d157306 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -3289,6 +3289,15 @@ static int check_synth_field(struct synth_event *event,
 
 	field = event->fields[field_pos];
 
+	/*
+	 * A dynamic string synth field can accept static or
+	 * dynamic. A static string synth field can only accept a
+	 * same-sized static string, which is checked for later.
+	 */
+	if (strstr(hist_field->type, "char[") && field->is_string
+	    && field->is_dynamic)
+		return 0;
+
 	if (strcmp(field->type, hist_field->type) != 0) {
 		if (field->size != hist_field->size ||
 		    field->is_signed != hist_field->is_signed)
diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
index fa8a99828f41..24bc6d61aa40 100644
--- a/kernel/trace/trace_events_synth.c
+++ b/kernel/trace/trace_events_synth.c
@@ -88,7 +88,7 @@ static int synth_event_define_fields(struct trace_event_call *call)
 
 		event->fields[i]->offset = n_u64;
 
-		if (event->fields[i]->is_string) {
+		if (event->fields[i]->is_string && !event->fields[i]->is_dynamic) {
 			offset += STR_VAR_LEN_MAX;
 			n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
 		} else {
@@ -139,6 +139,9 @@ static int synth_field_string_size(char *type)
 	if (len > 3)
 		return -EINVAL;
 
+	if (len == 0)
+		return 0; /* variable-length string */
+
 	strncpy(buf, start, len);
 	buf[len] = '\0';
 
@@ -290,10 +293,25 @@ static enum print_line_t print_synth_event(struct trace_iterator *iter,
 
 		/* parameter values */
 		if (se->fields[i]->is_string) {
-			trace_seq_printf(s, print_fmt, se->fields[i]->name,
-					 (char *)&entry->fields[n_u64],
-					 i == se->n_fields - 1 ? "" : " ");
-			n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
+			if (se->fields[i]->is_dynamic) {
+				u32 offset, data_offset;
+				char *str_field;
+
+				offset = (u32)entry->fields[n_u64];
+				data_offset = offset & 0xffff;
+
+				str_field = (char *)entry + data_offset;
+
+				trace_seq_printf(s, print_fmt, se->fields[i]->name,
+						 str_field,
+						 i == se->n_fields - 1 ? "" : " ");
+				n_u64++;
+			} else {
+				trace_seq_printf(s, print_fmt, se->fields[i]->name,
+						 (char *)&entry->fields[n_u64],
+						 i == se->n_fields - 1 ? "" : " ");
+				n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
+			}
 		} else {
 			struct trace_print_flags __flags[] = {
 			    __def_gfpflag_names, {-1, NULL} };
@@ -325,16 +343,52 @@ static struct trace_event_functions synth_event_funcs = {
 	.trace		= print_synth_event
 };
 
+static unsigned int trace_string(struct synth_trace_event *entry,
+				 struct synth_event *event,
+				 char *str_val,
+				 bool is_dynamic,
+				 unsigned int data_size,
+				 unsigned int *n_u64)
+{
+	unsigned int len = 0;
+	char *str_field;
+
+	if (is_dynamic) {
+		u32 data_offset;
+
+		data_offset = offsetof(typeof(*entry), fields);
+		data_offset += event->n_u64 * sizeof(u64);
+		data_offset += data_size;
+
+		str_field = (char *)entry + data_offset;
+
+		len = strlen(str_val) + 1;
+		strscpy(str_field, str_val, len);
+
+		data_offset |= len << 16;
+		*(u32 *)&entry->fields[*n_u64] = data_offset;
+
+		(*n_u64)++;
+	} else {
+		str_field = (char *)&entry->fields[*n_u64];
+
+		strscpy(str_field, str_val, STR_VAR_LEN_MAX);
+		(*n_u64) += STR_VAR_LEN_MAX / sizeof(u64);
+	}
+
+	return len;
+}
+
 static notrace void trace_event_raw_event_synth(void *__data,
 						u64 *var_ref_vals,
 						unsigned int *var_ref_idx)
 {
+	unsigned int i, n_u64, val_idx, len, data_size = 0;
 	struct trace_event_file *trace_file = __data;
 	struct synth_trace_event *entry;
 	struct trace_event_buffer fbuffer;
 	struct trace_buffer *buffer;
 	struct synth_event *event;
-	unsigned int i, n_u64, val_idx;
 	int fields_size = 0;
 
 	event = trace_file->event_call->data;
@@ -344,6 +398,18 @@ static notrace void trace_event_raw_event_synth(void *__data,
 
 	fields_size = event->n_u64 * sizeof(u64);
 
+	for (i = 0; i < event->n_dynamic_fields; i++) {
+		unsigned int field_pos = event->dynamic_fields[i]->field_pos;
+		char *str_val;
+
+		val_idx = var_ref_idx[field_pos];
+		str_val = (char *)(long)var_ref_vals[val_idx];
+
+		len = strlen(str_val) + 1;
+
+		fields_size += len;
+	}
+
 	/*
 	 * Avoid ring buffer recursion detection, as this event
 	 * is being performed within another event.
@@ -360,10 +426,11 @@ static notrace void trace_event_raw_event_synth(void *__data,
 		val_idx = var_ref_idx[i];
 		if (event->fields[i]->is_string) {
 			char *str_val = (char *)(long)var_ref_vals[val_idx];
-			char *str_field = (char *)&entry->fields[n_u64];
 
-			strscpy(str_field, str_val, STR_VAR_LEN_MAX);
-			n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
+			len = trace_string(entry, event, str_val,
+					   event->fields[i]->is_dynamic,
+					   data_size, &n_u64);
+			data_size += len; /* only dynamic string increments */
 		} else {
 			struct synth_field *field = event->fields[i];
 			u64 val = var_ref_vals[val_idx];
@@ -422,8 +489,13 @@ static int __set_synth_event_print_fmt(struct synth_event *event,
 	pos += snprintf(buf + pos, LEN_OR_ZERO, "\"");
 
 	for (i = 0; i < event->n_fields; i++) {
-		pos += snprintf(buf + pos, LEN_OR_ZERO,
-				", REC->%s", event->fields[i]->name);
+		if (event->fields[i]->is_dynamic &&
+		    event->fields[i]->is_dynamic)
+			pos += snprintf(buf + pos, LEN_OR_ZERO,
+				", __get_str(%s)", event->fields[i]->name);
+		else
+			pos += snprintf(buf + pos, LEN_OR_ZERO,
+					", REC->%s", event->fields[i]->name);
 	}
 
 #undef LEN_OR_ZERO
@@ -522,9 +594,30 @@ static struct synth_field *parse_synth_field(int argc, const char **argv,
 	}
 
 	size = synth_field_size(field->type);
-	if (size <= 0) {
+	if (size < 0) {
 		ret = -EINVAL;
 		goto free;
+	} else if (size == 0) {
+		if (synth_field_is_string(field->type)) {
+			char *type;
+
+			type = kzalloc(sizeof("__data_loc ") + strlen(field->type) + 1, GFP_KERNEL);
+			if (!type) {
+				ret = -ENOMEM;
+				goto free;
+			}
+
+			strcat(type, "__data_loc ");
+			strcat(type, field->type);
+			kfree(field->type);
+			field->type = type;
+
+			field->is_dynamic = true;
+			size = sizeof(u64);
+		} else {
+			ret = -EINVAL;
+			goto free;
+		}
 	}
 	field->size = size;
 
@@ -532,7 +625,6 @@ static struct synth_field *parse_synth_field(int argc, const char **argv,
 		field->is_string = true;
 
 	field->is_signed = synth_field_signed(field->type);
-
  out:
 	return field;
  free:
@@ -663,6 +755,7 @@ static void free_synth_event(struct synth_event *event)
 		free_synth_field(event->fields[i]);
 
 	kfree(event->fields);
+	kfree(event->dynamic_fields);
 	kfree(event->name);
 	kfree(event->class.system);
 	free_synth_tracepoint(event->tp);
@@ -673,8 +766,8 @@ static void free_synth_event(struct synth_event *event)
 static struct synth_event *alloc_synth_event(const char *name, int n_fields,
 					     struct synth_field **fields)
 {
+	unsigned int i, j, n_dynamic_fields = 0;
 	struct synth_event *event;
-	unsigned int i;
 
 	event = kzalloc(sizeof(*event), GFP_KERNEL);
 	if (!event) {
@@ -696,11 +789,33 @@ static struct synth_event *alloc_synth_event(const char *name, int n_fields,
 		goto out;
 	}
 
+	for (i = 0; i < n_fields; i++)
+		if (fields[i]->is_dynamic)
+			n_dynamic_fields++;
+
+	if (n_dynamic_fields) {
+		event->dynamic_fields = kcalloc(n_dynamic_fields,
+						sizeof(*event->dynamic_fields),
+						GFP_KERNEL);
+		if (!event->dynamic_fields) {
+			free_synth_event(event);
+			event = ERR_PTR(-ENOMEM);
+			goto out;
+		}
+	}
+
 	dyn_event_init(&event->devent, &synth_event_ops);
 
-	for (i = 0; i < n_fields; i++)
+	for (i = 0, j = 0; i < n_fields; i++) {
 		event->fields[i] = fields[i];
 
+		if (fields[i]->is_dynamic) {
+			event->dynamic_fields[j] = fields[i];
+			event->dynamic_fields[j]->field_pos = i;
+			event->dynamic_fields[j++] = fields[i];
+			event->n_dynamic_fields++;
+		}
+	}
 	event->n_fields = n_fields;
  out:
 	return event;
@@ -712,6 +827,10 @@ static int synth_event_check_arg_fn(void *data)
 	int size;
 
 	size = synth_field_size((char *)arg_pair->lhs);
+	if (size == 0) {
+		if (strstr((char *)arg_pair->lhs, "["))
+			return 0;
+	}
 
 	return size ? 0 : -EINVAL;
 }
@@ -1200,10 +1319,9 @@ void synth_event_cmd_init(struct dynevent_cmd *cmd, char *buf, int maxlen)
 EXPORT_SYMBOL_GPL(synth_event_cmd_init);
 
 static inline int
-__synth_event_trace_start(struct trace_event_file *file,
-			  struct synth_event_trace_state *trace_state)
+__synth_event_trace_init(struct trace_event_file *file,
+			 struct synth_event_trace_state *trace_state)
 {
-	int entry_size, fields_size = 0;
 	int ret = 0;
 
 	memset(trace_state, '\0', sizeof(*trace_state));
@@ -1225,8 +1343,20 @@ __synth_event_trace_start(struct trace_event_file *file,
 	}
 
 	trace_state->event = file->event_call->data;
+out:
+	return ret;
+}
+
+static inline int
+__synth_event_trace_start(struct trace_event_file *file,
+			  struct synth_event_trace_state *trace_state,
+			  int dynamic_fields_size)
+{
+	int entry_size, fields_size = 0;
+	int ret = 0;
 
 	fields_size = trace_state->event->n_u64 * sizeof(u64);
+	fields_size += dynamic_fields_size;
 
 	/*
 	 * Avoid ring buffer recursion detection, as this event
@@ -1243,7 +1373,7 @@ __synth_event_trace_start(struct trace_event_file *file,
 		ring_buffer_nest_end(trace_state->buffer);
 		ret = -EINVAL;
 	}
-out:
+
 	return ret;
 }
 
@@ -1276,23 +1406,46 @@ __synth_event_trace_end(struct synth_event_trace_state *trace_state)
  */
 int synth_event_trace(struct trace_event_file *file, unsigned int n_vals, ...)
 {
+	unsigned int i, n_u64, len, data_size = 0;
 	struct synth_event_trace_state state;
-	unsigned int i, n_u64;
 	va_list args;
 	int ret;
 
-	ret = __synth_event_trace_start(file, &state);
+	ret = __synth_event_trace_init(file, &state);
 	if (ret) {
 		if (ret == -ENOENT)
 			ret = 0; /* just disabled, not really an error */
 		return ret;
 	}
 
+	if (state.event->n_dynamic_fields) {
+		va_start(args, n_vals);
+
+		for (i = 0; i < state.event->n_fields; i++) {
+			u64 val = va_arg(args, u64);
+
+			if (state.event->fields[i]->is_string &&
+			    state.event->fields[i]->is_dynamic) {
+				char *str_val = (char *)(long)val;
+
+				data_size += strlen(str_val) + 1;
+			}
+		}
+
+		va_end(args);
+	}
+
+	ret = __synth_event_trace_start(file, &state, data_size);
+	if (ret)
+		return ret;
+
 	if (n_vals != state.event->n_fields) {
 		ret = -EINVAL;
 		goto out;
 	}
 
+	data_size = 0;
+
 	va_start(args, n_vals);
 	for (i = 0, n_u64 = 0; i < state.event->n_fields; i++) {
 		u64 val;
@@ -1301,10 +1454,11 @@ int synth_event_trace(struct trace_event_file *file, unsigned int n_vals, ...)
 
 		if (state.event->fields[i]->is_string) {
 			char *str_val = (char *)(long)val;
-			char *str_field = (char *)&state.entry->fields[n_u64];
 
-			strscpy(str_field, str_val, STR_VAR_LEN_MAX);
-			n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
+			len = trace_string(state.entry, state.event, str_val,
+					   state.event->fields[i]->is_dynamic,
+					   data_size, &n_u64);
+			data_size += len; /* only dynamic string increments */
 		} else {
 			struct synth_field *field = state.event->fields[i];
 
@@ -1357,29 +1511,46 @@ EXPORT_SYMBOL_GPL(synth_event_trace);
 int synth_event_trace_array(struct trace_event_file *file, u64 *vals,
 			    unsigned int n_vals)
 {
+	unsigned int i, n_u64, field_pos, len, data_size = 0;
 	struct synth_event_trace_state state;
-	unsigned int i, n_u64;
+	char *str_val;
 	int ret;
 
-	ret = __synth_event_trace_start(file, &state);
+	ret = __synth_event_trace_init(file, &state);
 	if (ret) {
 		if (ret == -ENOENT)
 			ret = 0; /* just disabled, not really an error */
 		return ret;
 	}
 
+	if (state.event->n_dynamic_fields) {
+		for (i = 0; i < state.event->n_dynamic_fields; i++) {
+			field_pos = state.event->dynamic_fields[i]->field_pos;
+			str_val = (char *)(long)vals[field_pos];
+			len = strlen(str_val) + 1;
+			data_size += len;
+		}
+	}
+
+	ret = __synth_event_trace_start(file, &state, data_size);
+	if (ret)
+		return ret;
+
 	if (n_vals != state.event->n_fields) {
 		ret = -EINVAL;
 		goto out;
 	}
 
+	data_size = 0;
+
 	for (i = 0, n_u64 = 0; i < state.event->n_fields; i++) {
 		if (state.event->fields[i]->is_string) {
 			char *str_val = (char *)(long)vals[i];
-			char *str_field = (char *)&state.entry->fields[n_u64];
 
-			strscpy(str_field, str_val, STR_VAR_LEN_MAX);
-			n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
+			len = trace_string(state.entry, state.event, str_val,
+					   state.event->fields[i]->is_dynamic,
+					   data_size, &n_u64);
+			data_size += len; /* only dynamic string increments */
 		} else {
 			struct synth_field *field = state.event->fields[i];
 			u64 val = vals[i];
@@ -1447,9 +1618,17 @@ int synth_event_trace_start(struct trace_event_file *file,
 	if (!trace_state)
 		return -EINVAL;
 
-	ret = __synth_event_trace_start(file, trace_state);
-	if (ret == -ENOENT)
-		ret = 0; /* just disabled, not really an error */
+	ret = __synth_event_trace_init(file, trace_state);
+	if (ret) {
+		if (ret == -ENOENT)
+			ret = 0; /* just disabled, not really an error */
+		return ret;
+	}
+
+	if (trace_state->event->n_dynamic_fields)
+		return -ENOTSUPP;
+
+	ret = __synth_event_trace_start(file, trace_state, 0);
 
 	return ret;
 }
@@ -1510,6 +1689,11 @@ static int __synth_event_add_val(const char *field_name, u64 val,
 		char *str_val = (char *)(long)val;
 		char *str_field;
 
+		if (field->is_dynamic) { /* add_val can't do dynamic strings */
+			ret = -EINVAL;
+			goto out;
+		}
+
 		if (!str_val) {
 			ret = -EINVAL;
 			goto out;
diff --git a/kernel/trace/trace_synth.h b/kernel/trace/trace_synth.h
index 5166705d1556..6e146b959dcd 100644
--- a/kernel/trace/trace_synth.h
+++ b/kernel/trace/trace_synth.h
@@ -16,6 +16,8 @@ struct synth_field {
 	unsigned int offset;
 	bool is_signed;
 	bool is_string;
+	bool is_dynamic;
+	bool field_pos;
 };
 
 struct synth_event {
@@ -24,6 +26,8 @@ struct synth_event {
 	char					*name;
 	struct synth_field			**fields;
 	unsigned int				n_fields;
+	struct synth_field			**dynamic_fields;
+	unsigned int				n_dynamic_fields;
 	unsigned int				n_u64;
 	struct trace_event_class		class;
 	struct trace_event_call			call;
-- 
2.17.1

[PATCH v4 5/7] tracing: Add README information for synthetic_events file

[Tom Zanussi]

Add an entry with a basic description of events/synthetic_events along
with a simple example.

Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
 kernel/trace/trace.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 3f2533adae72..73fd0e0c0f39 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -5249,7 +5249,12 @@ static const char readme_msg[] =
 	"\t        trace(<synthetic_event>,param list)  - generate synthetic event\n"
 	"\t        save(field,...)                      - save current event fields\n"
 #ifdef CONFIG_TRACER_SNAPSHOT
-	"\t        snapshot()                           - snapshot the trace buffer\n"
+	"\t        snapshot()                           - snapshot the trace buffer\n\n"
+#endif
+#ifdef CONFIG_SYNTH_EVENTS
+	"  events/synthetic_events\t- Create/append/remove/show synthetic events\n"
+	"\t  Write into this file to define/undefine new synthetic events.\n"
+	"\t     example: echo 'myevent u64 lat; char name[]' >> synthetic_events\n"
 #endif
 #endif
 ;
-- 
2.17.1

[PATCH v4 6/7] selftests/ftrace: Add test case for synthetic event dynamic strings

[Tom Zanussi]

Add a selftest that defines and traces a synthetic event that uses a
dynamic string event field.

Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
 .../trigger-synthetic-event-dynstring.tc      | 31 +++++++++++++++++++
 1 file changed, 31 insertions(+)
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc

diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc
new file mode 100644
index 000000000000..3d65c856eca3
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc
@@ -0,0 +1,31 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: event trigger - test inter-event histogram trigger trace action with dynamic string param
+# requires: set_event synthetic_events events/sched/sched_process_exec/hist "char name[]' >> synthetic_events":README
+
+fail() { #msg
+    echo $1
+    exit_fail
+}
+
+echo "Test create synthetic event"
+
+echo 'ping_test_latency u64 lat; char filename[]' > synthetic_events
+if [ ! -d events/synthetic/ping_test_latency ]; then
+    fail "Failed to create ping_test_latency synthetic event"
+fi
+
+echo "Test create histogram for synthetic event using trace action and dynamic strings"
+echo "Test histogram dynamic string variables,simple expression support and trace action"
+
+echo 'hist:key=pid:filenamevar=filename:ts0=common_timestamp.usecs' > events/sched/sched_process_exec/trigger
+echo 'hist:key=pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_process_exec).ping_test_latency($lat,$filenamevar) if comm == "ping"' > events/sched/sched_process_exit/trigger
+echo 'hist:keys=filename,lat:sort=filename,lat' > events/synthetic/ping_test_latency/trigger
+
+ping $LOCALHOST -c 5
+
+if ! grep -q "ping" events/synthetic/ping_test_latency/hist; then
+    fail "Failed to create dynamic string trace action inter-event histogram"
+fi
+
+exit 0
-- 
2.17.1

[PATCH v4 7/7] tracing: Change synthetic event string format to limit printed length

[Tom Zanussi]

From: Steven Rostedt <rostedt@goodmis.org>

Change the format for printing synthetic field strings to limit the
length of the string printed even if it's not correctly terminated.

Description from Steve:

I also added this for a bit of paranoid, and probably should be a
separate patch, just to make sure if the string isn't nul terminated,
this will keep it from bleeding pass the end of the string.
---
 kernel/trace/trace_events_synth.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
index 24bc6d61aa40..742ce5f62d6d 100644
--- a/kernel/trace/trace_events_synth.c
+++ b/kernel/trace/trace_events_synth.c
@@ -234,7 +234,7 @@ static const char *synth_field_fmt(char *type)
 	else if (strcmp(type, "gfp_t") == 0)
 		fmt = "%x";
 	else if (synth_field_is_string(type))
-		fmt = "%s";
+		fmt = "%.*s";
 
 	return fmt;
 }
@@ -303,11 +303,13 @@ static enum print_line_t print_synth_event(struct trace_iterator *iter,
 				str_field = (char *)entry + data_offset;
 
 				trace_seq_printf(s, print_fmt, se->fields[i]->name,
+						 STR_VAR_LEN_MAX,
 						 str_field,
 						 i == se->n_fields - 1 ? "" : " ");
 				n_u64++;
 			} else {
 				trace_seq_printf(s, print_fmt, se->fields[i]->name,
+						 STR_VAR_LEN_MAX,
 						 (char *)&entry->fields[n_u64],
 						 i == se->n_fields - 1 ? "" : " ");
 				n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
-- 
2.17.1

Re: [PATCH v4 7/7] tracing: Change synthetic event string format to limit printed length

[Steven Rostedt]

On Sun,  4 Oct 2020 17:14:09 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> From: Steven Rostedt <rostedt@goodmis.org>
> 
> Change the format for printing synthetic field strings to limit the
> length of the string printed even if it's not correctly terminated.
> 
> Description from Steve:
> 
> I also added this for a bit of paranoid, and probably should be a
> separate patch, just to make sure if the string isn't nul terminated,
> this will keep it from bleeding pass the end of the string.

Just FYI. In the future, for something like this, you should still have
your own Signed-off-by, as you are sending it (and part of the commit
path). You could also add:

[ Need signed-off-by from Steven ]

Which I would have also added as well.

Thanks!

-- Steve


> ---
>  kernel/trace/trace_events_synth.c | 4 +++-
>  1 file changed, 3 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/trace/trace_events_synth.c b/kernel/trace/trace_events_synth.c
> index 24bc6d61aa40..742ce5f62d6d 100644
> --- a/kernel/trace/trace_events_synth.c
> +++ b/kernel/trace/trace_events_synth.c
> @@ -234,7 +234,7 @@ static const char *synth_field_fmt(char *type)
>  	else if (strcmp(type, "gfp_t") == 0)
>  		fmt = "%x";
>  	else if (synth_field_is_string(type))
> -		fmt = "%s";
> +		fmt = "%.*s";
>  
>  	return fmt;
>  }
> @@ -303,11 +303,13 @@ static enum print_line_t print_synth_event(struct trace_iterator *iter,
>  				str_field = (char *)entry + data_offset;
>  
>  				trace_seq_printf(s, print_fmt, se->fields[i]->name,
> +						 STR_VAR_LEN_MAX,
>  						 str_field,
>  						 i == se->n_fields - 1 ? "" : " ");
>  				n_u64++;
>  			} else {
>  				trace_seq_printf(s, print_fmt, se->fields[i]->name,
> +						 STR_VAR_LEN_MAX,
>  						 (char *)&entry->fields[n_u64],
>  						 i == se->n_fields - 1 ? "" : " ");
>  				n_u64 += STR_VAR_LEN_MAX / sizeof(u64);

Re: [PATCH v4 7/7] tracing: Change synthetic event string format to limit printed length

[Tom Zanussi]

Hi Steve,

On Mon, 2020-10-05 at 18:17 -0400, Steven Rostedt wrote:
> On Sun,  4 Oct 2020 17:14:09 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
> 
> > From: Steven Rostedt <rostedt@goodmis.org>
> > 
> > Change the format for printing synthetic field strings to limit the
> > length of the string printed even if it's not correctly terminated.
> > 
> > Description from Steve:
> > 
> > I also added this for a bit of paranoid, and probably should be a
> > separate patch, just to make sure if the string isn't nul
> > terminated,
> > this will keep it from bleeding pass the end of the string.
> 
> Just FYI. In the future, for something like this, you should still
> have
> your own Signed-off-by, as you are sending it (and part of the commit
> path). You could also add:
> 
> [ Need signed-off-by from Steven ]
> 
> Which I would have also added as well.
> 

Yeah, will do that next time.  Thanks for the tip.

Tom

> Thanks!
> 
> -- Steve
> 
> 
> > ---
> >  kernel/trace/trace_events_synth.c | 4 +++-
> >  1 file changed, 3 insertions(+), 1 deletion(-)
> > 
> > diff --git a/kernel/trace/trace_events_synth.c
> > b/kernel/trace/trace_events_synth.c
> > index 24bc6d61aa40..742ce5f62d6d 100644
> > --- a/kernel/trace/trace_events_synth.c
> > +++ b/kernel/trace/trace_events_synth.c
> > @@ -234,7 +234,7 @@ static const char *synth_field_fmt(char *type)
> >  	else if (strcmp(type, "gfp_t") == 0)
> >  		fmt = "%x";
> >  	else if (synth_field_is_string(type))
> > -		fmt = "%s";
> > +		fmt = "%.*s";
> >  
> >  	return fmt;
> >  }
> > @@ -303,11 +303,13 @@ static enum print_line_t
> > print_synth_event(struct trace_iterator *iter,
> >  				str_field = (char *)entry +
> > data_offset;
> >  
> >  				trace_seq_printf(s, print_fmt, se-
> > >fields[i]->name,
> > +						 STR_VAR_LEN_MAX,
> >  						 str_field,
> >  						 i == se->n_fields - 1
> > ? "" : " ");
> >  				n_u64++;
> >  			} else {
> >  				trace_seq_printf(s, print_fmt, se-
> > >fields[i]->name,
> > +						 STR_VAR_LEN_MAX,
> >  						 (char *)&entry-
> > >fields[n_u64],
> >  						 i == se->n_fields - 1
> > ? "" : " ");
> >  				n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
> 
> 

Re: [PATCH v4 6/7] selftests/ftrace: Add test case for synthetic event dynamic strings

[Masami Hiramatsu]

On Sun,  4 Oct 2020 17:14:08 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> Add a selftest that defines and traces a synthetic event that uses a
> dynamic string event field.
> 
> Signed-off-by: Tom Zanussi <zanussi@kernel.org>

This looks good to me.

Acked-by: Masami Hiramatsu <mhiramat@kernel.org>

Thank you!
> ---
>  .../trigger-synthetic-event-dynstring.tc      | 31 +++++++++++++++++++
>  1 file changed, 31 insertions(+)
>  create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc
> new file mode 100644
> index 000000000000..3d65c856eca3
> --- /dev/null
> +++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-dynstring.tc
> @@ -0,0 +1,31 @@
> +#!/bin/sh
> +# SPDX-License-Identifier: GPL-2.0
> +# description: event trigger - test inter-event histogram trigger trace action with dynamic string param
> +# requires: set_event synthetic_events events/sched/sched_process_exec/hist "char name[]' >> synthetic_events":README
> +
> +fail() { #msg
> +    echo $1
> +    exit_fail
> +}
> +
> +echo "Test create synthetic event"
> +
> +echo 'ping_test_latency u64 lat; char filename[]' > synthetic_events
> +if [ ! -d events/synthetic/ping_test_latency ]; then
> +    fail "Failed to create ping_test_latency synthetic event"
> +fi
> +
> +echo "Test create histogram for synthetic event using trace action and dynamic strings"
> +echo "Test histogram dynamic string variables,simple expression support and trace action"
> +
> +echo 'hist:key=pid:filenamevar=filename:ts0=common_timestamp.usecs' > events/sched/sched_process_exec/trigger
> +echo 'hist:key=pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_process_exec).ping_test_latency($lat,$filenamevar) if comm == "ping"' > events/sched/sched_process_exit/trigger
> +echo 'hist:keys=filename,lat:sort=filename,lat' > events/synthetic/ping_test_latency/trigger
> +
> +ping $LOCALHOST -c 5
> +
> +if ! grep -q "ping" events/synthetic/ping_test_latency/hist; then
> +    fail "Failed to create dynamic string trace action inter-event histogram"
> +fi
> +
> +exit 0
> -- 
> 2.17.1
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v4 5/7] tracing: Add README information for synthetic_events file

[Masami Hiramatsu]

Hi Tom,

On Sun,  4 Oct 2020 17:14:07 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> Add an entry with a basic description of events/synthetic_events along
> with a simple example.
> 
> Signed-off-by: Tom Zanussi <zanussi@kernel.org>

This looks good to me.

Reviewed-by: Masami Hiramatsu <mhiramat@kernel.org>

Thank you,

> ---
>  kernel/trace/trace.c | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index 3f2533adae72..73fd0e0c0f39 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -5249,7 +5249,12 @@ static const char readme_msg[] =
>  	"\t        trace(<synthetic_event>,param list)  - generate synthetic event\n"
>  	"\t        save(field,...)                      - save current event fields\n"
>  #ifdef CONFIG_TRACER_SNAPSHOT
> -	"\t        snapshot()                           - snapshot the trace buffer\n"
> +	"\t        snapshot()                           - snapshot the trace buffer\n\n"
> +#endif
> +#ifdef CONFIG_SYNTH_EVENTS
> +	"  events/synthetic_events\t- Create/append/remove/show synthetic events\n"
> +	"\t  Write into this file to define/undefine new synthetic events.\n"
> +	"\t     example: echo 'myevent u64 lat; char name[]' >> synthetic_events\n"
>  #endif
>  #endif
>  ;
> -- 
> 2.17.1
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v4 4/7] tracing: Add support for dynamic strings to synthetic events

[Masami Hiramatsu]

Hi Tom,

On Sun,  4 Oct 2020 17:14:06 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> Currently, sythetic events only support static string fields such as:
> 
>   # echo 'test_latency u64 lat; char somename[32]' > /sys/kernel/debug/tracing/synthetic_events
> 
> Which is fine, but wastes a lot of space in the event.
> 
> It also prevents the most commonly-defined strings in the existing
> trace events e.g. those defined using __string(), from being passed to
> synthetic events via the trace() action.
> 
> With this change, synthetic events with dynamic fields can be defined:
> 
>   # echo 'test_latency u64 lat; char somename[]' > /sys/kernel/debug/tracing/synthetic_events
> 
> And the trace() action can be used to generate events using either
> dynamic or static strings:
> 
>   # echo 'hist:keys=name:lat=common_timestamp.usecs-$ts0:onmatch(sys.event).test_latency($lat,name)' > /sys/kernel/debug/tracing/events
> 
> The synthetic event dynamic strings are implemented in the same way as
> the existing __data_loc strings and appear as such in the format file.
> 
> [ <rostedt@goodmis.org>: added __set_synth_event_print_fmt() changes:
> 
>   I added the following to make it work with trace-cmd. Dynamic strings
>   must have __get_str() for events in the print_fmt otherwise it can't be
>   parsed correctly. ]

I confirmed this works, but have some questions;
- It seems no error message when we failed to define with wrong syntax

/sys/kernel/debug/tracing # echo 'myevent char name []' >> synthetic_events 
sh: write error: Invalid argument
/sys/kernel/debug/tracing # cat error_log 
/sys/kernel/debug/tracing #

- what we write and what we see in synthetic_events are different

/sys/kernel/debug/tracing # echo 'myevent char name[]' >> synthetic_events 
/sys/kernel/debug/tracing # cat synthetic_events 
myevent	__data_loc char[] name

- And it is not able to re-define with that syntax

/sys/kernel/debug/tracing # echo > synthetic_events 
/sys/kernel/debug/tracing # echo 'myevent __data_loc char[] name' >> synthetic_events 
sh: write error: Invalid argument
/sys/kernel/debug/tracing # 

- It seems to accept wrong name for variables

/sys/kernel/debug/tracing # echo 'myevent char name]' >> synthetic_events 
/sys/kernel/debug/tracing # echo 'myevent2 char name;[]' >> synthetic_events 
/sys/kernel/debug/tracing # cat synthetic_events 
myevent	char name]
myevent2	__data_loc char[] name;

Some of those issues are not introduced from this series. I think
we'd better fix those before introducing this series so that
we can backport it to stable kernels.

Thank you,


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v4 4/7] tracing: Add support for dynamic strings to synthetic events

[Steven Rostedt]

On Thu, 8 Oct 2020 18:22:07 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Some of those issues are not introduced from this series. I think
> we'd better fix those before introducing this series so that
> we can backport it to stable kernels.

I agree that these should be fixed, but I'm not sure I want to hold off
this series before they are.

-- Steve

Re: [PATCH v4 4/7] tracing: Add support for dynamic strings to synthetic events

[Tom Zanussi]

Hi Masami,

On Thu, 2020-10-08 at 18:22 +0900, Masami Hiramatsu wrote:
> Hi Tom,
> 
> On Sun,  4 Oct 2020 17:14:06 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
> 
> > Currently, sythetic events only support static string fields such
> > as:
> > 
> >   # echo 'test_latency u64 lat; char somename[32]' >
> > /sys/kernel/debug/tracing/synthetic_events
> > 
> > Which is fine, but wastes a lot of space in the event.
> > 
> > It also prevents the most commonly-defined strings in the existing
> > trace events e.g. those defined using __string(), from being passed
> > to
> > synthetic events via the trace() action.
> > 
> > With this change, synthetic events with dynamic fields can be
> > defined:
> > 
> >   # echo 'test_latency u64 lat; char somename[]' >
> > /sys/kernel/debug/tracing/synthetic_events
> > 
> > And the trace() action can be used to generate events using either
> > dynamic or static strings:
> > 
> >   # echo 'hist:keys=name:lat=common_timestamp.usecs-
> > $ts0:onmatch(sys.event).test_latency($lat,name)' >
> > /sys/kernel/debug/tracing/events
> > 
> > The synthetic event dynamic strings are implemented in the same way
> > as
> > the existing __data_loc strings and appear as such in the format
> > file.
> > 
> > [ <rostedt@goodmis.org>: added __set_synth_event_print_fmt()
> > changes:
> > 
> >   I added the following to make it work with trace-cmd. Dynamic
> > strings
> >   must have __get_str() for events in the print_fmt otherwise it
> > can't be
> >   parsed correctly. ]
> 
> I confirmed this works, but have some questions;
> - It seems no error message when we failed to define with wrong
> syntax

Yes, I need to add an error message for this (as well as others in this
file).

> 
> /sys/kernel/debug/tracing # echo 'myevent char name []' >>
> synthetic_events 
> sh: write error: Invalid argument
> /sys/kernel/debug/tracing # cat error_log 
> /sys/kernel/debug/tracing #
> 
> - what we write and what we see in synthetic_events are different
> 
> /sys/kernel/debug/tracing # echo 'myevent char name[]' >>
> synthetic_events 
> /sys/kernel/debug/tracing # cat synthetic_events 
> myevent	__data_loc char[] name
> 
> - And it is not able to re-define with that syntax
> 
> /sys/kernel/debug/tracing # echo > synthetic_events 
> /sys/kernel/debug/tracing # echo 'myevent __data_loc char[] name' >>
> synthetic_events 
> sh: write error: Invalid argument
> /sys/kernel/debug/tracing # 
> 

Yes, only the format needs to have the __data_loc, but the event
description shouldn't.

> - It seems to accept wrong name for variables
> 
> /sys/kernel/debug/tracing # echo 'myevent char name]' >>
> synthetic_events 
> /sys/kernel/debug/tracing # echo 'myevent2 char name;[]' >>
> synthetic_events 
> /sys/kernel/debug/tracing # cat synthetic_events 
> myevent	char name]
> myevent2	__data_loc char[] name;
> 

Yes, I think all these other errors boil down to allowing illegal
names.  Applying your is_good_name() function for probe events to these
fields should get rid of them.

> Some of those issues are not introduced from this series. I think
> we'd better fix those before introducing this series so that
> we can backport it to stable kernels.
> 

I should have patches addressing all of these shortly, tomorrow at the
latest.

Thanks,

Tom

> Thank you,
> 
> 

Re: [PATCH v4 4/7] tracing: Add support for dynamic strings to synthetic events

[Masami Hiramatsu]

On Thu, 8 Oct 2020 15:21:50 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Thu, 8 Oct 2020 18:22:07 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > Some of those issues are not introduced from this series. I think
> > we'd better fix those before introducing this series so that
> > we can backport it to stable kernels.
> 
> I agree that these should be fixed, but I'm not sure I want to hold off
> this series before they are.

OK, I think the last event-name issue will be separated from this patch,
but others are directly related this patch. So those need to be fixed in
this series.

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>