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

From: Arnaldo Carvalho de Melo
Date: Fri Apr 03 2020 - 09:02:59 EST

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