Re: perf is unable to read dward from go programs

[Ivan Babrou]

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.

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.

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)

On Fri, Nov 29, 2019 at 7:14 AM Arnaldo Carvalho de Melo
<arnaldo.melo@xxxxxxxxx> wrote:
>
> Em Fri, Nov 29, 2019 at 02:49:29PM +0100, Jiri Olsa escreveu:
> > On Wed, Nov 27, 2019 at 01:15:20PM -0800, Ivan Babrou wrote:
> > > There were no response in linux-perf-users@, so I think it's fair to
> > > ask maintainers.
> > >
> > > On Fri, Nov 8, 2019 at 3:53 PM Ivan Babrou <ivan@xxxxxxxxxxxxxx> wrote:
> > > >
> > > > I have a simple piece of code that burns CPU for 1s:
> > > >
> > > > * https://gist.github.com/bobrik/cf022ff6950d09032fa13a984e2272ed
> > > >
> > > > I can build it just fine: go build -o /tmp/burn burn.go
> > > >
> > > > And I can see correct stacks if I record with fp:
> > > >
> > > > perf record -e cpu-clock -g -F 99 /tmp/burn
> > > >
> > > > But if I record with gwarf:
> > > >
> > > > perf record -e cpu-clock -g -F 99 --call-graph dwarf /tmp/burn
> > > >
> > > > Then stacks are lost with the following complaints during "perf script":
> > > >
> > > > 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 '65271', this reader only
> > > > handles version 2, 3 and 4 information.
> > > > BFD: Dwarf Error: found dwarf version '289', this reader only handles
> > > > version 2, 3 and 4 information.
> >
> > hi,
> > the binary generated by go has compressed debug info (on my setup)
> > and libunwind (default dwarf unwinder) does not seem to support that
> >
> > but when I compile perf with libdw unwind support:
> >
> >   $ make DEBUG=1 VF=1 NO_LIBUNWIND=1
> >
> > I'm getting proper backtraces (below), maybe it's time to change
> > the default dwarf unwinder ;-)
>
> we have some 'perf test' entries testing the unwinding routines, can you
> please check if those pass when switching to libdw's unwinder?
>
> - Arnaldo
>
> > thanks,
> > jirka
> >
> >
> > ---
> >     51.63%  ex       ex                [.] crypto/sha512.blockAVX2
> >             |
> >             ---crypto/sha512.blockAVX2
> >                |
> >                 --51.48%--crypto/sha512.block
> >                           crypto/sha512.(*digest).Write
> >                           crypto/sha512.(*digest).checkSum
> >                           crypto/sha512.(*digest).Sum
> >                           main.burn
> >                           main.main
> >                           runtime.main
> >                           runtime.goexit
> >
> >     11.55%  ex       ex                [.] runtime.mallocgc
> >             |
> >             ---runtime.mallocgc
> >                |
> >                |--7.45%--runtime.newobject
> >                |          |
> >                |           --7.45%--main.burn
> >                |                     main.main
> >                |                     runtime.main
> >                |                     runtime.goexit
> >                |
> >                 --3.40%--runtime.growslice
> >                           crypto/sha512.(*digest).Sum
> >                           main.burn
> >                           main.main
> >                           runtime.main
> >                           runtime.goexit
> >
> >      3.69%  ex       ex                [.] crypto/sha512.(*digest).Write
> >             |
> >             ---crypto/sha512.(*digest).Write
> >                |
> >                |--2.91%--crypto/sha512.(*digest).checkSum
> >                |          crypto/sha512.(*digest).Sum
> >                |          main.burn
> >                |          main.main
> >                |          runtime.main
> >                |          runtime.goexit
> >                |
> >                 --0.57%--main.burn
> >                           main.main
> >                           runtime.main
> >                           runtime.goexit
> >
> >      3.44%  ex       ex                [.] runtime.memclrNoHeapPointers
> >             |
> >             ---runtime.memclrNoHeapPointers
> >                |
> >                 --2.92%--runtime.(*mheap).alloc
> >                           runtime.(*mcentral).grow
> >                           runtime.(*mcentral).cacheSpan
> >                           runtime.(*mcache).refill
> >                           runtime.(*mcache).nextFree
> >                           runtime.mallocgc
> >                           |
> >                           |--2.27%--runtime.newobject
> >                           |          main.burn
> >                           |          main.main
> >                           |          runtime.main
> >                           |          runtime.goexit
> >                           |
> >                            --0.64%--runtime.growslice
> >                                      crypto/sha512.(*digest).Sum
> >                                      main.burn
> >                                      main.main
> >                                      runtime.main
> >                                      runtime.goexit
> > ...
>
> --
>
> - Arnaldo