Re: [PATCH] perf probe: Add support for DW_OP_call_frame_cfa vars

From: Daniel Shaulov
Date: Fri Apr 03 2020 - 13:59:14 EST

Next message: Alex Dewar: "[PATCH] scsi: Remove unnecessary calls to memset after dma_alloc_coherent"
Previous message: Zeno Davatz: "Re: acr: failed to load firmware with Kernel 5.6. Kernel 5.5 works just fine."
In reply to: Arnaldo Carvalho de Melo: "Re: [PATCH] perf probe: Add support for DW_OP_call_frame_cfa vars"
Next in thread: Masami Hiramatsu: "Re: [PATCH] perf probe: Add support for DW_OP_call_frame_cfa vars"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Fri, Apr 03, 2020 at 10:02:51AM -0300, Arnaldo Carvalho de Melo wrote:
> Em Thu, Apr 02, 2020 at 08:25:24PM +0000, Daniel Shaulov escreveu:
> > On Thu, Apr 02, 2020 at 03:49:43PM -0300, Arnaldo Carvalho de Melo wrote:
> > > Daniel, next time please consider providing precise steps to show what
> > > wasn't working and then how the patch solves the problem, i.e. get some
> > > go program, show the command lines used to build, probe, etc.
> > >
> > > - Arnaldo
> >
> > Sure thing:
> >
> > ---- contents of example.go ----
> > package main
> >
> > import "fmt"
> >
> > func example(param1 int, param2 int) {
> > fmt.Println(param1, param2)
> > }
> >
> > func main() {
> > example(111, 222)
> > }
> > ---- end contents of example.go ----
> >
> > Build with:
> > $ go build example.go
> >
> > Note that the output file is named after the directory.
> >
> > Then try to probe it with:
> > $ perf probe -x ./example 'main.example param1 param2'
> >
> > The result is:
> > > Target program is compiled without optimization. Skipping prologue.
> > > Probe on address 0x4820f0 to force probing at the function entry.
> > >
> > > Sorry, we don't support this variable location yet.
> > > Error: Failed to add events.
> >
> > With my changes the event is added successfuly.
> > The reason for the change can be observed in the output of:
> > $ readelf --debug-dump=info ./example
> >
> > Where we have the following for the main.example function (with go >= 1.10):
> > <1><63dd2>: Abbrev Number: 2 (DW_TAG_subprogram)
> > <63dd3> DW_AT_name : main.example
> > <63de0> DW_AT_low_pc : 0x4820f0
> > <63de8> DW_AT_high_pc : 0x4821c2
> > <63df0> DW_AT_frame_base : 1 byte block: 9c (DW_OP_call_frame_cfa)
> > <63df2> DW_AT_decl_file : 0x1
> > <63df6> DW_AT_external : 1
> > <2><63df7>: Abbrev Number: 14 (DW_TAG_formal_parameter)
> > <63df8> DW_AT_name : param1
> > <63dff> DW_AT_variable_parameter: 0
> > <63e00> DW_AT_decl_line : 5
> > <63e01> DW_AT_type : <0x220f>
> > <63e05> DW_AT_location : 1 byte block: 9c (DW_OP_call_frame_cfa)
> > <2><63e07>: Abbrev Number: 14 (DW_TAG_formal_parameter)
> > <63e08> DW_AT_name : param2
> > <63e0f> DW_AT_variable_parameter: 0
> > <63e10> DW_AT_decl_line : 5
> > <63e11> DW_AT_type : <0x220f>
> > <63e15> DW_AT_location : 2 byte block: 91 8 (DW_OP_fbreg: 8)
> > <2><63e18>: Abbrev Number: 0
>
> > The go compiler (after 1.10) uses DW_OP_call_frame_cfa for the first parameter and DW_OP_fbreg for the rest.
> > On go versions lower than 1.10, it used DW_OP_call_frame_cfa for all parameters.
> > Here is example output of the readelf on main.example, compiled with go1.9.7:
> > <1><2634d>: Abbrev Number: 2 (DW_TAG_subprogram)
> > <2634e> DW_AT_name : main.example
> > <2635b> DW_AT_low_pc : 0x487db0
> > <26363> DW_AT_high_pc : 0x487e99
> > <2636b> DW_AT_frame_base : 1 byte block: 9c (DW_OP_call_frame_cfa)
> > <2636d> DW_AT_external : 1
> > <2><2636e>: Abbrev Number: 5 (DW_TAG_formal_parameter)
> > <2636f> DW_AT_name : param1
> > <26376> DW_AT_location : 1 byte block: 9c (DW_OP_call_frame_cfa)
> > <26378> DW_AT_type : <0x27f1c>
> > <2><2637c>: Abbrev Number: 5 (DW_TAG_formal_parameter)
> > <2637d> DW_AT_name : param2
> > <26384> DW_AT_location : 4 byte block: 9c 11 8 22 (DW_OP_call_frame_cfa; DW_OP_consts: 8; DW_OP_plus)
> > <26389> DW_AT_type : <0x27f1c>
> > <2><2638d>: Abbrev Number: 0
> >
> > Hope this makes things easier to understand.
>
> Right, but I tried following your instructions here and got up to this:
>
> <0><76ded>: Abbrev Number: 1 (DW_TAG_compile_unit)
> <76dee> DW_AT_name : main
> <76df3> DW_AT_language : 22 (Go)
> <76df4> DW_AT_stmt_list : 0x27a7d
> <76df8> DW_AT_low_pc : 0x48cd90
> <76e00> DW_AT_ranges : 0x2e0
> <76e04> DW_AT_comp_dir : .
> <76e06> DW_AT_producer : Go cmd/compile go1.13.6
> <76e1e> Unknown AT value: 2905: main
> <1><76e23>: Abbrev Number: 4 (DW_TAG_subprogram)
> <76e24> DW_AT_name : main.example
> <76e31> DW_AT_inline : 1 (inlined)
> <76e32> DW_AT_external : 1
> <2><76e33>: Abbrev Number: 17 (DW_TAG_formal_parameter)
> <76e34> DW_AT_name : param1
> <76e3b> DW_AT_variable_parameter: 0
> <76e3c> DW_AT_type : <0x37430>
> <2><76e40>: Abbrev Number: 17 (DW_TAG_formal_parameter)
> <76e41> DW_AT_name : param2
> <76e48> DW_AT_variable_parameter: 0
> <76e49> DW_AT_type : <0x37430>
> <2><76e4d>: Abbrev Number: 0
>
>
> Which, with or without your patch ends with:
>
> [acme@five daniel.shaulov@xxxxxxxxx]$ perf probe -x ./example 'main.example param1 param2'
> Failed to find 'param1' in this function.
> Probe point 'main.example' not found.
> Error: Failed to add events.
> [acme@five daniel.shaulov@xxxxxxxxx]$
>
> [acme@five perf]$ rpm -q golang-bin
> golang-bin-1.13.6-1.fc31.x86_64
> [acme@five perf]$ cat /etc/fedora-release
> Fedora release 31 (Thirty One)
> [acme@five perf]$
>
> Has the behaviour changed again in 1.13? Or is this some optimization
> level that fedora sets that ends up auto-inlining that main.example
> routine?
>
> [acme@five daniel.shaulov@xxxxxxxxx]$ readelf --debug-dump=info ./example | grep main\.example -B10 -A13
> <0><76ded>: Abbrev Number: 1 (DW_TAG_compile_unit)
> <76dee> DW_AT_name : main
> <76df3> DW_AT_language : 22 (Go)
> <76df4> DW_AT_stmt_list : 0x27a7d
> <76df8> DW_AT_low_pc : 0x48cd90
> <76e00> DW_AT_ranges : 0x2e0
> <76e04> DW_AT_comp_dir : .
> <76e06> DW_AT_producer : Go cmd/compile go1.13.6
> <76e1e> Unknown AT value: 2905: main
> <1><76e23>: Abbrev Number: 4 (DW_TAG_subprogram)
> <76e24> DW_AT_name : main.example
> <76e31> DW_AT_inline : 1 (inlined)
> <76e32> DW_AT_external : 1
> <2><76e33>: Abbrev Number: 17 (DW_TAG_formal_parameter)
> <76e34> DW_AT_name : param1
> <76e3b> DW_AT_variable_parameter: 0
> <76e3c> DW_AT_type : <0x37430>
> <2><76e40>: Abbrev Number: 17 (DW_TAG_formal_parameter)
> <76e41> DW_AT_name : param2
> <76e48> DW_AT_variable_parameter: 0
> <76e49> DW_AT_type : <0x37430>
> <2><76e4d>: Abbrev Number: 0
> <1><76e4e>: Abbrev Number: 4 (DW_TAG_subprogram)
> <76e4f> DW_AT_name : fmt.Println
> [acme@five daniel.shaulov@xxxxxxxxx]$
>
> - Arnaldo

