Re: perf is unable to read dward from go programs

From: Ivan Babrou
Date: Thu Dec 19 2019 - 18:58:08 EST

Next message: Rob Herring: "Re: [PATCH 10/14] dt-bindings: bus: sunxi: Add R40 MBUS compatible"
Previous message: Rob Herring: "Re: [PATCH 02/14] dt-bindings: media: sun4i-csi: Add compatible for CSI0 on R40"
In reply to: Ivan Babrou: "Re: perf is unable to read dward from go programs"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Found a reproducer for missing /tmp/perf-XXX frames:

$ cat hello.java
class HelloWorld {
public static void main(String args[]) {
for (long i = 0; ; i++) {}
}
}

Compile it:

$ javac hello.java

Run it:

$ java HelloWorld

Trace it with libdw:

$ sudo perf record -p $(pidof java) --call-graph dwarf -- sleep 1

Observe traces in perf script not having any frames:

java 61467 127535.601549: 149893 cycles:

java 61467 127535.601602: 606223 cycles:

java 61467 127535.601802: 890579 cycles:

java 61467 127535.602158: 840878 cycles:

java 61467 127535.602453: 809547 cycles:

java 61467 127535.602718: 794099 cycles:

java 61467 127535.602981: 777283 cycles:

Now trace it with libunwind:

$ sudo perf record -p $(pidof java) --call-graph dwarf -- sleep 1

And observe traces with /tmp/perf-XXX:

java 61467 127583.896584: 118386 cycles:
7fcd55342ce8 [unknown] (/tmp/perf-61466.map)

java 61467 127583.896626: 537046 cycles:
7fcd55342d17 [unknown] (/tmp/perf-61466.map)

java 61467 127583.896804: 866323 cycles:
7fcd55342ce8 [unknown] (/tmp/perf-61466.map)

java 61467 127583.897091: 825548 cycles:
7fcd55342d17 [unknown] (/tmp/perf-61466.map)

java 61467 127583.897361: 812276 cycles:
7fcd55342d17 [unknown] (/tmp/perf-61466.map)

java 61467 127583.897627: 804520 cycles:
7fcd55342ce5 [unknown] (/tmp/perf-61466.map)

This should cover all issues I mentioned.

