lkml.org 
[lkml]   [2017]   [Oct]   [9]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    Date
    From
    SubjectRe: ftrace: Save module init functions kallsyms symbols for tracing
    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

    \
     
     \ /
      Last update: 2017-10-09 21:52    [W:3.033 / U:0.116 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site