On Fri, 6 Oct 2017 22:55:15 +0200 Jessica Yu <[email protected]> wrote:
> +++ Steven Rostedt [19/09/17 14:28 +0000]: > >From: "Steven Rostedt (VMware)" <[email protected]> > > > >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) <[email protected]> > > 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
