Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Wed, 17 Oct 2018 09:28:55 -0300
From:   Arnaldo Carvalho de Melo <acme@kernel.org>
To:     Masami Hiramatsu <mhiramat@kernel.org>
Cc:     Arnaldo Carvalho de Melo <acme@redhat.com>,
        David Miller <davem@davemloft.net>,
        linux-kernel@vger.kernel.org,
        Peter Zijlstra <peterz@infradead.org>,
        Ingo Molnar <mingo@kernel.org>, Jiri Olsa <jolsa@redhat.com>,
        Namhyung Kim <namhyung@gmail.com>
Subject: Re: perf's handling of unfindable user symbols...
Message-ID: <20181017122855.GB31465@kernel.org>
References: <20181014.004238.292485794143606801.davem@davemloft.net>
 <20181015222546.GA2159@redhat.com>
 <20181015.160246.58484704665215987.davem@davemloft.net>
 <20181016184506.GB3254@redhat.com>
 <20181017172226.7274498db2bbe3431c3f4057@kernel.org>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20181017172226.7274498db2bbe3431c3f4057@kernel.org>
User-Agent: Mutt/1.9.2 (2017-12-15)
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

Em Wed, Oct 17, 2018 at 05:22:26PM +0900, Masami Hiramatsu escreveu:
> On Tue, 16 Oct 2018 15:45:06 -0300
> Arnaldo Carvalho de Melo <acme@redhat.com> wrote:
> > So, I thought something had changed and in the past we would somehow
> > find that address in the kallsyms, but I couldn't find anything to back
> > that up, the patch introducing this is over a decade old, lots of things
> > changed, so I was just thinking I was missing something.

> > I tried a gtod busy loop to generate vdso activity and added a 'perf
> > probe' at that branch, on x86_64 to see if it ever gets hit:

> > Made thread__find_map() noinline, as 'perf probe' in lines of inline
> > functions seems to not be working, only at function start. (Masami?)
 
> Thank you for reporting it. Hmm, what happened when you did it?
> I checked some points, but seems no problem.
> (Would you see no line number? or defined event didn't work?)

So, the problem is with a function in the perf tool that ends up inlined
in five places, then when I ask for a line inside of this function to be
probed, it creates 4 probes, one in each of the function it inlines,
see:

[root@jouet ~]# perf probe -x ~/bin/perf -L thread__find_map:43
<thread__find_map@/home/acme/git/perf/tools/perf/util/event.c:43>
     43                 return NULL;
                }
         
     46         al->map = map_groups__find(mg, al->addr);
     47         if (al->map != NULL) {
                        /*
                         * Kernel maps might be changed when loading symbols so loading
                         * must be done prior to using kernel maps.
                         */
                        if (load_map)
     53                         map__load(al->map);
     54                 al->addr = al->map->map_ip(al->map, al->addr);
                }
         
     57         return al->map;
     58  }
         
         struct symbol *thread__find_symbol(struct thread *thread, u8 cpumode,
                                           u64 addr, struct addr_location *al)

[root@jouet ~]# 

So I know that everytime we look for a mmap in a thread and we find that map,
we get to line 54, lets try to add it:

[root@jouet ~]# perf probe -x ~/bin/perf thread__find_map:54
Added new events:
  probe_perf:thread__find_map (on thread__find_map:54 in /home/acme/bin/perf)
  probe_perf:thread__find_map_1 (on thread__find_map:54 in /home/acme/bin/perf)
  probe_perf:thread__find_map_2 (on thread__find_map:54 in /home/acme/bin/perf)
  probe_perf:thread__find_map_3 (on thread__find_map:54 in /home/acme/bin/perf)
  probe_perf:thread__find_map_4 (on thread__find_map:54 in /home/acme/bin/perf)

You can now use it in all perf tools, such as:

	perf record -e probe_perf:thread__find_map_4 -aR sleep 1

[root@jouet ~]#

Now I run 'perf top' and then, on another terminal, run this to get system wide
events to get a few of those probes:

[root@jouet ~]# perf trace -a -e *perf:*/max-stack=7/ sleep 0.02
     0.000 probe_perf:thread__find_map_3:(4be2e3)
                                       machine__resolve (/home/acme/bin/perf)
                                       perf_top__mmap_read_idx (/home/acme/bin/perf)
                                       perf_top__mmap_read (/home/acme/bin/perf)
                                       cmd_top (/home/acme/bin/perf)
                                       run_builtin (/home/acme/bin/perf)
                                       handle_internal_command (/home/acme/bin/perf)
                                       main (/home/acme/bin/perf)
     0.023 probe_perf:thread__find_map_3:(4be2e3)
                                       machine__resolve (/home/acme/bin/perf)
                                       perf_top__mmap_read_idx (/home/acme/bin/perf)
                                       perf_top__mmap_read (/home/acme/bin/perf)
                                       cmd_top (/home/acme/bin/perf)
                                       run_builtin (/home/acme/bin/perf)
                                       handle_internal_command (/home/acme/bin/perf)
                                       main (/home/acme/bin/perf)
     0.048 probe_perf:thread__find_map_3:(4be2e3)
                                       machine__resolve (/home/acme/bin/perf)
                                       perf_top__mmap_read_idx (/home/acme/bin/perf)
                                       perf_top__mmap_read (/home/acme/bin/perf)
                                       cmd_top (/home/acme/bin/perf)
                                       run_builtin (/home/acme/bin/perf)
                                       handle_internal_command (/home/acme/bin/perf)
                                       main (/home/acme/bin/perf)
<SNIP>
[root@jouet ~]# 

So it now I'm not being able to reproduce... Erm, nevermind then, I'll report
back if I notice this again... :-)

Thanks for checking, sorry for the noise.

- Arnaldo