[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-Id: <20181018183538.fba99bf336f9e6261860e049@kernel.org>
Date: Thu, 18 Oct 2018 18:35:38 +0900
From: Masami Hiramatsu <mhiramat@...nel.org>
To: Arnaldo Carvalho de Melo <acme@...nel.org>
Cc: Arnaldo Carvalho de Melo <acme@...hat.com>,
David Miller <davem@...emloft.net>,
linux-kernel@...r.kernel.org,
Peter Zijlstra <peterz@...radead.org>,
Ingo Molnar <mingo@...nel.org>, Jiri Olsa <jolsa@...hat.com>,
Namhyung Kim <namhyung@...il.com>
Subject: Re: perf's handling of unfindable user symbols...
On Wed, 17 Oct 2018 09:28:55 -0300
Arnaldo Carvalho de Melo <acme@...nel.org> wrote:
> 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@...hat.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@...et ~]# perf probe -x ~/bin/perf -L thread__find_map:43
> <thread__find_map@...me/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@...et ~]#
>
> 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@...et ~]# 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@...et ~]#
Hmm, it seems that the line is optimized and spread into 5 places (instructions).
"perf probe -x ~/bin/perf -D thread__find_map:54" will show you the actual address
where the probes are. Or, you can just dump the /sys/kernel/debug/tracing/uprobe_events.
> 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@...et ~]# 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@...et ~]#
>
> So it now I'm not being able to reproduce... Erm, nevermind then, I'll report
> back if I notice this again... :-)
Thanks!
I guess it might be broken. I will investigate it.
>
> Thanks for checking, sorry for the noise.
Issue reports are always welcome :)
>
> - Arnaldo
--
Masami Hiramatsu <mhiramat@...nel.org>
Powered by blists - more mailing lists