[RFC][PATCH 0/5] tracing: Allow module init functions to be traced

[RFC][PATCH 0/5] tracing: Allow module init functions to be traced

[Steven Rostedt]

Last release, module functions can be enabled before they are loaded
by echoing in ":mod:module-name" into set_ftrace_filter before the
module is loaded. When the module is loaded, its functions will be
enabled for tracing. Now it makes sense to enable module init functions
as well (kernel init functions can already be traced).

The first patch adds a function ftrace_free_mem() to let module code
tell ftrace to free the init functions from its tables so that new
enabling or disabling of function tracing does not try to modify
text that no longer exists in memory.

The second patch enables tracing of init functions from within modules.

The third patch adds kallsyms of those init functions so they look
like funtion names and not function pointers within the trace.

The fourth patch frees the saved kallsym name maps of the function
names to the module init addresses.

The last patch has kallsyms display the module init functions.


Steven Rostedt (VMware) (5):
      ftrace: Add a ftrace_free_mem() function for modules to use
      ftrace: Allow module init functions to be traced
      ftrace: Save module init functions kallsyms symbols for tracing
      ftrace: Add freeing algorithm to free ftrace_mod_maps
      ftrace/kallsyms: Have /proc/kallsyms show saved mod init functions

----
 include/linux/ftrace.h |  26 ++++++
 include/linux/init.h   |   4 +-
 kernel/kallsyms.c      |  38 +++++++--
 kernel/module.c        |   2 +
 kernel/trace/ftrace.c  | 226 ++++++++++++++++++++++++++++++++++++++++++++++++-
 5 files changed, 284 insertions(+), 12 deletions(-)

[RFC][PATCH 1/5] ftrace: Add a ftrace_free_mem() function for modules to use

[Steven Rostedt]

