[PATCH 15/18] tracing: Add string type for dynamic strings in function based events

[Steven Rostedt <rostedt@goodmis.org>]

[-- Attachment #1: 0015-tracing-Add-string-type-for-dynamic-strings-in-funct.patch --]
[-- Type: text/plain, Size: 10751 bytes --]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

Add a "string" type that will create a dynamic length string for the
event, this is the same as the __string() field in normal TRACE_EVENTS.

[ missing 'static' found by Fengguang Wu's kbuild test robot ]
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/trace/function-based-events.rst |  19 ++-
 kernel/trace/trace_event_ftrace.c             | 183 +++++++++++++++++++++++---
 2 files changed, 181 insertions(+), 21 deletions(-)

diff --git a/Documentation/trace/function-based-events.rst b/Documentation/trace/function-based-events.rst
index 99ae77cd59e6..6c643ea749e7 100644
--- a/Documentation/trace/function-based-events.rst
+++ b/Documentation/trace/function-based-events.rst
@@ -99,7 +99,7 @@ as follows:
          's8' | 's16' | 's32' | 's64' |
          'x8' | 'x16' | 'x32' | 'x64' |
          'char' | 'short' | 'int' | 'long' | 'size_t' |
-	 'symbol'
+	 'symbol' | 'string'
 
  FIELD := <name> | <name> INDEX | <name> OFFSET | <name> OFFSET INDEX
 
@@ -342,3 +342,20 @@ the format "%s". If a nul is found, the output will stop. Use another type
       bash-1470  [003] ...2   980.678715: path_openat->link_path_walk(name=/lib64/ld-linux-x86-64.so.2)
       bash-1470  [003] ...2   980.678721: path_openat->link_path_walk(name=ld-2.24.so)
       bash-1470  [003] ...2   980.678978: path_lookupat->link_path_walk(name=/etc/ld.so.preload)
+
+
+Dynamic strings
+===============
+
+Static strings are fine, but they can waste a lot of memory in the ring buffer.
+The above allocated 64 bytes for a character array, but most of the output was
+less than 20 characters. Not wanting to truncate strings or waste space on
+the ring buffer, the dynamic string can help.
+
+Use the "string" type for strings that have a large range in size. The max
+size that will be recorded is 512 bytes. If a string is larger than that, then
+it will be truncated.
+
+ # echo 'link_path_walk(string name)' > function_events
+
+Gives the same result as above, but does not waste buffer space.
diff --git a/kernel/trace/trace_event_ftrace.c b/kernel/trace/trace_event_ftrace.c
index dd24b840329d..273c5838a8e2 100644
--- a/kernel/trace/trace_event_ftrace.c
+++ b/kernel/trace/trace_event_ftrace.c
@@ -39,6 +39,7 @@ struct func_event {
 	struct func_arg			*last_arg;
 	int				arg_cnt;
 	int				arg_offset;
+	int				has_strings;
 };
 
 struct func_file {
@@ -83,6 +84,8 @@ typedef u32 x32;
 typedef u16 x16;
 typedef u8 x8;
 typedef void * symbol;
+/* 2 byte offset, 2 byte length */
+typedef u32 string;
 
 #define TYPE_TUPLE(type)			\
 	{ #type, sizeof(type), is_signed_type(type) }
@@ -105,7 +108,8 @@ typedef void * symbol;
 	TYPE_TUPLE(u8),				\
 	TYPE_TUPLE(s8),				\
 	TYPE_TUPLE(x8),				\
-	TYPE_TUPLE(symbol)
+	TYPE_TUPLE(symbol),			\
+	TYPE_TUPLE(string)
 
 static struct func_type {
 	char		*name;
@@ -124,6 +128,16 @@ enum {
 	FUNC_TYPE_MAX
 };
 
+#define MAX_STR		512
+
+/* Two contexts, normal and NMI, hence the " * 2" */
+struct func_string {
+	char		buf[MAX_STR * 2];
+};
+
+static struct func_string __percpu *str_buffer;
+static int nr_strings;
+
 /**
  * arch_get_func_args - retrieve function arguments via pt_regs
  * @regs: The registers at the moment the function is called
@@ -163,6 +177,23 @@ int __weak arch_get_func_args(struct pt_regs *regs,
 	return 0;
 }
 
+static void free_arg(struct func_arg *arg)
+{
+	list_del(&arg->list);
+	if (arg->func_type == FUNC_TYPE_string) {
+		nr_strings--;
+		if (WARN_ON(nr_strings < 0))
+			nr_strings = 0;
+		if (!nr_strings) {
+			free_percpu(str_buffer);
+			str_buffer = NULL;
+		}
+	}
+	kfree(arg->name);
+	kfree(arg->type);
+	kfree(arg);
+}
+
 static void free_func_event(struct func_event *func_event)
 {
 	struct func_arg *arg, *n;
@@ -171,10 +202,7 @@ static void free_func_event(struct func_event *func_event)
 		return;
 
 	list_for_each_entry_safe(arg, n, &func_event->args, list) {
-		list_del(&arg->list);
-		kfree(arg->name);
-		kfree(arg->type);
-		kfree(arg);
+		free_arg(arg);
 	}
 	ftrace_free_filter(&func_event->ops);
 	kfree(func_event->call.print_fmt);
@@ -255,6 +283,17 @@ static int add_arg(struct func_event *fevent, int ftype, int unsign)
 	list_add_tail(&arg->list, &fevent->args);
 	fevent->last_arg = arg;
 
+	if (ftype == FUNC_TYPE_string) {
+		fevent->has_strings++;
+		nr_strings++;
+		if (nr_strings == 1) {
+			str_buffer = alloc_percpu(struct func_string);
+			if (!str_buffer) {
+				free_arg(arg);
+				return -ENOMEM;
+			}
+		}
+	}
 	return 0;
 }
 
@@ -344,8 +383,19 @@ process_event(struct func_event *fevent, const char *token, enum func_states sta
 		return FUNC_STATE_TYPE;
 
 	case FUNC_STATE_TYPE:
-		if (token[0] == '[')
+		if (token[0] == '[') {
+			/* Strings are already arrays */
+			if (fevent->last_arg->func_type == FUNC_TYPE_string)
+				break;
 			return FUNC_STATE_ARRAY;
+		}
+		if (fevent->last_arg->func_type == FUNC_TYPE_string) {
+			type = kstrdup("__data_loc char[]", GFP_KERNEL);
+			if (!type)
+				break;
+			kfree(fevent->last_arg->type);
+			fevent->last_arg->type = type;
+		}
 		/* Fall through */
 	case FUNC_STATE_ARRAY_END:
 		if (WARN_ON(!fevent->last_arg))
@@ -473,7 +523,7 @@ process_event(struct func_event *fevent, const char *token, enum func_states sta
 	return FUNC_STATE_END;
 }
 
-static long long get_arg(struct func_arg *arg, unsigned long val)
+static long long __get_arg(struct func_arg *arg, unsigned long val)
 {
 	char buf[8];
 	int ret;
@@ -485,8 +535,8 @@ static long long get_arg(struct func_arg *arg, unsigned long val)
 
 	val = val + (arg->indirect ^ INDIRECT_FLAG);
 
-	/* Arrays do their own indirect reads */
-	if (arg->array)
+	/* Arrays and strings do their own indirect reads */
+	if (arg->array || arg->func_type == FUNC_TYPE_string)
 		return val;
 
 	ret = probe_kernel_read(buf, (void *)val, arg->size);
@@ -510,6 +560,15 @@ static long long get_arg(struct func_arg *arg, unsigned long val)
 	return val;
 }
 
+static long long get_arg(struct func_arg *arg, long *args)
+{
+	/* Is arg an address and not a parameter? */
+	if (arg->arg < 0)
+		return __get_arg(arg, 0);
+	else
+		return __get_arg(arg, args[arg->arg]);
+}
+
 static void get_array(void *dst, struct func_arg *arg, unsigned long val)
 {
 	void *ptr = (void *)val;
@@ -525,6 +584,67 @@ static void get_array(void *dst, struct func_arg *arg, unsigned long val)
 	}
 }
 
+static int read_string(char *str, unsigned long addr)
+{
+	unsigned long flags;
+	struct func_string *strbuf;
+	char *ptr = (void *)addr;
+	char *buf;
+	int ret;
+
+	if (!str_buffer)
+		return 0;
+
+	strbuf = this_cpu_ptr(str_buffer);
+	buf = &strbuf->buf[0];
+
+	if (in_nmi())
+		buf += MAX_STR;
+
+	local_irq_save(flags);
+	ret = strncpy_from_unsafe(buf, ptr, MAX_STR);
+	if (ret < 0)
+		ret = 0;
+	if (ret > 0 && str)
+		memcpy(str, buf, ret);
+	local_irq_restore(flags);
+
+	return ret;
+}
+
+static int calculate_strings(struct func_event *func_event, int nr_args, long *args)
+{
+	struct func_arg *arg;
+	unsigned long val;
+	int str_count = 0;
+	int size = 0;
+
+	list_for_each_entry(arg, &func_event->args, list) {
+		if (arg->func_type != FUNC_TYPE_string)
+			continue;
+		if (arg->arg < nr_args)
+			val = get_arg(arg, args);
+		else
+			goto skip;
+		size += read_string(NULL, val);
+ skip:
+		if (++str_count >= func_event->has_strings)
+			return size;
+	}
+	return size;
+}
+
+static int get_string(unsigned long addr, unsigned int idx,
+		      unsigned int *info, char *data)
+{
+	int len;
+
+	len = read_string(data, addr);
+	*info = len << 16 | idx;
+
+	return len;
+}
+
 static void func_event_trace(struct trace_event_file *trace_file,
 			     struct func_event *func_event,
 			     unsigned long ip, unsigned long parent_ip,
@@ -538,6 +658,8 @@ static void func_event_trace(struct trace_event_file *trace_file,
 	long args[func_event->arg_cnt];
 	long long val = 1;
 	unsigned long irq_flags;
+	int str_offset;
+	int str_idx = 0;
 	int nr_args = 0;
 	int size;
 	int pc;
@@ -550,6 +672,12 @@ static void func_event_trace(struct trace_event_file *trace_file,
 
 	size = func_event->arg_offset + sizeof(*entry);
 
+	if (func_event->arg_cnt)
+		nr_args = arch_get_func_args(pt_regs, 0, func_event->arg_cnt, args);
+
+	if (func_event->has_strings)
+		size += calculate_strings(func_event, nr_args, args);
+
 	event = trace_event_buffer_lock_reserve(&buffer, trace_file,
 						call->event.type,
 						size, irq_flags, pc);
@@ -559,21 +687,22 @@ static void func_event_trace(struct trace_event_file *trace_file,
 	entry = ring_buffer_event_data(event);
 	entry->ip = ip;
 	entry->parent_ip = parent_ip;
-	if (func_event->arg_cnt)
-		nr_args = arch_get_func_args(pt_regs, 0, func_event->arg_cnt, args);
 
 	list_for_each_entry(arg, &func_event->args, list) {
-		if (arg->arg < nr_args) {
-			/* Is arg an address and not a parameter? */
-			if (arg->arg < 0)
-				val = get_arg(arg, 0);
-			else
-				val = get_arg(arg, args[arg->arg]);
-		} else
+		if (arg->arg < nr_args)
+			val = get_arg(arg, args);
+		else
 			val = 0;
 		if (arg->array)
 			get_array(&entry->data[arg->offset], arg, val);
-		else
+		else if (arg->func_type == FUNC_TYPE_string) {
+			str_offset = sizeof(struct func_event_hdr) +
+				func_event->arg_offset;
+
+			str_idx += get_string(val, str_offset + str_idx,
+					      (unsigned int *)&entry->data[arg->offset],
+					      &entry->data[func_event->arg_offset + str_idx]);
+		} else
 			memcpy(&entry->data[arg->offset], &val, arg->size);
 	}
 
@@ -610,6 +739,11 @@ static void make_fmt(struct func_arg *arg, char *fmt)
 
 	fmt[c++] = '%';
 
+	if (arg->func_type == FUNC_TYPE_string) {
+		fmt[c++] = 's';
+		goto out;
+	}
+
 	if (arg->func_type == FUNC_TYPE_char) {
 		if (arg->array)
 			fmt[c++] = 's';
@@ -667,6 +801,7 @@ func_event_print(struct trace_iterator *iter, int flags,
 	char fmt[FMT_SIZE];
 	void *data;
 	bool comma = false;
+	int info;
 	int a;
 
 	entry = (struct func_event_hdr *)iter->ent;
@@ -692,6 +827,11 @@ func_event_print(struct trace_iterator *iter, int flags,
 				comma = true;
 				write_data(s, arg, fmt, data);
 			}
+		} else if (arg->func_type == FUNC_TYPE_string) {
+			info = *(unsigned int *)data;
+			info = (info & 0xffff) - sizeof(struct func_event_hdr);
+			data = &entry->data[info];
+			trace_seq_printf(s, fmt, data);
 		} else
 			write_data(s, arg, fmt, data);
 	}
@@ -866,7 +1006,10 @@ static int __set_print_fmt(struct func_event *func_event,
 				len = update_len(len, i);
 			}
 		} else {
-			i = snprintf(buf + r, len, ", REC->%s", arg->name);
+			if (arg->func_type == FUNC_TYPE_string)
+				i = snprintf(buf + r, len, ", __get_str(%s)", arg->name);
+			else
+				i = snprintf(buf + r, len, ", REC->%s", arg->name);
 			r += i;
 			len = update_len(len, i);
 		}
-- 
2.15.1