On Thu, Dec 19, 2019 at 3:38 PM Ivan Babrou <ivan@xxxxxxxxxxxxxx> wrote:
>
> At first I thought it was related to C/Go interaction, but it looks
> even easier to trigger.
>
> Ok, I have a reproduction for both random dwarf versions and for
> uncached binary symbol resolution:
>
> $ cat /tmp/main.go
> package main
>
> func main() {
> for {
> src := make([]byte, 100*1024*1024)
> dst := make([]byte, len(src))
> copy(dst, src)
> }
> }
>
> Compile and run it:
>
> $ go build -o /tmp/memmove /tmp/main.go && /tmp/memmove
>
> Then record a trace:
>
> $ sudo perf record -p $(pidof memmove) --call-graph dwarf -- sleep 1
>
> Getting stack traces generates warnings:
>
> $ sudo perf script > /dev/null
> BFD: Dwarf Error: found dwarf version '376', this reader only handles
> version 2, 3 and 4 information.
> BFD: Dwarf Error: found dwarf version '31863', this reader only
> handles version 2, 3 and 4 information.
> BFD: Dwarf Error: found dwarf version '65267', this reader only
> handles version 2, 3 and 4 information.
> BFD: Dwarf Error: found dwarf version '33833', this reader only
> handles version 2, 3 and 4 information.
> BFD: Dwarf Error: found dwarf version '41392', this reader only
> handles version 2, 3 and 4 information.
>
> Here's an example of raw perf script output where it generates the warning:
>
> memmove 254821 125950.754906: 174236 cycles: BFD: Dwarf Error:
> found dwarf version '33833', this reader only handles version 2, 3 and
> 4 information.
>
> 44d549 runtime.memmove+0x4d9 (/tmp/memmove)
> 452644 main.main+0x94 (/tmp/memmove)
> 42668d runtime.main+0x21d (/tmp/memmove)
> 44bef0 runtime.goexit+0x0 (/tmp/memmove)
>
> Timed execution shows quite a bit of time spent:
>
> $ time sudo perf script > /dev/null
> ... whole bunch of warnings about dwarf version here ..
>
> real 0m24.356s
> user 0m23.617s
> sys 0m0.723s
>
> And you can see object files being open over and over again:
>
> $ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_open,
> tracepoint:syscalls:sys_enter_openat {
> @filename[str(args->filename)]++ }'
> ... some unrelated files here ...
> @filename[/lib/x86_64-linux-gnu/libpcre.so.3]: 595
> @filename[/usr/lib/locale/locale-archive]: 625
> @filename[/lib/x86_64-linux-gnu/libpthread.so.0]: 789
> @filename[/lib/x86_64-linux-gnu/libdl.so.2]: 838
> @filename[/var/log/journal/0bc45a9309f7404586bcddee0d45bf9d/system.journa]: 1044
> @filename[/lib/x86_64-linux-gnu/libc.so.6]: 1273
> @filename[/etc/ld.so.cache]: 1501
> @filename[/usr/lib/x86_64-linux-gnu/../lib/x86_64-linux-gnu/elfutils/libe]: 5784
> @filename[/usr/lib/x86_64-linux-gnu/elfutils/libebl_x86_64.so]: 5784
> @filename[/tmp/memmove]: 5789
>
> I'm going to guess that anything open for 5000+ times is related to
> perf script run, as I can also see those in strace.
>
> This is on Debian Stretch and Linux 5.4.5 (perf is from 5.4.5 as well).
>
> This should cover points 2 and 3, I'll have to get back to you on
> points 4 and 5, but those are separate.
>
> On Tue, Dec 3, 2019 at 2:22 AM Jiri Olsa <jolsa@xxxxxxxxxx> wrote:
> >
> > On Mon, Dec 02, 2019 at 11:49:55AM -0800, Ivan Babrou wrote:
> > > I've tried building with libdw with mixed results:
> > >
> > > 1. I can see stacks from some Go programs that were invisible before (yay!)
> > >
> > > 2. Warnings like below still appear in great numbers for a system-wide
> > > flamegraph:
> > >
> > > BFD: Dwarf Error: found dwarf version '18345', this reader only
> > > handles version 2, 3 and 4 information.
> > >
> > > I'm not sure how to pinpoint this to a particular binary and would
> > > appreciate some help with this.
> >
> > I'd need some way of reproducing this, could you please
> > paste me command lines you used?
> >
> > >
> > > 3. It takes minutes to produce a flamegraph of a running system
> > > whereas before it only took seconds. See this flamegraph of "perf
> > > script" itself:
> > >
> > > * https://gist.github.com/bobrik/a9c46cffe9daa5840abd137443d8bab0#file-flamegraph-perf-svg
> > >
> > > Seems like there is no caching and debug info is getting reparsed
> > > continuously for every stack. It's possible that it was not an issue
> > > before, because we spent no time decompressing dwarf.
> >
> > possibly, if we have some clear reproducer we can hand it
> > to the libdw guy that helped us develop this
> >
> > >
> > > 4. Pretty much all luajit frames stacks that were marked as unknown
> > > before are now gone.
> > >
> > > See before and after here: https://imgur.com/a/1LNfqAk
> > >
> > > Before:
> > >
> > > nginx-cache 94572 446642.722028: 10101010 cpu-clock:
> > > 5607d8d56718 ngx_http_lua_shdict_lookup+0x48 (inlined)
> > > 5607d8d5a09d ngx_http_lua_ffi_shdict_incr+0xcd
> > > (/usr/local/nginx-cache/sbin/nginx-cache)
> > > 560802fe58e4 [unknown] (/tmp/perf-94572.map)
> > >
> > > After:
> > >
> > > nginx-cache 94572 446543.008703: 10101010 cpu-clock:
> > > 5607d8d56718 ngx_http_lua_shdict_lookup+0x48 (inlined)
> > > 5607d8d59da7 ngx_http_lua_ffi_shdict_get+0x197
> > > (/usr/local/nginx-cache/sbin/nginx-cache)
> > >
> > > The key is /tmp/perf-*.map frame at the bottom. I don't know if it's
> > > expected, but we grew dependent on knowing this.
> > >
> > > 5. Special [[stack]], [[heap]] and [anon] frames are also gone, and
> > > you can see the following during "perf script" run:
> > >
> > > open("[stack]", O_RDONLY) = -1 ENOENT (No such file or directory)
> > > open("[heap]", O_RDONLY) = -1 ENOENT (No such file or directory)
> > > open("//anon", O_RDONLY) = -1 ENOENT (No such file or directory)
> >
> > strange, let's start with the reproducer and I'll check
> > on this if I see it
> >
> > thanks,
> > jirka
> >

Next message: Rob Herring: "Re: [PATCH 10/14] dt-bindings: bus: sunxi: Add R40 MBUS compatible"
Previous message: Rob Herring: "Re: [PATCH 02/14] dt-bindings: media: sun4i-csi: Add compatible for CSI0 on R40"
In reply to: Ivan Babrou: "Re: perf is unable to read dward from go programs"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]