[-- Attachment #1: 0001-ftrace-Add-a-ftrace_free_mem-function-for-modules-to.patch --]
[-- Type: text/plain, Size: 1977 bytes --]

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

In order to be able to trace module init functions, the module code needs to
tell ftrace what is being freed when the init sections are freed. Use the
code that the main init calls to tell ftrace to free the main init sections.
This requires passing in a start and end address to free.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/linux/ftrace.h |  2 ++
 kernel/trace/ftrace.c  | 14 +++++++++++---
 2 files changed, 13 insertions(+), 3 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 2e028854bac7..47fc404ad233 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -151,8 +151,10 @@ struct ftrace_ops_hash {
 };
 
 void ftrace_free_init_mem(void);
+void ftrace_free_mem(void *start, void *end);
 #else
 static inline void ftrace_free_init_mem(void) { }
+static inline void ftrace_free_mem(void *start, void *end) { }
 #endif
 
 /*
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 6abfafd7f173..84cb5928665a 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -5868,10 +5868,10 @@ void ftrace_module_init(struct module *mod)
 }
 #endif /* CONFIG_MODULES */
 
-void __init ftrace_free_init_mem(void)
+void ftrace_free_mem(void *start_ptr, void *end_ptr)
 {
-	unsigned long start = (unsigned long)(&__init_begin);
-	unsigned long end = (unsigned long)(&__init_end);
+	unsigned long start = (unsigned long)(start_ptr);
+	unsigned long end = (unsigned long)(end_ptr);
 	struct ftrace_page **last_pg = &ftrace_pages_start;
 	struct ftrace_page *pg;
 	struct dyn_ftrace *rec;
@@ -5913,6 +5913,14 @@ void __init ftrace_free_init_mem(void)
 	mutex_unlock(&ftrace_lock);
 }
 
+void __init ftrace_free_init_mem(void)
+{
+	void *start = (void *)(&__init_begin);
+	void *end = (void *)(&__init_end);
+
+	ftrace_free_mem(start, end);
+}
+
 void __init ftrace_init(void)
 {
 	extern unsigned long __start_mcount_loc[];
-- 
2.13.2

[RFC][PATCH 2/5] ftrace: Allow module init functions to be traced

[Steven Rostedt]

[-- Attachment #1: 0002-ftrace-Allow-module-init-functions-to-be-traced.patch --]
[-- Type: text/plain, Size: 2260 bytes --]

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

Allow for module init sections to be traced as well as core kernel init
sections. Now that filtering modules functions can be stored, for when they
are loaded, it makes sense to be able to trace them.

Cc: Jessica Yu <jeyu@kernel.org>
Cc: Rusty Russell <rusty@rustcorp.com.au>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/linux/init.h  | 4 +---
 kernel/module.c       | 2 ++
 kernel/trace/ftrace.c | 3 ++-
 3 files changed, 5 insertions(+), 4 deletions(-)

diff --git a/include/linux/init.h b/include/linux/init.h
index 94769d687cf0..a779c1816437 100644
--- a/include/linux/init.h
+++ b/include/linux/init.h
@@ -39,7 +39,7 @@
 
 /* These are for everybody (although not all archs will actually
    discard it in modules) */
-#define __init		__section(.init.text) __cold __inittrace __latent_entropy
+#define __init		__section(.init.text) __cold  __latent_entropy
 #define __initdata	__section(.init.data)
 #define __initconst	__section(.init.rodata)
 #define __exitdata	__section(.exit.data)
@@ -68,10 +68,8 @@
 
 #ifdef MODULE
 #define __exitused
-#define __inittrace notrace
 #else
 #define __exitused  __used
-#define __inittrace
 #endif
 
 #define __exit          __section(.exit.text) __exitused __cold notrace
diff --git a/kernel/module.c b/kernel/module.c
index 40f983cbea81..c1267ae10239 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -3473,6 +3473,8 @@ static noinline int do_init_module(struct module *mod)
 	if (!mod->async_probe_requested && (current->flags & PF_USED_ASYNC))
 		async_synchronize_full();
 
+	ftrace_free_mem(mod->init_layout.base, mod->init_layout.base +
+			mod->init_layout.size);
 	mutex_lock(&module_mutex);
 	/* Drop initial reference. */
 	module_put(mod);
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 84cb5928665a..7f7c56d532fd 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -5821,7 +5821,8 @@ void ftrace_module_enable(struct module *mod)
 		 * not part of this module, then skip this pg,
 		 * which the "break" will do.
 		 */
-		if (!within_module_core(rec->ip, mod))
+		if (!within_module_core(rec->ip, mod) &&
+		    !within_module_init(rec->ip, mod))
 			break;
 
 		cnt = 0;
-- 
2.13.2

[RFC][PATCH 3/5] ftrace: Save module init functions kallsyms symbols for tracing

[Steven Rostedt]

[-- Attachment #1: 0003-ftrace-Save-module-init-functions-kallsyms-symbols-f.patch --]
[-- Type: text/plain, Size: 10813 bytes --]

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

If function tracing is active when the module init functions are freed, then
store them to be referenced by kallsyms. As module init functions can now be
traced on module load, they were useless:

 ># echo ':mod:snd_seq' > set_ftrace_filter
 ># echo function > current_tracer
 ># modprobe snd_seq
 ># cat trace
 # tracer: function
 #
 #                              _-----=> irqs-off
 #                             / _----=> need-resched
 #                            | / _---=> hardirq/softirq
 #                            || / _--=> preempt-depth
 #                            ||| /     delay
 #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
 #              | |       |   ||||       |         |
         modprobe-2786  [000] ....  3189.037874: 0xffffffffa0860000 <-do_one_initcall
         modprobe-2786  [000] ....  3189.037876: 0xffffffffa086004d <-0xffffffffa086000f
         modprobe-2786  [000] ....  3189.037876: 0xffffffffa086010d <-0xffffffffa0860018
         modprobe-2786  [000] ....  3189.037877: 0xffffffffa086011a <-0xffffffffa0860021
         modprobe-2786  [000] ....  3189.037877: 0xffffffffa0860080 <-0xffffffffa086002a
         modprobe-2786  [000] ....  3189.039523: 0xffffffffa0860400 <-0xffffffffa0860033
         modprobe-2786  [000] ....  3189.039523: 0xffffffffa086038a <-0xffffffffa086041c
         modprobe-2786  [000] ....  3189.039591: 0xffffffffa086038a <-0xffffffffa0860436
         modprobe-2786  [000] ....  3189.039657: 0xffffffffa086038a <-0xffffffffa0860450
         modprobe-2786  [000] ....  3189.039719: 0xffffffffa0860127 <-0xffffffffa086003c
         modprobe-2786  [000] ....  3189.039742: snd_seq_create_kernel_client <-0xffffffffa08601f6

When the output is shown, the kallsyms for the module init functions have
already been freed, and the output of the trace can not convert them to
their function names.

Now this looks like this:

 # tracer: function
 #
 #                              _-----=> irqs-off
 #                             / _----=> need-resched
 #                            | / _---=> hardirq/softirq
 #                            || / _--=> preempt-depth
 #                            ||| /     delay
 #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
 #              | |       |   ||||       |         |
         modprobe-2463  [002] ....   174.243237: alsa_seq_init <-do_one_initcall
         modprobe-2463  [002] ....   174.243239: client_init_data <-alsa_seq_init
         modprobe-2463  [002] ....   174.243240: snd_sequencer_memory_init <-alsa_seq_init
         modprobe-2463  [002] ....   174.243240: snd_seq_queues_init <-alsa_seq_init
         modprobe-2463  [002] ....   174.243240: snd_sequencer_device_init <-alsa_seq_init
         modprobe-2463  [002] ....   174.244860: snd_seq_info_init <-alsa_seq_init
         modprobe-2463  [002] ....   174.244861: create_info_entry <-snd_seq_info_init
         modprobe-2463  [002] ....   174.244936: create_info_entry <-snd_seq_info_init
         modprobe-2463  [002] ....   174.245003: create_info_entry <-snd_seq_info_init
         modprobe-2463  [002] ....   174.245072: snd_seq_system_client_init <-alsa_seq_init
         modprobe-2463  [002] ....   174.245094: snd_seq_create_kernel_client <-snd_seq_system_client_init

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/linux/ftrace.h |  19 ++++++-
 kernel/kallsyms.c      |   5 ++
 kernel/module.c        |   2 +-
 kernel/trace/ftrace.c  | 145 ++++++++++++++++++++++++++++++++++++++++++++++++-
 4 files changed, 166 insertions(+), 5 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 47fc404ad233..99b770228739 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -51,6 +51,21 @@ static inline void early_trace_init(void) { }
 struct module;
 struct ftrace_hash;
 
+#if defined(CONFIG_FUNCTION_TRACER) && defined(CONFIG_MODULES) && \
+	defined(CONFIG_DYNAMIC_FTRACE)
+const char *
+ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
+		   unsigned long *off, char **modname, char *sym);
+#else
+static inline const char *
+ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
+		   unsigned long *off, char **modname, char *sym)
+{
+	return NULL;
+}
+#endif
+
+
 #ifdef CONFIG_FUNCTION_TRACER
 
 extern int ftrace_enabled;
@@ -151,10 +166,10 @@ struct ftrace_ops_hash {
 };
 
 void ftrace_free_init_mem(void);
-void ftrace_free_mem(void *start, void *end);
+void ftrace_free_mem(struct module *mod, void *start, void *end);
 #else
 static inline void ftrace_free_init_mem(void) { }
-static inline void ftrace_free_mem(void *start, void *end) { }
+static inline void ftrace_free_mem(struct module *mod, void *start, void *end) { }
 #endif
 
 /*
diff --git a/kernel/kallsyms.c b/kernel/kallsyms.c
index 127e7cfafa55..976ecb9275d9 100644
--- a/kernel/kallsyms.c
+++ b/kernel/kallsyms.c
@@ -24,6 +24,7 @@
 #include <linux/ctype.h>
 #include <linux/slab.h>
 #include <linux/filter.h>
+#include <linux/ftrace.h>
 #include <linux/compiler.h>
 
 #include <asm/sections.h>
@@ -337,6 +338,10 @@ const char *kallsyms_lookup(unsigned long addr,
 	if (!ret)
 		ret = bpf_address_lookup(addr, symbolsize,
 					 offset, modname, namebuf);
+
+	if (!ret)
+		ret = ftrace_mod_address_lookup(addr, symbolsize,
+						offset, modname, namebuf);
 	return ret;
 }
 
diff --git a/kernel/module.c b/kernel/module.c
index c1267ae10239..d0f48e402572 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -3473,7 +3473,7 @@ static noinline int do_init_module(struct module *mod)
 	if (!mod->async_probe_requested && (current->flags & PF_USED_ASYNC))
 		async_synchronize_full();
 
-	ftrace_free_mem(mod->init_layout.base, mod->init_layout.base +
+	ftrace_free_mem(mod, mod->init_layout.base, mod->init_layout.base +
 			mod->init_layout.size);
 	mutex_lock(&module_mutex);
 	/* Drop initial reference. */
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 7f7c56d532fd..2aad52802d70 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -5675,6 +5675,21 @@ static int ftrace_process_locs(struct module *mod,
 	return ret;
 }
 
+struct ftrace_mod_func {
+	struct list_head	list;
+	char			*name;
+	unsigned long		ip;
+	unsigned int		size;
+};
+
+struct ftrace_mod_map {
+	struct list_head	list;
+	struct module		*mod;
+	unsigned long		start_addr;
+	unsigned long		end_addr;
+	struct list_head	funcs;
+};
+
 #ifdef CONFIG_MODULES
 
 #define next_to_ftrace_page(p) container_of(p, struct ftrace_page, next)
@@ -5867,9 +5882,122 @@ void ftrace_module_init(struct module *mod)
 	ftrace_process_locs(mod, mod->ftrace_callsites,
 			    mod->ftrace_callsites + mod->num_ftrace_callsites);
 }
+
+static void save_ftrace_mod_rec(struct ftrace_mod_map *mod_map,
+				struct dyn_ftrace *rec)
+{
+	struct ftrace_mod_func *mod_func;
+	unsigned long symsize;
+	unsigned long offset;
+	char str[KSYM_SYMBOL_LEN];
+	char *modname;
+	const char *ret;
+
+	ret = kallsyms_lookup(rec->ip, &symsize, &offset, &modname, str);
+	if (!ret)
+		return;
+
+	mod_func = kmalloc(sizeof(*mod_func), GFP_KERNEL);
+	if (!mod_func)
+		return;
+
+	mod_func->name = kstrdup(str, GFP_KERNEL);
+	if (!mod_func->name) {
+		kfree(mod_func);
+		return;
+	}
+
+	mod_func->ip = rec->ip - offset;
+	mod_func->size = symsize;
+
+	list_add_rcu(&mod_func->list, &mod_map->funcs);
+}
+
+static LIST_HEAD(ftrace_mod_maps);
+
+static struct ftrace_mod_map *
+allocate_ftrace_mod_map(struct module *mod,
+			unsigned long start, unsigned long end)
+{
+	struct ftrace_mod_map *mod_map;
+
+	mod_map = kmalloc(sizeof(*mod_map), GFP_KERNEL);
+	if (!mod_map)
+		return NULL;
+
+	mod_map->mod = mod;
+	mod_map->start_addr = start;
+	mod_map->end_addr = end;
+
+	INIT_LIST_HEAD_RCU(&mod_map->funcs);
+
+	list_add_rcu(&mod_map->list, &ftrace_mod_maps);
+
+	return mod_map;
+}
+
+static const char *
+ftrace_func_address_lookup(struct ftrace_mod_map *mod_map,
+			   unsigned long addr, unsigned long *size,
+			   unsigned long *off, char *sym)
+{
+	struct ftrace_mod_func *found_func =  NULL;
+	struct ftrace_mod_func *mod_func;
+
+	list_for_each_entry_rcu(mod_func, &mod_map->funcs, list) {
+		if (addr >= mod_func->ip &&
+		    addr < mod_func->ip + mod_func->size) {
+			found_func = mod_func;
+			break;
+		}
+	}
+
+	if (found_func) {
+		if (size)
+			*size = found_func->size;
+		if (off)
+			*off = addr - found_func->ip;
+		if (sym)
+			strlcpy(sym, found_func->name, KSYM_NAME_LEN);
+
+		return found_func->name;
+	}
+
+	return NULL;
+}
+
+const char *
+ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
+		   unsigned long *off, char **modname, char *sym)
+{
+	struct ftrace_mod_map *mod_map;
+	const char *ret = NULL;
+
+	preempt_disable();
+	list_for_each_entry_rcu(mod_map, &ftrace_mod_maps, list) {
+		ret = ftrace_func_address_lookup(mod_map, addr, size, off, sym);
+		if (ret) {
+			if (modname)
+				*modname = mod_map->mod->name;
+			break;
+		}
+	}
+	preempt_enable();
+
+	return ret;
+}
+
+#else
+static inline void save_ftrace_mod_rec(struct dyn_ftrace *rec) { }
+static inline struct ftrace_mod_map *
+allocate_ftrace_mod_map(struct module *mod,
+			unsigned long start, unsigned long end)
+{
+	return NULL;
+}
 #endif /* CONFIG_MODULES */
 
