[PATCH v2 0/3] tracing: Add dynamic strings for synthetic events

[PATCH v2 0/3] tracing: Add dynamic strings for synthetic events

[Tom Zanussi]

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 106c076d23cca67c959a6fd1ccadb5b3ef01ddc9:

  mmap_lock: add tracepoints around lock acquisition (2020-09-23 08:48:08 -0500)

are available in the Git repository at:

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

Tom Zanussi (3):
  tracing: Change STR_VAR_MAX_LEN
  tracing: Fix parse_synth_field() error handling
  tracing: Add support for dynamic strings to synthetic events

 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   | 243 ++++++++++++++++++++++++----
 kernel/trace/trace_synth.h          |   6 +-
 6 files changed, 269 insertions(+), 40 deletions(-)

-- 
2.17.1

[PATCH v2 1/3] 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.

Signed-off-by: Tom Zanussi <zanussi@kernel.org>
---
 kernel/trace/trace_synth.h | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

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 v2 2/3] 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 ]

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 v2 3/3] 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.

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   | 239 ++++++++++++++++++++++++----
 kernel/trace/trace_synth.h          |   4 +
 6 files changed, 265 insertions(+), 38 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 1b2ef6490229..ee6b27c82350 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -3279,6 +3279,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..4b3ec570147a 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];
@@ -522,9 +589,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 +620,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 +750,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 +761,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 +784,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 +822,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 +1314,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 +1338,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 +1368,7 @@ __synth_event_trace_start(struct trace_event_file *file,
 		ring_buffer_nest_end(trace_state->buffer);
 		ret = -EINVAL;
 	}
-out:
+
 	return ret;
 }
 
@@ -1276,23 +1401,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 +1449,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 +1506,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 +1613,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 +1684,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

Re: [PATCH v2 1/3] tracing: Change STR_VAR_MAX_LEN

[Axel Rasmussen]

I still get the same WARN_ON behavior when trying to use bpftrace.
But, I spent some time today reading through that call path, and at
this point I'm convinced that it's the version of bpftrace I'm using
which is slightly broken, not the kernel in this case. (To be fair,
I'm trying to use some unreleased tip-of-tree version of it, with some
not-yet-merged patches, and some extra hacks on top of all that, so
it's not particularly surprising...)

In my experiments with just the synthetic event + histogram triggers,
this patchset works as expected for my use case.

So (for the whole series, not just this one patch):

Tested-by: Axel Rasmussen <axelrasmussen@google.com>

On Wed, Sep 30, 2020 at 11:41 AM Tom Zanussi <zanussi@kernel.org> wrote:
>
> 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.
>
> Signed-off-by: Tom Zanussi <zanussi@kernel.org>
> ---
>  kernel/trace/trace_synth.h | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
>
> 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
>

Re: [PATCH v2 2/3] tracing: Fix parse_synth_field() error handling

[Masami Hiramatsu]

Hi Tom,

On Wed, 30 Sep 2020 13:40:51 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> 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.

This looks good to me. And I guess it is a kind of bugfix which should be backported?
(doesn't this need a Fixes tag?)

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

Thank you,

> 
> [ axelrasmussen@google.com: changelog addition, first paragraph above ]
> 
> 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
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v2 2/3] tracing: Fix parse_synth_field() error handling

[Tom Zanussi]

Hi Masami,

On Thu, 2020-10-01 at 14:27 +0900, Masami Hiramatsu wrote:
> Hi Tom,
> 
> On Wed, 30 Sep 2020 13:40:51 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
> 
> > 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.
> 
> This looks good to me. And I guess it is a kind of bugfix which
> should be backported?
> (doesn't this need a Fixes tag?)

Yep, thanks for pointing that out.

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

Thanks!

Tom

> Thank you,
> 
> > 
> > [ axelrasmussen@google.com: changelog addition, first paragraph
> > above ]
> > 
> > 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
> > 
> 
> 

Re: [PATCH v2 1/3] tracing: Change STR_VAR_MAX_LEN

[Tom Zanussi]

Hi Axel,

On Wed, 2020-09-30 at 15:45 -0700, Axel Rasmussen wrote:
> I still get the same WARN_ON behavior when trying to use bpftrace.
> But, I spent some time today reading through that call path, and at
> this point I'm convinced that it's the version of bpftrace I'm using
> which is slightly broken, not the kernel in this case. (To be fair,
> I'm trying to use some unreleased tip-of-tree version of it, with
> some
> not-yet-merged patches, and some extra hacks on top of all that, so
> it's not particularly surprising...)
> 
> In my experiments with just the synthetic event + histogram triggers,
> this patchset works as expected for my use case.
> 
> So (for the whole series, not just this one patch):
> 
> Tested-by: Axel Rasmussen <axelrasmussen@google.com>

Thanks!

Tom

> 
> On Wed, Sep 30, 2020 at 11:41 AM Tom Zanussi <zanussi@kernel.org>
> wrote:
> > 
> > 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.
> > 
> > Signed-off-by: Tom Zanussi <zanussi@kernel.org>
> > ---
> >  kernel/trace/trace_synth.h | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > 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
> > 

Re: [PATCH v2 3/3] tracing: Add support for dynamic strings to synthetic events

[Masami Hiramatsu]

Hi Tom,

On Wed, 30 Sep 2020 13:40:52 -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

Could you add a testcase (and update existing one) of ftracetest
for this new feature too?

> 
> 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.
> 
> 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   | 239 ++++++++++++++++++++++++----
>  kernel/trace/trace_synth.h          |   4 +

And you might also need to update tracefs/README so that user
can check whether the kernel supports dynamic string or not.


Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v2 3/3] tracing: Add support for dynamic strings to synthetic events

[Tom Zanussi]

Hi Masami,

On Fri, 2020-10-02 at 16:17 +0900, Masami Hiramatsu wrote:
> Hi Tom,
> 
> On Wed, 30 Sep 2020 13:40:52 -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
> 
> Could you add a testcase (and update existing one) of ftracetest
> for this new feature too?
> 

Yes, I'll add it in the next version.

> > 
> > 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.
> > 
> > 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   | 239
> > ++++++++++++++++++++++++----
> >  kernel/trace/trace_synth.h          |   4 +
> 
> And you might also need to update tracefs/README so that user
> can check whether the kernel supports dynamic string or not.
> 

Yeah, good to add regardless, will do.

Thanks,

Tom