Ok, so I looked into it a little bit.
I was using go1.10.4 (that's the one in Ubuntu 18.04 repo)

Apperantly they improved inlining in go1.12
https://golang.org/doc/go1.12#compiler
> More functions are now eligible for inlining by default,
> including functions that do nothing but call another function.

I added "//go:noinline" to the example function and it works in go1.12 and go1.13.6
---- contents of example.go ----
package main

import "fmt"

//go:noinline
func example(param1 int, param2 int) {
fmt.Println(param1, param2)
}

func main() {
example(111, 222)
}
---- end contents of example.go ----

There were some other changes to the dwarf output and in 1.13.6 with "//go:noinline" it looks like this:
$ readelf --debug-dump=info ./example | grep main\.example -A17
<1><76e8f>: Abbrev Number: 3 (DW_TAG_subprogram)
<76e90> DW_AT_name : main.example
<76e9d> DW_AT_low_pc : 0x48ce90
<76ea5> DW_AT_high_pc : 0x48cf58
<76ead> DW_AT_frame_base : 1 byte block: 9c (DW_OP_call_frame_cfa)
<76eaf> DW_AT_decl_file : 0x1
<76eb3> DW_AT_external : 1
<2><76eb4>: Abbrev Number: 16 (DW_TAG_formal_parameter)
<76eb5> DW_AT_name : param1
<76ebc> DW_AT_variable_parameter: 0
<76ebd> DW_AT_decl_line : 6
<76ebe> DW_AT_type : <0x37472>
<76ec2> DW_AT_location : 0x7cd57 (location list)
<2><76ec6>: Abbrev Number: 16 (DW_TAG_formal_parameter)
<76ec7> DW_AT_name : param2
<76ece> DW_AT_variable_parameter: 0
<76ecf> DW_AT_decl_line : 6
<76ed0> DW_AT_type : <0x37472>
<76ed4> DW_AT_location : 0x7cd8a (location list)

The "0x7cd57 (location list)" can be read with another readelf:
$ readelf --debug-dump=loc ./example | grep 7cd57 -A5
0007cd57 ffffffffffffffff 000000000048ce90 (base address)
0007cd67 000000000048ce90 000000000048cf58 (DW_OP_call_frame_cfa)
0007cd7a <End of list>
0007cd8a ffffffffffffffff 000000000048ce90 (base address)
0007cd9a 000000000048ce90 000000000048cf58 (DW_OP_fbreg: 8)
0007cdae <End of list>

So it is basically the same as what I was getting with go1.10, but with a deref in the way.
I guess dwarf_getlocation_addr abstracts the difference away since my code still works.

Note - in go1.11, I think there was some bug, because it shows up like this in readelf:
<1><72a95>: Abbrev Number: 2 (DW_TAG_subprogram)
<72a96> DW_AT_name : main.example
<72aa3> DW_AT_low_pc : 0x4850b0
<72aab> DW_AT_high_pc : 0x48516e
<72ab3> DW_AT_frame_base : 1 byte block: 9c (DW_OP_call_frame_cfa)
<72ab5> DW_AT_decl_file : 0x1
<72ab9> DW_AT_external : 1
<2><72aba>: Abbrev Number: 14 (DW_TAG_formal_parameter)
<72abb> DW_AT_name : param1
<72ac2> DW_AT_variable_parameter: 0
<72ac3> DW_AT_decl_line : 6
<72ac4> DW_AT_type : <0x3118>
<72ac8> DW_AT_location : 0 byte block: ()
<2><72ac9>: Abbrev Number: 14 (DW_TAG_formal_parameter)
<72aca> DW_AT_name : param2
<72ad1> DW_AT_variable_parameter: 0
<72ad2> DW_AT_decl_line : 6
<72ad3> DW_AT_type : <0x3118>
<72ad7> DW_AT_location : 0 byte block: ()
<2><72ad8>: Abbrev Number: 0

And perf has no way to find the parameters (DW_AT_location is empty).

Next message: Alex Dewar: "[PATCH] scsi: Remove unnecessary calls to memset after dma_alloc_coherent"
Previous message: Zeno Davatz: "Re: acr: failed to load firmware with Kernel 5.6. Kernel 5.5 works just fine."
In reply to: Arnaldo Carvalho de Melo: "Re: [PATCH] perf probe: Add support for DW_OP_call_frame_cfa vars"
Next in thread: Masami Hiramatsu: "Re: [PATCH] perf probe: Add support for DW_OP_call_frame_cfa vars"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]