Re: perf is unable to read dward from go programs

[Ivan Babrou]

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
>