Message-ID: <CAEi0qNmwyEfk+pyNAVsrSCCn9YGM2n-VVnoJmYLMdou7adEakw@mail.gmail.com>
Date:   Sat, 7 Oct 2017 21:52:52 -0700
From:   "Joel Fernandes (Google)" <joel.opensrc@...il.com>
To:     Steven Rostedt <rostedt@...dmis.org>
Cc:     Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
        Ingo Molnar <mingo@...nel.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Jessica Yu <jeyu@...nel.org>,
        Joel Fernandes <joelaf@...gle.com>
Subject: Re: [for-next][PATCH 15/16] ftrace: Add freeing algorithm to free ftrace_mod_maps

Hi Steve,

On Sat, Oct 7, 2017 at 6:32 AM, Steven Rostedt <rostedt@...dmis.org> wrote:
> On Fri, 6 Oct 2017 23:41:25 -0700
> "Joel Fernandes (Google)" <joel.opensrc@...il.com> wrote:
>
>> Hi Steve,
>>
>> On Fri, Oct 6, 2017 at 11:07 AM, Steven Rostedt <rostedt@...dmis.org> wrote:
>> > From: "Steven Rostedt (VMware)" <rostedt@...dmis.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.
>>
>> Just checking for my understanding of this patch - wouldn't this also
>> mean that if there were any look ups of the init functions that may be
>> needed at trace output time, then those look ups wont be possible any
>> more after module is unloaded?
>
> Yes. That's true for all functions in the module. When a module is
> unloaded, all references to it in kallsyms is also freed. Try it on a
> current kernel. Trace a function in a module, then unload that module.
> The trace data will just show the ip hex address of the module function
> after that.
>

I tried your core branch and I see some weirdness with the filters:

Here's the code for the module:
================================================
#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>

void bar(void)
{
    printk(KERN_INFO "bar!\n");
}

void foo(void)
{
    printk(KERN_INFO "foo!\n");
    bar();
}

static int __init hello_init(void)
{
    printk(KERN_INFO "Hello world!\n");
    foo();
    return 0;
}

static void __exit hello_cleanup(void)
{
    printk(KERN_INFO "Cleaning up module.\n");
}

module_init(hello_init);
module_exit(hello_cleanup);
================================================

Following is a run with function tracing, during the first run I see
foo and bar are setup in the filters. After that when I unload and
load the module, I see that only "bar" is in the filters:

bash-4.3# echo '*:mod:test' > /d/tracing/set_ftrace_filter
bash-4.3# echo function > /d/tracing/current_tracer
bash-4.3# cat /d/tracing/set_ftrace_filter
*:mod:test
bash-4.3# modprobe test
bash-4.3# cat /d/tracing/trace
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        modprobe-1050  [003] ....     1.653000: hello_init <-do_one_initcall
bash-4.3# cat /d/tracing/set_ftrace_filter
bar [test]
foo [test]
bash-4.3# rmmod test
bash-4.3# cat /d/tracing/set_ftrace_filter
bash-4.3# sleep 2
bash-4.3# modprobe test
bash-4.3# cat /d/tracing/trace
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
        modprobe-1050  [003] ....     1.653000: bar <-do_one_initcall
bash-4.3# cat /d/tracing/set_ftrace_filter
bar [test]                                       <--- bar is still in
the filter list
bash-4.3#

Interestingly this also shows that the symbol conversion can be
unreliable if another module was loaded into the same address, in this
case 'bar' was loaded at the same address as 'hello_init' the second
time so during the second cat of the trace file, it shows a different
symbol name.

Also could you let me know what is the correct behavior of the filters
after a module being traced is unloaded, are the filters supposed to
be setup again after the module is unloaded, before the module can be
loaded again?

Also I wasn't able to see the call from hello_init -> bar and bar ->
foo so I'm not fully sure if that's a bug or I did something wrong.
I'm happy to try out anything you suggest.

>> I guess having a reference somehow on the ftrace_mod_map descriptor if
>> there are any entries in the trace buffer that need it can help
>> prevent that but it could be too expensive for not much return since
>> most likely the user wouldn't unload modules before trace collection
>> in normal usage.
>
> Right, I have thought about this, and I haven't come up with an
> inexpensive way to do this. As this has been the default operation of
> all module functions, and I haven't heard much complaining about it (I
> think I may have had a single complaint), I didn't put too much effort
> into it.

> I need to look at the approach that Jessica sent me. Perhaps there's

Yes, I think that approach is better. But I think it would have the
same issue (that if the init sections are freed and say used by other
loaded modules), then the trace output would incorrectly show a
different symbol name than the one from the module at the time the
trace record was generated.

thanks,

- Joel

Powered by blists - more mailing lists