-void ftrace_free_mem(void *start_ptr, void *end_ptr)
+void ftrace_free_mem(struct module *mod, void *start_ptr, void *end_ptr)
 {
 	unsigned long start = (unsigned long)(start_ptr);
 	unsigned long end = (unsigned long)(end_ptr);
@@ -5877,6 +6005,7 @@ void ftrace_free_mem(void *start_ptr, void *end_ptr)
 	struct ftrace_page *pg;
 	struct dyn_ftrace *rec;
 	struct dyn_ftrace key;
+	struct ftrace_mod_map *mod_map = NULL;
 	int order;
 
 	key.ip = start;
@@ -5884,6 +6013,14 @@ void ftrace_free_mem(void *start_ptr, void *end_ptr)
 
 	mutex_lock(&ftrace_lock);
 
+	/*
+	 * If we are freeing module init memory, then check if
+	 * any tracer is active. If so, we need to save a mapping of
+	 * the module functions being freed with the address.
+	 */
+	if (mod && ftrace_ops_list != &ftrace_list_end)
+		mod_map = allocate_ftrace_mod_map(mod, start, end);
+
 	for (pg = ftrace_pages_start; pg; last_pg = &pg->next, pg = *last_pg) {
 		if (end < pg->records[0].ip ||
 		    start >= (pg->records[pg->index - 1].ip + MCOUNT_INSN_SIZE))
@@ -5894,6 +6031,10 @@ void ftrace_free_mem(void *start_ptr, void *end_ptr)
 			      ftrace_cmp_recs);
 		if (!rec)
 			continue;
+
+		if (mod_map)
+			save_ftrace_mod_rec(mod_map, rec);
+
 		pg->index--;
 		ftrace_update_tot_cnt--;
 		if (!pg->index) {
@@ -5919,7 +6060,7 @@ void __init ftrace_free_init_mem(void)
 	void *start = (void *)(&__init_begin);
 	void *end = (void *)(&__init_end);
 
-	ftrace_free_mem(start, end);
+	ftrace_free_mem(NULL, start, end);
 }
 
 void __init ftrace_init(void)
-- 
2.13.2

[RFC][PATCH 4/5] ftrace: Add freeing algorithm to free ftrace_mod_maps

[Steven Rostedt]

[-- Attachment #1: 0004-ftrace-Add-freeing-algorithm-to-free-ftrace_mod_maps.patch --]
[-- Type: text/plain, Size: 2935 bytes --]

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

The ftrace_mod_map is a descriptor to save module init function names in
case they were traced, and the trace output needs to reference the function
name from the function address. But after the function is unloaded, it
the maps should be freed, as the rest of the function names are as well.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 kernel/trace/ftrace.c | 32 ++++++++++++++++++++++++++++++--
 1 file changed, 30 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 2aad52802d70..f0af3573b808 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -5683,6 +5683,7 @@ struct ftrace_mod_func {
 };
 
 struct ftrace_mod_map {
+	struct rcu_head		rcu;
 	struct list_head	list;
 	struct module		*mod;
 	unsigned long		start_addr;
@@ -5694,6 +5695,8 @@ struct ftrace_mod_map {
 
 #define next_to_ftrace_page(p) container_of(p, struct ftrace_page, next)
 
+static LIST_HEAD(ftrace_mod_maps);
+
 static int referenced_filters(struct dyn_ftrace *rec)
 {
 	struct ftrace_ops *ops;
@@ -5747,8 +5750,26 @@ static void clear_mod_from_hashes(struct ftrace_page *pg)
 	mutex_unlock(&trace_types_lock);
 }
 
+static void ftrace_free_mod_map(struct rcu_head *rcu)
+{
+	struct ftrace_mod_map *mod_map = container_of(rcu, struct ftrace_mod_map, rcu);
+	struct ftrace_mod_func *mod_func;
+	struct ftrace_mod_func *n;
+
+	/* All the contents of mod_map are now not visible to readers */
+	list_for_each_entry_safe(mod_func, n, &mod_map->funcs, list) {
+		kfree(mod_func->name);
+		list_del(&mod_func->list);
+		kfree(mod_func);
+	}
+
+	kfree(mod_map);
+}
+
 void ftrace_release_mod(struct module *mod)
 {
+	struct ftrace_mod_map *mod_map;
+	struct ftrace_mod_map *n;
 	struct dyn_ftrace *rec;
 	struct ftrace_page **last_pg;
 	struct ftrace_page *tmp_page = NULL;
@@ -5760,6 +5781,14 @@ void ftrace_release_mod(struct module *mod)
 	if (ftrace_disabled)
 		goto out_unlock;
 
+	list_for_each_entry_safe(mod_map, n, &ftrace_mod_maps, list) {
+		if (mod_map->mod == mod) {
+			list_del_rcu(&mod_map->list);
+			call_rcu_sched(&mod_map->rcu, ftrace_free_mod_map);
+			break;
+		}
+	}
+
 	/*
 	 * Each module has its own ftrace_pages, remove
 	 * them from the list.
@@ -5913,8 +5942,6 @@ static void save_ftrace_mod_rec(struct ftrace_mod_map *mod_map,
 	list_add_rcu(&mod_func->list, &mod_map->funcs);
 }
 
-static LIST_HEAD(ftrace_mod_maps);
-
 static struct ftrace_mod_map *
 allocate_ftrace_mod_map(struct module *mod,
 			unsigned long start, unsigned long end)
@@ -5973,6 +6000,7 @@ ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
 	struct ftrace_mod_map *mod_map;
 	const char *ret = NULL;
 
+	/* mod_map is freed via call_rcu_sched() */
 	preempt_disable();
 	list_for_each_entry_rcu(mod_map, &ftrace_mod_maps, list) {
 		ret = ftrace_func_address_lookup(mod_map, addr, size, off, sym);
-- 
2.13.2

[RFC][PATCH 5/5] ftrace/kallsyms: Have /proc/kallsyms show saved mod init functions

[Steven Rostedt]

[-- Attachment #1: 0005-ftrace-kallsyms-Have-proc-kallsyms-show-saved-mod-in.patch --]
[-- Type: text/plain, Size: 5428 bytes --]

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

If a module is loaded while tracing is enabled, then there's a possibility
that the module init functions were traced. These functions have their name
and address stored by ftrace such that it can translate the function address
that is written into the buffer into a human readable function name.

As userspace tools may be doing the same, they need a way to map function
names to their address as well. This is done through reading /proc/kallsyms.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 include/linux/ftrace.h |  9 +++++++++
 kernel/kallsyms.c      | 33 ++++++++++++++++++++++++++++-----
 kernel/trace/ftrace.c  | 40 ++++++++++++++++++++++++++++++++++++++++
 3 files changed, 77 insertions(+), 5 deletions(-)

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 99b770228739..3bfafeff26cc 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -56,6 +56,9 @@ struct ftrace_hash;
 const char *
 ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
 		   unsigned long *off, char **modname, char *sym);
+int ftrace_mod_get_kallsym(unsigned int symnum, unsigned long *value,
+			   char *type, char *name,
+			   char *module_name, int *exported);
 #else
 static inline const char *
 ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
@@ -63,6 +66,12 @@ ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
 {
 	return NULL;
 }
+static inline int ftrace_mod_get_kallsym(unsigned int symnum, unsigned long *value,
+					 char *type, char *name,
+					 char *module_name, int *exported)
+{
+	return 0;
+}
 #endif
 
 
diff --git a/kernel/kallsyms.c b/kernel/kallsyms.c
index 976ecb9275d9..97983dc1555c 100644
--- a/kernel/kallsyms.c
+++ b/kernel/kallsyms.c
@@ -479,6 +479,7 @@ EXPORT_SYMBOL(__print_symbol);
 struct kallsym_iter {
 	loff_t pos;
 	loff_t pos_mod_end;
+	loff_t pos_ftrace_mod_end;
 	unsigned long value;
 	unsigned int nameoff; /* If iterating in core kernel symbols. */
 	char type;
@@ -501,11 +502,25 @@ static int get_ksymbol_mod(struct kallsym_iter *iter)
 	return 1;
 }
 
+static int get_ksymbol_ftrace_mod(struct kallsym_iter *iter)
+{
+	int ret = ftrace_mod_get_kallsym(iter->pos - iter->pos_mod_end,
+					 &iter->value, &iter->type,
+					 iter->name, iter->module_name,
+					 &iter->exported);
+	if (ret < 0) {
+		iter->pos_ftrace_mod_end = iter->pos;
+		return 0;
+	}
+
+	return 1;
+}
+
 static int get_ksymbol_bpf(struct kallsym_iter *iter)
 {
 	iter->module_name[0] = '\0';
 	iter->exported = 0;
-	return bpf_get_kallsym(iter->pos - iter->pos_mod_end,
+	return bpf_get_kallsym(iter->pos - iter->pos_ftrace_mod_end,
 			       &iter->value, &iter->type,
 			       iter->name) < 0 ? 0 : 1;
 }
@@ -530,20 +545,28 @@ static void reset_iter(struct kallsym_iter *iter, loff_t new_pos)
 	iter->name[0] = '\0';
 	iter->nameoff = get_symbol_offset(new_pos);
 	iter->pos = new_pos;
-	if (new_pos == 0)
+	if (new_pos == 0) {
 		iter->pos_mod_end = 0;
+		iter->pos_ftrace_mod_end = 0;
+	}
 }
 
 static int update_iter_mod(struct kallsym_iter *iter, loff_t pos)
 {
 	iter->pos = pos;
 
+	if (iter->pos_ftrace_mod_end > 0 &&
+	    iter->pos_ftrace_mod_end < iter->pos)
+		return get_ksymbol_bpf(iter);
+
 	if (iter->pos_mod_end > 0 &&
 	    iter->pos_mod_end < iter->pos)
-		return get_ksymbol_bpf(iter);
+		return get_ksymbol_ftrace_mod(iter);
 
-	if (!get_ksymbol_mod(iter))
-		return get_ksymbol_bpf(iter);
+	if (!get_ksymbol_mod(iter)) {
+		if (!get_ksymbol_ftrace_mod(iter))
+			return get_ksymbol_bpf(iter);
+	}
 
 	return 1;
 }
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index f0af3573b808..fabf315b9cb1 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -5689,6 +5689,7 @@ struct ftrace_mod_map {
 	unsigned long		start_addr;
 	unsigned long		end_addr;
 	struct list_head	funcs;
+	unsigned int		num_funcs;
 };
 
 #ifdef CONFIG_MODULES
@@ -5939,6 +5940,8 @@ static void save_ftrace_mod_rec(struct ftrace_mod_map *mod_map,
 	mod_func->ip = rec->ip - offset;
 	mod_func->size = symsize;
 
+	mod_map->num_funcs++;
+
 	list_add_rcu(&mod_func->list, &mod_map->funcs);
 }
 
@@ -5955,6 +5958,7 @@ allocate_ftrace_mod_map(struct module *mod,
 	mod_map->mod = mod;
 	mod_map->start_addr = start;
 	mod_map->end_addr = end;
+	mod_map->num_funcs = 0;
 
 	INIT_LIST_HEAD_RCU(&mod_map->funcs);
 
@@ -6015,6 +6019,42 @@ ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
 	return ret;
 }
 
+int ftrace_mod_get_kallsym(unsigned int symnum, unsigned long *value,
+			   char *type, char *name,
+			   char *module_name, int *exported)
+{
+	struct ftrace_mod_map *mod_map;
+	struct ftrace_mod_func *mod_func;
+
+	preempt_disable();
+	list_for_each_entry_rcu(mod_map, &ftrace_mod_maps, list) {
+
+		if (symnum >= mod_map->num_funcs) {
+			symnum -= mod_map->num_funcs;
+			continue;
+		}
+
+		list_for_each_entry_rcu(mod_func, &mod_map->funcs, list) {
+			if (symnum > 1) {
+				symnum--;
+				continue;
+			}
+
+			*value = mod_func->ip;
+			*type = 'T';
+			strlcpy(name, mod_func->name, KSYM_NAME_LEN);
+			strlcpy(module_name, mod_map->mod->name, MODULE_NAME_LEN);
+			*exported = 1;
+			preempt_enable();
+			return 0;
+		}
+		WARN_ON(1);
+		break;
+	}
+	preempt_enable();
+	return -ERANGE;
+}
+
 #else
 static inline void save_ftrace_mod_rec(struct dyn_ftrace *rec) { }
 static inline struct ftrace_mod_map *
-- 
2.13.2

Re: ftrace: Save module init functions kallsyms symbols for tracing

[Jessica Yu]

+++ Steven Rostedt [19/09/17 14:28 +0000]:
>From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
>
>If function tracing is active when the module init functions are freed, then
>store them to be referenced by kallsyms. As module init functions can now be
>traced on module load, they were useless:
>
> ># echo ':mod:snd_seq' > set_ftrace_filter
> ># echo function > current_tracer
> ># modprobe snd_seq
> ># cat trace
> # tracer: function
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>         modprobe-2786  [000] ....  3189.037874: 0xffffffffa0860000 <-do_one_initcall
>         modprobe-2786  [000] ....  3189.037876: 0xffffffffa086004d <-0xffffffffa086000f
>         modprobe-2786  [000] ....  3189.037876: 0xffffffffa086010d <-0xffffffffa0860018
>         modprobe-2786  [000] ....  3189.037877: 0xffffffffa086011a <-0xffffffffa0860021
>         modprobe-2786  [000] ....  3189.037877: 0xffffffffa0860080 <-0xffffffffa086002a
>         modprobe-2786  [000] ....  3189.039523: 0xffffffffa0860400 <-0xffffffffa0860033
>         modprobe-2786  [000] ....  3189.039523: 0xffffffffa086038a <-0xffffffffa086041c
>         modprobe-2786  [000] ....  3189.039591: 0xffffffffa086038a <-0xffffffffa0860436
>         modprobe-2786  [000] ....  3189.039657: 0xffffffffa086038a <-0xffffffffa0860450
>         modprobe-2786  [000] ....  3189.039719: 0xffffffffa0860127 <-0xffffffffa086003c
>         modprobe-2786  [000] ....  3189.039742: snd_seq_create_kernel_client <-0xffffffffa08601f6
>
>When the output is shown, the kallsyms for the module init functions have
>already been freed, and the output of the trace can not convert them to
>their function names.
>
>Now this looks like this:
>
> # tracer: function
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>         modprobe-2463  [002] ....   174.243237: alsa_seq_init <-do_one_initcall
>         modprobe-2463  [002] ....   174.243239: client_init_data <-alsa_seq_init
>         modprobe-2463  [002] ....   174.243240: snd_sequencer_memory_init <-alsa_seq_init
>         modprobe-2463  [002] ....   174.243240: snd_seq_queues_init <-alsa_seq_init
>         modprobe-2463  [002] ....   174.243240: snd_sequencer_device_init <-alsa_seq_init
>         modprobe-2463  [002] ....   174.244860: snd_seq_info_init <-alsa_seq_init
>         modprobe-2463  [002] ....   174.244861: create_info_entry <-snd_seq_info_init
>         modprobe-2463  [002] ....   174.244936: create_info_entry <-snd_seq_info_init
>         modprobe-2463  [002] ....   174.245003: create_info_entry <-snd_seq_info_init
>         modprobe-2463  [002] ....   174.245072: snd_seq_system_client_init <-alsa_seq_init
>         modprobe-2463  [002] ....   174.245094: snd_seq_create_kernel_client <-snd_seq_system_client_init
>
>Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

Hi Steven,

Hm, I think there may be a way to make this easier and avoid all this
copying and freeing of ftrace_mod* descriptors. It is trivially easy
to save module init symbol information in the module's copy of the
symbol table (mod->kallsyms). Currently the module loader just ignores
symbols in init sections when building the module symtab. If we just
make that information available, ftrace can easily walk the module's
symtab to look for the init function symbol, its (former, before it
was freed) address, and its name in the module's strtab. If this
change is implemented we could probably omit patch 05 as well.

This might look like the following (patch applies on top of patches 01-04)
(not thoroughly tested yet!):

-->8--
diff --git a/include/linux/module.h b/include/linux/module.h
index fe5aa3736707..8a8bdf8397d3 100644
--- a/include/linux/module.h
+++ b/include/linux/module.h
@@ -541,6 +541,10 @@ const struct kernel_symbol *find_symbol(const char *name,
 					bool gplok,
 					bool warn);
 
+const char *get_module_ksymbol(struct module *mod,
+			       unsigned long addr,
+			       unsigned long *size,
+			       unsigned long *offset);
 /*
  * Walk the exported symbol table
  *
diff --git a/kernel/module.c b/kernel/module.c
index 279a469dc375..db85e47d4f2f 100644
--- a/kernel/module.c
+++ b/kernel/module.c
@@ -2596,7 +2596,7 @@ static bool is_core_symbol(const Elf_Sym *src, const Elf_Shdr *sechdrs,
 #ifndef CONFIG_KALLSYMS_ALL
 	    || !(sec->sh_flags & SHF_EXECINSTR)
 #endif
-	    || (sec->sh_entsize & INIT_OFFSET_MASK))
+	    )
 		return false;
 
 	return true;
@@ -3885,25 +3885,20 @@ static const char *symname(struct mod_kallsyms *kallsyms, unsigned int symnum)
 	return kallsyms->strtab + kallsyms->symtab[symnum].st_name;
 }
 
-static const char *get_ksymbol(struct module *mod,
+const char *get_module_ksymbol(struct module *mod,
 			       unsigned long addr,
 			       unsigned long *size,
 			       unsigned long *offset)
 {
-	unsigned int i, best = 0;
-	unsigned long nextval;
+	unsigned int i, found = 0;
 	struct mod_kallsyms *kallsyms = rcu_dereference_sched(mod->kallsyms);
+	Elf_Sym *sym, *symtab = kallsyms->symtab;
 
-	/* At worse, next value is at end of module */
-	if (within_module_init(addr, mod))
-		nextval = (unsigned long)mod->init_layout.base+mod->init_layout.text_size;
-	else
-		nextval = (unsigned long)mod->core_layout.base+mod->core_layout.text_size;
-
-	/* Scan for closest preceding symbol, and next symbol. (ELF
-	   starts real symbols at 1). */
+	/* Note: ELF symbols in a symbol table start at index 1). */
 	for (i = 1; i < kallsyms->num_symtab; i++) {
-		if (kallsyms->symtab[i].st_shndx == SHN_UNDEF)
+		sym = &symtab[i];
+
+		if (sym->st_shndx == SHN_UNDEF)
 			continue;
 
 		/* We ignore unnamed symbols: they're uninformative
@@ -3912,22 +3907,30 @@ static const char *get_ksymbol(struct module *mod,
 		    || is_arm_mapping_symbol(symname(kallsyms, i)))
 			continue;
 
-		if (kallsyms->symtab[i].st_value <= addr
-		    && kallsyms->symtab[i].st_value > kallsyms->symtab[best].st_value)
-			best = i;
-		if (kallsyms->symtab[i].st_value > addr
-		    && kallsyms->symtab[i].st_value < nextval)
-			nextval = kallsyms->symtab[i].st_value;
+		/*
+		 * These are "internal" symbols aliased to the real init and
+		 * exit functions in a module. But they're not particularly
+		 * informative in oopses/tracing. Skip them and use the module's
+		 * real init/exit functions instead.
+		 */
+		if (strcmp(symname(kallsyms, i), "init_module") == 0 ||
+		    strcmp(symname(kallsyms, i), "cleanup_module") == 0)
+			continue;
+
+		if (sym->st_value <= addr &&
+		    addr < sym->st_value + sym->st_size)
+			found = i;
 	}
 
-	if (!best)
+	if (!found)
 		return NULL;
 
 	if (size)
-		*size = nextval - kallsyms->symtab[best].st_value;
+		*size = symtab[found].st_size;
 	if (offset)
-		*offset = addr - kallsyms->symtab[best].st_value;
-	return symname(kallsyms, best);
+		*offset = addr - symtab[found].st_value;
+
+	return symname(kallsyms, found);
 }
 
 /* For kallsyms to ask for address resolution.  NULL means not found.  Careful
@@ -3946,7 +3949,7 @@ const char *module_address_lookup(unsigned long addr,
 	if (mod) {
 		if (modname)
 			*modname = mod->name;
-		ret = get_ksymbol(mod, addr, size, offset);
+		ret = get_module_ksymbol(mod, addr, size, offset);
 	}
 	/* Make a copy in here where it's safe */
 	if (ret) {
@@ -3969,7 +3972,7 @@ int lookup_module_symbol_name(unsigned long addr, char *symname)
 		if (within_module(addr, mod)) {
 			const char *sym;
 
-			sym = get_ksymbol(mod, addr, NULL, NULL);
+			sym = get_module_ksymbol(mod, addr, NULL, NULL);
 			if (!sym)
 				goto out;
 			strlcpy(symname, sym, KSYM_NAME_LEN);
@@ -3994,7 +3997,7 @@ int lookup_module_symbol_attrs(unsigned long addr, unsigned long *size,
 		if (within_module(addr, mod)) {
 			const char *sym;
 
-			sym = get_ksymbol(mod, addr, size, offset);
+			sym = get_module_ksymbol(mod, addr, size, offset);
 			if (!sym)
 				goto out;
 			if (modname)
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index f0af3573b808..c9862ddd3954 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -5675,20 +5675,12 @@ static int ftrace_process_locs(struct module *mod,
 	return ret;
 }
 
-struct ftrace_mod_func {
-	struct list_head	list;
-	char			*name;
-	unsigned long		ip;
-	unsigned int		size;
-};
-
 struct ftrace_mod_map {
 	struct rcu_head		rcu;
 	struct list_head	list;
 	struct module		*mod;
 	unsigned long		start_addr;
 	unsigned long		end_addr;
-	struct list_head	funcs;
 };
 
 #ifdef CONFIG_MODULES
@@ -5753,15 +5745,6 @@ static void clear_mod_from_hashes(struct ftrace_page *pg)
 static void ftrace_free_mod_map(struct rcu_head *rcu)
 {
 	struct ftrace_mod_map *mod_map = container_of(rcu, struct ftrace_mod_map, rcu);
-	struct ftrace_mod_func *mod_func;
-	struct ftrace_mod_func *n;
-
-	/* All the contents of mod_map are now not visible to readers */
-	list_for_each_entry_safe(mod_func, n, &mod_map->funcs, list) {
-		kfree(mod_func->name);
-		list_del(&mod_func->list);
-		kfree(mod_func);
-	}
 
 	kfree(mod_map);
 }
@@ -5912,36 +5895,6 @@ void ftrace_module_init(struct module *mod)
 			    mod->ftrace_callsites + mod->num_ftrace_callsites);
 }
 
-static void save_ftrace_mod_rec(struct ftrace_mod_map *mod_map,
-				struct dyn_ftrace *rec)
-{
-	struct ftrace_mod_func *mod_func;
-	unsigned long symsize;
-	unsigned long offset;
-	char str[KSYM_SYMBOL_LEN];
-	char *modname;
-	const char *ret;
-
-	ret = kallsyms_lookup(rec->ip, &symsize, &offset, &modname, str);
-	if (!ret)
-		return;
-
-	mod_func = kmalloc(sizeof(*mod_func), GFP_KERNEL);
-	if (!mod_func)
-		return;
-
-	mod_func->name = kstrdup(str, GFP_KERNEL);
-	if (!mod_func->name) {
-		kfree(mod_func);
-		return;
-	}
-
-	mod_func->ip = rec->ip - offset;
-	mod_func->size = symsize;
-
-	list_add_rcu(&mod_func->list, &mod_map->funcs);
-}
-
 static struct ftrace_mod_map *
 allocate_ftrace_mod_map(struct module *mod,
 			unsigned long start, unsigned long end)
@@ -5956,43 +5909,11 @@ allocate_ftrace_mod_map(struct module *mod,
 	mod_map->start_addr = start;
 	mod_map->end_addr = end;
 
-	INIT_LIST_HEAD_RCU(&mod_map->funcs);
-
 	list_add_rcu(&mod_map->list, &ftrace_mod_maps);
 
 	return mod_map;
 }
 
-static const char *
-ftrace_func_address_lookup(struct ftrace_mod_map *mod_map,
-			   unsigned long addr, unsigned long *size,
-			   unsigned long *off, char *sym)
-{
-	struct ftrace_mod_func *found_func =  NULL;
-	struct ftrace_mod_func *mod_func;
-
-	list_for_each_entry_rcu(mod_func, &mod_map->funcs, list) {
-		if (addr >= mod_func->ip &&
-		    addr < mod_func->ip + mod_func->size) {
-			found_func = mod_func;
-			break;
-		}
-	}
-
-	if (found_func) {
-		if (size)
-			*size = found_func->size;
-		if (off)
-			*off = addr - found_func->ip;
-		if (sym)
-			strlcpy(sym, found_func->name, KSYM_NAME_LEN);
-
-		return found_func->name;
-	}
-
-	return NULL;
-}
-
 const char *
 ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
 		   unsigned long *off, char **modname, char *sym)
@@ -6003,10 +5924,12 @@ ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
 	/* mod_map is freed via call_rcu_sched() */
 	preempt_disable();
 	list_for_each_entry_rcu(mod_map, &ftrace_mod_maps, list) {
-		ret = ftrace_func_address_lookup(mod_map, addr, size, off, sym);
+		ret = get_module_ksymbol(mod_map->mod, addr, size, off);
 		if (ret) {
 			if (modname)
 				*modname = mod_map->mod->name;
+			if (sym)
+				strlcpy(sym, ret, KSYM_NAME_LEN);
 			break;
 		}
 	}
@@ -6060,9 +5983,6 @@ void ftrace_free_mem(struct module *mod, void *start_ptr, void *end_ptr)
 		if (!rec)
 			continue;
 
-		if (mod_map)
-			save_ftrace_mod_rec(mod_map, rec);
-
 		pg->index--;
 		ftrace_update_tot_cnt--;
 		if (!pg->index) {
-->8--

Using the snd_seq example from patch 03, I get the same human-readable trace:

# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        modprobe-12748 [005] ....   138.964923: alsa_seq_init <-do_one_initcall
        modprobe-12748 [005] ....   138.964924: client_init_data <-alsa_seq_init
        modprobe-12748 [005] ....   138.964924: snd_sequencer_memory_init <-alsa_seq_init
        modprobe-12748 [005] ....   138.964924: snd_seq_queues_init <-alsa_seq_init
        modprobe-12748 [005] ....   138.964924: snd_sequencer_device_init <-alsa_seq_init
        modprobe-12748 [005] ....   138.964956: snd_seq_info_init <-alsa_seq_init
        modprobe-12748 [005] ....   138.964956: create_info_entry <-snd_seq_info_init
        modprobe-12748 [005] ....   138.964958: create_info_entry <-snd_seq_info_init
        modprobe-12748 [005] ....   138.964959: create_info_entry <-snd_seq_info_init
        modprobe-12748 [005] ....   138.964960: snd_seq_system_client_init <-alsa_seq_init
        modprobe-12748 [005] ....   138.964960: snd_seq_create_kernel_client <-snd_seq_system_client_init

In addition, the module init functions appear in /proc/kallsyms as
well. Thoughts? Would saving init symbol information in the module
symtab be sufficient for ftrace?

Thanks,

Jessica

Re: ftrace: Save module init functions kallsyms symbols for tracing

[Steven Rostedt]

On Fri, 6 Oct 2017 22:55:15 +0200
Jessica Yu <jeyu@kernel.org> wrote:

> +++ Steven Rostedt [19/09/17 14:28 +0000]:
> >From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
> >
> >If function tracing is active when the module init functions are freed, then
> >store them to be referenced by kallsyms. As module init functions can now be
> >traced on module load, they were useless:
> >  
> > ># echo ':mod:snd_seq' > set_ftrace_filter
> > ># echo function > current_tracer
> > ># modprobe snd_seq
> > ># cat trace  
> > # tracer: function
> > #
> > #                              _-----=> irqs-off
> > #                             / _----=> need-resched
> > #                            | / _---=> hardirq/softirq
> > #                            || / _--=> preempt-depth
> > #                            ||| /     delay
> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > #              | |       |   ||||       |         |
> >         modprobe-2786  [000] ....  3189.037874: 0xffffffffa0860000 <-do_one_initcall
> >         modprobe-2786  [000] ....  3189.037876: 0xffffffffa086004d <-0xffffffffa086000f
> >         modprobe-2786  [000] ....  3189.037876: 0xffffffffa086010d <-0xffffffffa0860018
> >         modprobe-2786  [000] ....  3189.037877: 0xffffffffa086011a <-0xffffffffa0860021
> >         modprobe-2786  [000] ....  3189.037877: 0xffffffffa0860080 <-0xffffffffa086002a
> >         modprobe-2786  [000] ....  3189.039523: 0xffffffffa0860400 <-0xffffffffa0860033
> >         modprobe-2786  [000] ....  3189.039523: 0xffffffffa086038a <-0xffffffffa086041c
> >         modprobe-2786  [000] ....  3189.039591: 0xffffffffa086038a <-0xffffffffa0860436
> >         modprobe-2786  [000] ....  3189.039657: 0xffffffffa086038a <-0xffffffffa0860450
> >         modprobe-2786  [000] ....  3189.039719: 0xffffffffa0860127 <-0xffffffffa086003c
> >         modprobe-2786  [000] ....  3189.039742: snd_seq_create_kernel_client <-0xffffffffa08601f6
> >
> >When the output is shown, the kallsyms for the module init functions have
> >already been freed, and the output of the trace can not convert them to
> >their function names.
> >
> >Now this looks like this:
> >
> > # tracer: function
> > #
> > #                              _-----=> irqs-off
> > #                             / _----=> need-resched
> > #                            | / _---=> hardirq/softirq
> > #                            || / _--=> preempt-depth
> > #                            ||| /     delay
> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > #              | |       |   ||||       |         |
> >         modprobe-2463  [002] ....   174.243237: alsa_seq_init <-do_one_initcall
> >         modprobe-2463  [002] ....   174.243239: client_init_data <-alsa_seq_init
> >         modprobe-2463  [002] ....   174.243240: snd_sequencer_memory_init <-alsa_seq_init
> >         modprobe-2463  [002] ....   174.243240: snd_seq_queues_init <-alsa_seq_init
> >         modprobe-2463  [002] ....   174.243240: snd_sequencer_device_init <-alsa_seq_init
> >         modprobe-2463  [002] ....   174.244860: snd_seq_info_init <-alsa_seq_init
> >         modprobe-2463  [002] ....   174.244861: create_info_entry <-snd_seq_info_init
> >         modprobe-2463  [002] ....   174.244936: create_info_entry <-snd_seq_info_init
> >         modprobe-2463  [002] ....   174.245003: create_info_entry <-snd_seq_info_init
> >         modprobe-2463  [002] ....   174.245072: snd_seq_system_client_init <-alsa_seq_init
> >         modprobe-2463  [002] ....   174.245094: snd_seq_create_kernel_client <-snd_seq_system_client_init
> >
> >Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>  
> 
> Hi Steven,
> 
> Hm, I think there may be a way to make this easier and avoid all this
> copying and freeing of ftrace_mod* descriptors. It is trivially easy
> to save module init symbol information in the module's copy of the
> symbol table (mod->kallsyms). Currently the module loader just ignores
> symbols in init sections when building the module symtab. If we just
> make that information available, ftrace can easily walk the module's
> symtab to look for the init function symbol, its (former, before it
> was freed) address, and its name in the module's strtab. If this
> change is implemented we could probably omit patch 05 as well.
> 
> This might look like the following (patch applies on top of patches 01-04)
> (not thoroughly tested yet!):

I just tried it. ;-)

This does simplify things, but it also causes some of the same issues
I've been trying to fix as well. But perhaps we can live with them.

I did:

 # rmmod kvm_intel
 # echo ":mod:kvm_intel" > set_ftrace_filter
 # echo function > current_tracer
 # modprobe kvm_intel
 # rmmod ip6table_filter
 # modprobe ip6table_filter
 # cat trace
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        modprobe-2856  [001] .... 15513.473966: vmx_init <-do_one_initcall
        modprobe-2856  [001] .... 15513.473968: ip6table_filter_init <-kvm_arch_init
        modprobe-2856  [001] .... 15513.473968: vmx_disabled_by_bios <-kvm_arch_init
        modprobe-2856  [001] .... 15513.479503: hardware_setup <-kvm_arch_hardware_setup
        modprobe-2856  [001] .... 15513.479514: setup_vmcs_config <-hardware_setup

Notice the "ip6table_filter_init" called by kvm_arch_init ;-)

I guess that's fine, as I don't have a solution for that either.

I did notice this though:

# grep ffffffffa0308000 /proc/kallsyms
ffffffffa0308000 t ip6table_filter_init	[ip6table_filter]
ffffffffa0308000 t init_module	[ip6table_filter]
ffffffffa0308000 t cpu_has_kvm_support	[kvm_intel]
ffffffffa0308000 t generic_driver_init	[snd_hda_codec_generic]
ffffffffa0308000 t init_module	[snd_hda_codec_generic]

As long as the last module loaded is the first one that gets picked up
by kallsyms, we should be good.

As I finished all my tests, I want to still post the changes. But if
this proves to be a better method, I can just revert them.

-- Steve


> 
> -->8--  
> diff --git a/include/linux/module.h b/include/linux/module.h
> index fe5aa3736707..8a8bdf8397d3 100644
> --- a/include/linux/module.h
> +++ b/include/linux/module.h
> @@ -541,6 +541,10 @@ const struct kernel_symbol *find_symbol(const char *name,
>  					bool gplok,
>  					bool warn);
>  
> +const char *get_module_ksymbol(struct module *mod,
> +			       unsigned long addr,
> +			       unsigned long *size,
> +			       unsigned long *offset);
>  /*
>   * Walk the exported symbol table
>   *
> diff --git a/kernel/module.c b/kernel/module.c
> index 279a469dc375..db85e47d4f2f 100644
> --- a/kernel/module.c
> +++ b/kernel/module.c
> @@ -2596,7 +2596,7 @@ static bool is_core_symbol(const Elf_Sym *src, const Elf_Shdr *sechdrs,
>  #ifndef CONFIG_KALLSYMS_ALL
>  	    || !(sec->sh_flags & SHF_EXECINSTR)
>  #endif
> -	    || (sec->sh_entsize & INIT_OFFSET_MASK))
> +	    )
>  		return false;
>  
>  	return true;
> @@ -3885,25 +3885,20 @@ static const char *symname(struct mod_kallsyms *kallsyms, unsigned int symnum)
>  	return kallsyms->strtab + kallsyms->symtab[symnum].st_name;
>  }
>  
> -static const char *get_ksymbol(struct module *mod,
> +const char *get_module_ksymbol(struct module *mod,
>  			       unsigned long addr,
>  			       unsigned long *size,
>  			       unsigned long *offset)
>  {
> -	unsigned int i, best = 0;
> -	unsigned long nextval;
> +	unsigned int i, found = 0;
>  	struct mod_kallsyms *kallsyms = rcu_dereference_sched(mod->kallsyms);
> +	Elf_Sym *sym, *symtab = kallsyms->symtab;
>  
> -	/* At worse, next value is at end of module */
> -	if (within_module_init(addr, mod))
> -		nextval = (unsigned long)mod->init_layout.base+mod->init_layout.text_size;
> -	else
> -		nextval = (unsigned long)mod->core_layout.base+mod->core_layout.text_size;
> -
> -	/* Scan for closest preceding symbol, and next symbol. (ELF
> -	   starts real symbols at 1). */
> +	/* Note: ELF symbols in a symbol table start at index 1). */
>  	for (i = 1; i < kallsyms->num_symtab; i++) {
> -		if (kallsyms->symtab[i].st_shndx == SHN_UNDEF)
> +		sym = &symtab[i];
> +
> +		if (sym->st_shndx == SHN_UNDEF)
>  			continue;
>  
>  		/* We ignore unnamed symbols: they're uninformative
> @@ -3912,22 +3907,30 @@ static const char *get_ksymbol(struct module *mod,
>  		    || is_arm_mapping_symbol(symname(kallsyms, i)))
>  			continue;
>  
> -		if (kallsyms->symtab[i].st_value <= addr
> -		    && kallsyms->symtab[i].st_value > kallsyms->symtab[best].st_value)
> -			best = i;
> -		if (kallsyms->symtab[i].st_value > addr
> -		    && kallsyms->symtab[i].st_value < nextval)
> -			nextval = kallsyms->symtab[i].st_value;
> +		/*
> +		 * These are "internal" symbols aliased to the real init and
> +		 * exit functions in a module. But they're not particularly
> +		 * informative in oopses/tracing. Skip them and use the module's
> +		 * real init/exit functions instead.
> +		 */
> +		if (strcmp(symname(kallsyms, i), "init_module") == 0 ||
> +		    strcmp(symname(kallsyms, i), "cleanup_module") == 0)
> +			continue;
> +
> +		if (sym->st_value <= addr &&
> +		    addr < sym->st_value + sym->st_size)
> +			found = i;
>  	}
>  
> -	if (!best)
> +	if (!found)
>  		return NULL;
>  
>  	if (size)
> -		*size = nextval - kallsyms->symtab[best].st_value;
> +		*size = symtab[found].st_size;
>  	if (offset)
> -		*offset = addr - kallsyms->symtab[best].st_value;
> -	return symname(kallsyms, best);
> +		*offset = addr - symtab[found].st_value;
> +
> +	return symname(kallsyms, found);
>  }
>  
>  /* For kallsyms to ask for address resolution.  NULL means not found.  Careful
> @@ -3946,7 +3949,7 @@ const char *module_address_lookup(unsigned long addr,
>  	if (mod) {
>  		if (modname)
>  			*modname = mod->name;
> -		ret = get_ksymbol(mod, addr, size, offset);
> +		ret = get_module_ksymbol(mod, addr, size, offset);
>  	}
>  	/* Make a copy in here where it's safe */
>  	if (ret) {
> @@ -3969,7 +3972,7 @@ int lookup_module_symbol_name(unsigned long addr, char *symname)
>  		if (within_module(addr, mod)) {
>  			const char *sym;
>  
> -			sym = get_ksymbol(mod, addr, NULL, NULL);
> +			sym = get_module_ksymbol(mod, addr, NULL, NULL);
>  			if (!sym)
>  				goto out;
>  			strlcpy(symname, sym, KSYM_NAME_LEN);
> @@ -3994,7 +3997,7 @@ int lookup_module_symbol_attrs(unsigned long addr, unsigned long *size,
>  		if (within_module(addr, mod)) {
>  			const char *sym;
>  
> -			sym = get_ksymbol(mod, addr, size, offset);
> +			sym = get_module_ksymbol(mod, addr, size, offset);
>  			if (!sym)
>  				goto out;
>  			if (modname)
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index f0af3573b808..c9862ddd3954 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -5675,20 +5675,12 @@ static int ftrace_process_locs(struct module *mod,
>  	return ret;
>  }
>  
> -struct ftrace_mod_func {
> -	struct list_head	list;
> -	char			*name;
> -	unsigned long		ip;
> -	unsigned int		size;
> -};
> -
>  struct ftrace_mod_map {
>  	struct rcu_head		rcu;
>  	struct list_head	list;
>  	struct module		*mod;
>  	unsigned long		start_addr;
>  	unsigned long		end_addr;
> -	struct list_head	funcs;
>  };
>  
>  #ifdef CONFIG_MODULES
> @@ -5753,15 +5745,6 @@ static void clear_mod_from_hashes(struct ftrace_page *pg)
>  static void ftrace_free_mod_map(struct rcu_head *rcu)
>  {
>  	struct ftrace_mod_map *mod_map = container_of(rcu, struct ftrace_mod_map, rcu);
> -	struct ftrace_mod_func *mod_func;
> -	struct ftrace_mod_func *n;
> -
> -	/* All the contents of mod_map are now not visible to readers */
> -	list_for_each_entry_safe(mod_func, n, &mod_map->funcs, list) {
> -		kfree(mod_func->name);
> -		list_del(&mod_func->list);
> -		kfree(mod_func);
> -	}
>  
>  	kfree(mod_map);
>  }
> @@ -5912,36 +5895,6 @@ void ftrace_module_init(struct module *mod)
>  			    mod->ftrace_callsites + mod->num_ftrace_callsites);
>  }
>  
> -static void save_ftrace_mod_rec(struct ftrace_mod_map *mod_map,
> -				struct dyn_ftrace *rec)
> -{
> -	struct ftrace_mod_func *mod_func;
> -	unsigned long symsize;
> -	unsigned long offset;
> -	char str[KSYM_SYMBOL_LEN];
> -	char *modname;
> -	const char *ret;
> -
> -	ret = kallsyms_lookup(rec->ip, &symsize, &offset, &modname, str);
> -	if (!ret)
> -		return;
> -
> -	mod_func = kmalloc(sizeof(*mod_func), GFP_KERNEL);
> -	if (!mod_func)
> -		return;
> -
> -	mod_func->name = kstrdup(str, GFP_KERNEL);
> -	if (!mod_func->name) {
> -		kfree(mod_func);
> -		return;
> -	}
> -
> -	mod_func->ip = rec->ip - offset;
> -	mod_func->size = symsize;
> -
> -	list_add_rcu(&mod_func->list, &mod_map->funcs);
> -}
> -
>  static struct ftrace_mod_map *
>  allocate_ftrace_mod_map(struct module *mod,
>  			unsigned long start, unsigned long end)
> @@ -5956,43 +5909,11 @@ allocate_ftrace_mod_map(struct module *mod,
>  	mod_map->start_addr = start;
>  	mod_map->end_addr = end;
>  
> -	INIT_LIST_HEAD_RCU(&mod_map->funcs);
> -
>  	list_add_rcu(&mod_map->list, &ftrace_mod_maps);
>  
>  	return mod_map;
>  }
>  
> -static const char *
> -ftrace_func_address_lookup(struct ftrace_mod_map *mod_map,
> -			   unsigned long addr, unsigned long *size,
> -			   unsigned long *off, char *sym)
> -{
> -	struct ftrace_mod_func *found_func =  NULL;
> -	struct ftrace_mod_func *mod_func;
> -
> -	list_for_each_entry_rcu(mod_func, &mod_map->funcs, list) {
> -		if (addr >= mod_func->ip &&
> -		    addr < mod_func->ip + mod_func->size) {
> -			found_func = mod_func;
> -			break;
> -		}
> -	}
> -
> -	if (found_func) {
> -		if (size)
> -			*size = found_func->size;
> -		if (off)
> -			*off = addr - found_func->ip;
> -		if (sym)
> -			strlcpy(sym, found_func->name, KSYM_NAME_LEN);
> -
> -		return found_func->name;
> -	}
> -
> -	return NULL;
> -}
> -
>  const char *
>  ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
>  		   unsigned long *off, char **modname, char *sym)
> @@ -6003,10 +5924,12 @@ ftrace_mod_address_lookup(unsigned long addr, unsigned long *size,
>  	/* mod_map is freed via call_rcu_sched() */
>  	preempt_disable();
>  	list_for_each_entry_rcu(mod_map, &ftrace_mod_maps, list) {
> -		ret = ftrace_func_address_lookup(mod_map, addr, size, off, sym);
> +		ret = get_module_ksymbol(mod_map->mod, addr, size, off);
>  		if (ret) {
>  			if (modname)
>  				*modname = mod_map->mod->name;
> +			if (sym)
> +				strlcpy(sym, ret, KSYM_NAME_LEN);
>  			break;
>  		}
>  	}
> @@ -6060,9 +5983,6 @@ void ftrace_free_mem(struct module *mod, void *start_ptr, void *end_ptr)
>  		if (!rec)
>  			continue;
>  
> -		if (mod_map)
> -			save_ftrace_mod_rec(mod_map, rec);
> -
>  		pg->index--;
>  		ftrace_update_tot_cnt--;
>  		if (!pg->index) {
> -->8--  
> 
> Using the snd_seq example from patch 03, I get the same human-readable trace:
> 
> # tracer: function
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |
>         modprobe-12748 [005] ....   138.964923: alsa_seq_init <-do_one_initcall
>         modprobe-12748 [005] ....   138.964924: client_init_data <-alsa_seq_init
>         modprobe-12748 [005] ....   138.964924: snd_sequencer_memory_init <-alsa_seq_init
>         modprobe-12748 [005] ....   138.964924: snd_seq_queues_init <-alsa_seq_init
>         modprobe-12748 [005] ....   138.964924: snd_sequencer_device_init <-alsa_seq_init
>         modprobe-12748 [005] ....   138.964956: snd_seq_info_init <-alsa_seq_init
>         modprobe-12748 [005] ....   138.964956: create_info_entry <-snd_seq_info_init
>         modprobe-12748 [005] ....   138.964958: create_info_entry <-snd_seq_info_init
>         modprobe-12748 [005] ....   138.964959: create_info_entry <-snd_seq_info_init
>         modprobe-12748 [005] ....   138.964960: snd_seq_system_client_init <-alsa_seq_init
>         modprobe-12748 [005] ....   138.964960: snd_seq_create_kernel_client <-snd_seq_system_client_init
> 
> In addition, the module init functions appear in /proc/kallsyms as
> well. Thoughts? Would saving init symbol information in the module
> symtab be sufficient for ftrace?
> 
> Thanks,
> 
> Jessica

Re: ftrace: Save module init functions kallsyms symbols for tracing

[Steven Rostedt]

On Mon, 9 Oct 2017 15:51:00 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:


> > Using the snd_seq example from patch 03, I get the same human-readable trace:
> > 
> > # tracer: function
> > #
> > #                              _-----=> irqs-off
> > #                             / _----=> need-resched
> > #                            | / _---=> hardirq/softirq
> > #                            || / _--=> preempt-depth
> > #                            ||| /     delay
> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> > #              | |       |   ||||       |         |
> >         modprobe-12748 [005] ....   138.964923: alsa_seq_init <-do_one_initcall
> >         modprobe-12748 [005] ....   138.964924: client_init_data <-alsa_seq_init
> >         modprobe-12748 [005] ....   138.964924: snd_sequencer_memory_init <-alsa_seq_init
> >         modprobe-12748 [005] ....   138.964924: snd_seq_queues_init <-alsa_seq_init
> >         modprobe-12748 [005] ....   138.964924: snd_sequencer_device_init <-alsa_seq_init
> >         modprobe-12748 [005] ....   138.964956: snd_seq_info_init <-alsa_seq_init
> >         modprobe-12748 [005] ....   138.964956: create_info_entry <-snd_seq_info_init
> >         modprobe-12748 [005] ....   138.964958: create_info_entry <-snd_seq_info_init
> >         modprobe-12748 [005] ....   138.964959: create_info_entry <-snd_seq_info_init
> >         modprobe-12748 [005] ....   138.964960: snd_seq_system_client_init <-alsa_seq_init
> >         modprobe-12748 [005] ....   138.964960: snd_seq_create_kernel_client <-snd_seq_system_client_init
> > 
> > In addition, the module init functions appear in /proc/kallsyms as
> > well. Thoughts? Would saving init symbol information in the module
> > symtab be sufficient for ftrace?

Hi Jessica,

Are you going to have time to work on this more?

Should we allow multiple init addresses to appear, or should there be
some check to see if they already exist, and remove the older one?

Ideally, I could have a way to know if a module init function was
traced and its address was stored in a ring buffer, and keep the init
mapping around and used for that buffer, and free it when the buffer
is cleared, and there's no other buffers that have a reference to it.
But I need to find a low overhead way to account for this.

Personally, I would rather have the mappings saved in the symbol tables
in the module code.

If we can come up with a better module way, I'll convert to that. But
as I want to get this code upstream by 4.15, I'm going to continue with
what I have.

Thoughts?

-- Steve

Re: ftrace: Save module init functions kallsyms symbols for tracing

[Jessica Yu]

+++ Steven Rostedt [10/10/17 15:45 +0000]:
>On Mon, 9 Oct 2017 15:51:00 -0400
>Steven Rostedt <rostedt@goodmis.org> wrote:
>
>
>> > Using the snd_seq example from patch 03, I get the same human-readable trace:
>> >
>> > # tracer: function
>> > #
>> > #                              _-----=> irqs-off
>> > #                             / _----=> need-resched
>> > #                            | / _---=> hardirq/softirq
>> > #                            || / _--=> preempt-depth
>> > #                            ||| /     delay
>> > #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
>> > #              | |       |   ||||       |         |
>> >         modprobe-12748 [005] ....   138.964923: alsa_seq_init <-do_one_initcall
>> >         modprobe-12748 [005] ....   138.964924: client_init_data <-alsa_seq_init
>> >         modprobe-12748 [005] ....   138.964924: snd_sequencer_memory_init <-alsa_seq_init
>> >         modprobe-12748 [005] ....   138.964924: snd_seq_queues_init <-alsa_seq_init
>> >         modprobe-12748 [005] ....   138.964924: snd_sequencer_device_init <-alsa_seq_init
>> >         modprobe-12748 [005] ....   138.964956: snd_seq_info_init <-alsa_seq_init
>> >         modprobe-12748 [005] ....   138.964956: create_info_entry <-snd_seq_info_init
>> >         modprobe-12748 [005] ....   138.964958: create_info_entry <-snd_seq_info_init
>> >         modprobe-12748 [005] ....   138.964959: create_info_entry <-snd_seq_info_init
>> >         modprobe-12748 [005] ....   138.964960: snd_seq_system_client_init <-alsa_seq_init
>> >         modprobe-12748 [005] ....   138.964960: snd_seq_create_kernel_client <-snd_seq_system_client_init
>> >
>> > In addition, the module init functions appear in /proc/kallsyms as
>> > well. Thoughts? Would saving init symbol information in the module
>> > symtab be sufficient for ftrace?
>
>Hi Jessica,
>
>Are you going to have time to work on this more?
>
>Should we allow multiple init addresses to appear, or should there be
>some check to see if they already exist, and remove the older one?

In /proc/kallsyms? IMO it would be better to make the behavior as
general as possible, as in, we just keep all symbols in each module's
symtab without regard to other modules. I think the code could quickly
get messy and complex if we're cross-checking other module symtabs
every time a module is loaded/unloaded to find which __init symbols
we should no longer keep.

Also worth noting, kallsyms already returns "live" symbols first
before __init ones in this patch, since module_address_lookup() is
called before ftrace_mod_address_lookup(). But I still need to look
into handling collisions in the case of multiple module init funcs
with the same addr, in this case I think we agree that kallsyms should
favor the last loaded module.

>Ideally, I could have a way to know if a module init function was
>traced and its address was stored in a ring buffer, and keep the init
>mapping around and used for that buffer, and free it when the buffer
>is cleared, and there's no other buffers that have a reference to it.
>But I need to find a low overhead way to account for this.
>
>Personally, I would rather have the mappings saved in the symbol tables
>in the module code.
>
>If we can come up with a better module way, I'll convert to that. But
>as I want to get this code upstream by 4.15, I'm going to continue with
>what I have.
>
>Thoughts?

Hm, I am not sure how to fix the symbol mix-up issue when reading out the
trace. I will try to clarify the limitation with an example...

 # rmmod snd_seq
 # echo ':mod:snd_seq' > set_ftrace_filter
 # echo function > current_tracer
 # modprobe snd_seq
 # cat trace
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        modprobe-15680 [000] ....   882.128680: alsa_seq_init <-do_one_initcall
        modprobe-15680 [000] ....   882.128683: client_init_data <-alsa_seq_init
        modprobe-15680 [000] ....   882.128683: snd_sequencer_memory_init <-alsa_seq_init
        modprobe-15680 [000] ....   882.128683: snd_seq_queues_init <-alsa_seq_init
        modprobe-15680 [000] ....   882.128683: snd_sequencer_device_init <-alsa_seq_init
        modprobe-15680 [000] ....   882.128765: snd_seq_info_init <-alsa_seq_init
        modprobe-15680 [000] ....   882.128765: create_info_entry <-snd_seq_info_init
        modprobe-15680 [000] ....   882.128770: create_info_entry <-snd_seq_info_init
        modprobe-15680 [000] ....   882.128771: create_info_entry <-snd_seq_info_init
        modprobe-15680 [000] ....   882.128772: snd_seq_system_client_init <-alsa_seq_init
        modprobe-15680 [000] ....   882.128772: snd_seq_create_kernel_client <-snd_seq_system_client_init
        modprobe-15680 [000] ....   882.128773: seq_create_client1 <-snd_seq_create_kernel_client
        modprobe-15680 [000] ....   882.128773: snd_seq_pool_new <-seq_create_client1

		[output snipped]

OK, so far so good. But as we load/unload modules, and as addresses get reused,
our trace output starts to get messed up:

 # modprobe xxhash
 # cat trace
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        modprobe-15680 [000] ....   882.128680: xxh32 <-do_one_initcall
        modprobe-15680 [000] ....   882.128683: xxh32 <-xxh32
        modprobe-15680 [000] ....   882.128683: xxh32 <-xxh32
        modprobe-15680 [000] ....   882.128683: xxh32 <-xxh32
        modprobe-15680 [000] ....   882.128683: xxh32 <-xxh32
        modprobe-15680 [000] ....   882.128765: xxh64 <-xxh32
        modprobe-15680 [000] ....   882.128765: xxh64 <-xxh64
        modprobe-15680 [000] ....   882.128770: xxh64 <-xxh64
        modprobe-15680 [000] ....   882.128771: xxh64 <-xxh64
        modprobe-15680 [000] ....   882.128772: xxh32 <-xxh32
        modprobe-15680 [000] ....   882.128772: snd_seq_create_kernel_client <-xxh64
        modprobe-15680 [000] ....   882.128773: seq_create_client1 <-snd_seq_create_kernel_client

% grep ffffffffc0d16000 /proc/kallsyms
ffffffffc0d16000 T xxh32        [xxhash]
ffffffffc0d16000 t alsa_seq_init        [snd_seq]
ffffffffc0d16000 t init_module  [snd_seq]
ffffffffc0d16000 t crypto_ccm_module_init       [ccm]
ffffffffc0d16000 t init_module  [ccm]

Since the address lookups in the trace output are being done by kallsyms,
kallsyms will return the "live" symbol xxh32 from the xxhash module (which is
in the module core memory, it's not an __init function) rather than the defunct
alsa_seq_init symbol in freed module init memory. This is because
module_address_lookup(), called from kallsyms_lookup, only takes core module
syms into account. I think this behavior makes sense, but perhaps it's not
completely suited for ftrace's use case here?

Maybe if there is some way to know which module(s) are being actively traced,
then it is possible to narrow the symbol search space to just those modules'
symbol table(s) when displaying the trace output. So if we know that functions
from snd_seq are being traced and *not* functions from xxhash, then we'd find
alsa_seq_init and not xxh32 for example. Do you think something like this would
be possible to do? In this case, ftrace might need something more specialized
than kallsyms_lookup().. 

And yeah, I would rather eventually keep the module init function ->
address mapping in the module symbol tables. The information is
already there, we just don't make it available. __init syms from the
core kernel stay listed in /proc/kallsyms, so I think it's OK to do
this for modules too. And ftrace wouldn't need to do the extra
bookkeeping.

Unfortunately, my next two weeks are looking grim, so I don't think I
can invest too much time on this before the 4.15 merge window :-/ I
don't want to slow you down, so for now please continue with what you
have, but I can gladly revisit this issue with you after the merge
window.

Thanks!

Jessica

Re: ftrace: Save module init functions kallsyms symbols for tracing

[Steven Rostedt]

On Wed, 11 Oct 2017 13:19:42 +0200
Jessica Yu <jeyu@kernel.org> wrote:

> Unfortunately, my next two weeks are looking grim, so I don't think I
> can invest too much time on this before the 4.15 merge window :-/ I
> don't want to slow you down, so for now please continue with what you
> have, but I can gladly revisit this issue with you after the merge
> window.

OK, I'm going to continue the current path. Then we can move the work
back into the module code for 4.16.

Thanks!

-- Steve