Subject: [PATCH -tip ] [BUGFIX] perf probe: Fix to probe on symbols with optimization suffix

Fix perf probe to probe on some symbols which have some
optimzation suffixes, e.g. ".part", ".isra", and ".constprop".
To fix this issue, instead of using DIE name, perf probe
uses symbol name found by dwfl_module_addrsym().

This also involves perf probe --vars operation update which
shows the symbol name instead of the DIE name.

Without this patch, putting a probe on an inlined function
which was compiled as a suffixed symbol will fail as below;

$ perf probe -v getname_flags
probe-definition(0): getname_flags
symbol:getname_flags file:(null) line:0 offset:0 return:0 lazy:(null)
0 arguments
Looking at the vmlinux_path (6 entries long)
Using /lib/modules/3.11.0+/build/vmlinux for symbols
found inline addr: 0xffffffff8119bb70
Probe point found: getname_flags+0
found inline addr: 0xffffffff8119bcb6
Probe point found: getname+6
found inline addr: 0xffffffff811a06a6
Probe point found: user_path_at_empty+6
find 3 probe_trace_events.
Opening /sys/kernel/debug//tracing/kprobe_events write=1
Added new events:
Writing event: p:probe/getname_flags getname_flags+0
Failed to write event: No such file or directory
Error: Failed to add events. (-1)

Because the debuginfo knows only the original (non suffix)
symbol name, it uses the original symbol for probe address
but the kernel (kallsyms) knows only suffixed symbol.
Then, the kernel rejects that original symbol.

This patch uses dwfl_module_addrsym() to get the correct
(suffixed) symbol from symtab when a probe point is found.

Reported-by: Arnaldo Carvalho de Melo <[email protected]>
Signed-off-by: Masami Hiramatsu <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
---
tools/perf/util/probe-finder.c | 77 +++++++++++++++++++++-------------------
tools/perf/util/probe-finder.h | 3 ++
2 files changed, 44 insertions(+), 36 deletions(-)

diff --git a/tools/perf/util/probe-finder.c b/tools/perf/util/probe-finder.c
index 20c7299..371476c 100644
--- a/tools/perf/util/probe-finder.c
+++ b/tools/perf/util/probe-finder.c
@@ -118,7 +118,6 @@ static const Dwfl_Callbacks offline_callbacks = {
static int debuginfo__init_offline_dwarf(struct debuginfo *self,
const char *path)
{
- Dwfl_Module *mod;
int fd;

fd = open(path, O_RDONLY);
@@ -129,11 +128,11 @@ static int debuginfo__init_offline_dwarf(struct debuginfo *self,
if (!self->dwfl)
goto error;

- mod = dwfl_report_offline(self->dwfl, "", "", fd);
- if (!mod)
+ self->mod = dwfl_report_offline(self->dwfl, "", "", fd);
+ if (!self->mod)
goto error;

- self->dbg = dwfl_module_getdwarf(mod, &self->bias);
+ self->dbg = dwfl_module_getdwarf(self->mod, &self->bias);
if (!self->dbg)
goto error;

@@ -676,37 +675,42 @@ static int find_variable(Dwarf_Die *sc_die, struct probe_finder *pf)
}

/* Convert subprogram DIE to trace point */
-static int convert_to_trace_point(Dwarf_Die *sp_die, Dwarf_Addr paddr,
- bool retprobe, struct probe_trace_point *tp)
+static int convert_to_trace_point(Dwarf_Die *sp_die, Dwfl_Module *mod,
+ Dwarf_Addr paddr, bool retprobe,
+ struct probe_trace_point *tp)
{
Dwarf_Addr eaddr, highaddr;
- const char *name;
-
- /* Copy the name of probe point */
- name = dwarf_diename(sp_die);
- if (name) {
- if (dwarf_entrypc(sp_die, &eaddr) != 0) {
- pr_warning("Failed to get entry address of %s\n",
- dwarf_diename(sp_die));
- return -ENOENT;
- }
- if (dwarf_highpc(sp_die, &highaddr) != 0) {
- pr_warning("Failed to get end address of %s\n",
- dwarf_diename(sp_die));
- return -ENOENT;
- }
- if (paddr > highaddr) {
- pr_warning("Offset specified is greater than size of %s\n",
- dwarf_diename(sp_die));
- return -EINVAL;
- }
- tp->symbol = strdup(name);
- if (tp->symbol == NULL)
- return -ENOMEM;
- tp->offset = (unsigned long)(paddr - eaddr);
- } else
- /* This function has no name. */
- tp->offset = (unsigned long)paddr;
+ GElf_Sym sym;
+ const char *symbol;
+
+ /* Verify the address is correct */
+ if (dwarf_entrypc(sp_die, &eaddr) != 0) {
+ pr_warning("Failed to get entry address of %s\n",
+ dwarf_diename(sp_die));
+ return -ENOENT;
+ }
+ if (dwarf_highpc(sp_die, &highaddr) != 0) {
+ pr_warning("Failed to get end address of %s\n",
+ dwarf_diename(sp_die));
+ return -ENOENT;
+ }
+ if (paddr > highaddr) {
+ pr_warning("Offset specified is greater than size of %s\n",
+ dwarf_diename(sp_die));
+ return -EINVAL;
+ }
+
+ /* Get an appropriate symbol from symtab */
+ symbol = dwfl_module_addrsym(mod, paddr, &sym, NULL);
+ if (!symbol) {
+ pr_warning("Failed to find symbol at 0x%lx\n",
+ (unsigned long)paddr);
+ return -ENOENT;
+ }
+ tp->offset = (unsigned long)(paddr - sym.st_value);
+ tp->symbol = strdup(symbol);
+ if (!tp->symbol)
+ return -ENOMEM;

/* Return probe must be on the head of a subprogram */
if (retprobe) {
@@ -1149,7 +1153,7 @@ static int add_probe_trace_event(Dwarf_Die *sc_die, struct probe_finder *pf)
tev = &tf->tevs[tf->ntevs++];

/* Trace point should be converted from subprogram DIE */
- ret = convert_to_trace_point(&pf->sp_die, pf->addr,
+ ret = convert_to_trace_point(&pf->sp_die, tf->mod, pf->addr,
pf->pev->point.retprobe, &tev->point);
if (ret < 0)
return ret;
@@ -1181,7 +1185,7 @@ int debuginfo__find_trace_events(struct debuginfo *self,
{
struct trace_event_finder tf = {
.pf = {.pev = pev, .callback = add_probe_trace_event},
- .max_tevs = max_tevs};
+ .mod = self->mod, .max_tevs = max_tevs};
int ret;

/* Allocate result tevs array */
@@ -1250,7 +1254,7 @@ static int add_available_vars(Dwarf_Die *sc_die, struct probe_finder *pf)
vl = &af->vls[af->nvls++];

/* Trace point should be converted from subprogram DIE */
- ret = convert_to_trace_point(&pf->sp_die, pf->addr,
+ ret = convert_to_trace_point(&pf->sp_die, af->mod, pf->addr,
pf->pev->point.retprobe, &vl->point);
if (ret < 0)
return ret;
@@ -1289,6 +1293,7 @@ int debuginfo__find_available_vars_at(struct debuginfo *self,
{
struct available_var_finder af = {
.pf = {.pev = pev, .callback = add_available_vars},
+ .mod = self->mod,
.max_vls = max_vls, .externs = externs};
int ret;

diff --git a/tools/perf/util/probe-finder.h b/tools/perf/util/probe-finder.h
index 17e94d0..3b7d630 100644
--- a/tools/perf/util/probe-finder.h
+++ b/tools/perf/util/probe-finder.h
@@ -23,6 +23,7 @@ static inline int is_c_varname(const char *name)
/* debug information structure */
struct debuginfo {
Dwarf *dbg;
+ Dwfl_Module *mod;
Dwfl *dwfl;
Dwarf_Addr bias;
};
@@ -77,6 +78,7 @@ struct probe_finder {

struct trace_event_finder {
struct probe_finder pf;
+ Dwfl_Module *mod; /* For solving symbols */
struct probe_trace_event *tevs; /* Found trace events */
int ntevs; /* Number of trace events */
int max_tevs; /* Max number of trace events */
@@ -84,6 +86,7 @@ struct trace_event_finder {

struct available_var_finder {
struct probe_finder pf;
+ Dwfl_Module *mod; /* For solving symbols */
struct variable_list *vls; /* Found variable lists */
int nvls; /* Number of variable lists */
int max_vls; /* Max no. of variable lists */


2013-09-25 15:38:45

by Arnaldo Carvalho de Melo

[permalink] [raw]
Subject: Re: [PATCH -tip ] [BUGFIX] perf probe: Fix to probe on symbols with optimization suffix

Em Wed, Sep 25, 2013 at 10:16:16PM +0900, Masami Hiramatsu escreveu:
> Fix perf probe to probe on some symbols which have some
> optimzation suffixes, e.g. ".part", ".isra", and ".constprop".
> To fix this issue, instead of using DIE name, perf probe
> uses symbol name found by dwfl_module_addrsym().

Thanks Masami! Now it behaves _exactly_ as I expected and need:

[root@zoo linux]# perf probe -L getname_flags:65
<getname_flags@/home/git/linux/fs/namei.c:65>
65 result->uptr = filename;
66 audit_getname(result);
return result;

error:
70 final_putname(result);
71 return err;
72 }

struct filename *
getname(const char __user * filename)

[root@zoo linux]# perf probe -V getname_flags:65
Available variables at getname_flags:65
@<getname_flags.part.35+178>
char* filename
int* empty
long int max
struct filename* result
[root@zoo linux]# perf probe 'getname_flags:66 pathname=result->name:string'
Added new event:
probe:getname_flags (on getname_flags:66 with pathname=result->name:string)

You can now use it in all perf tools, such as:

perf record -e probe:getname_flags -aR sleep 1

[root@zoo linux]# perf record -a -e probe:getname_flags
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.252 MB perf.data (~54692 samples) ]
[root@zoo linux]# perf script | grep -v '# | head -5
> ^C
[root@zoo linux]# perf script | grep -v '^#' | head -5
libvirtd 1163 [001] 100606.469450: probe:getname_flags: (ffffffff811a2f89) pathname="/proc/cpuinfo"
libvirtd 1163 [001] 100606.469563: probe:getname_flags: (ffffffff811a2f89) pathname="/sys/devices/system/node"
libvirtd 1163 [001] 100606.469596: probe:getname_flags: (ffffffff811a2f89) pathname="/sys/devices/system/node/node0"
libvirtd 1163 [001] 100606.469612: probe:getname_flags: (ffffffff811a2f89) pathname="/sys/devices/system/node/node0/cpu0/online"
libvirtd 1163 [001] 100606.469628: probe:getname_flags: (ffffffff811a2f89) pathname="/sys/devices/system/node/node0/cpu0/topology/physical_package_id"
[root@zoo linux]#

Thanks a lot, applied to my perf/urgent branch,

- Arnaldo

Subject: [tip:perf/urgent] perf probe: Fix probing symbols with optimization suffix

Commit-ID: 576b523721b7fbbf44a411ff0b3d958906c41653
Gitweb: http://git.kernel.org/tip/576b523721b7fbbf44a411ff0b3d958906c41653
Author: Masami Hiramatsu <[email protected]>
AuthorDate: Wed, 25 Sep 2013 22:16:16 +0900
Committer: Arnaldo Carvalho de Melo <[email protected]>
CommitDate: Wed, 25 Sep 2013 12:27:31 -0300

perf probe: Fix probing symbols with optimization suffix

Fix perf probe to probe on some symbols which have some optimzation
suffixes, e.g. ".part", ".isra", and ".constprop".

To fix this issue, instead of using the DIE name, perf probe uses the
symbol name found by dwfl_module_addrsym().

This also involves a perf probe --vars operation update which now shows
the symbol name instead of the DIE name.

Without this patch, putting a probe on an inlined function which was
compiled with a suffixed symbol will fail like this:

$ perf probe -v getname_flags
probe-definition(0): getname_flags
symbol:getname_flags file:(null) line:0 offset:0 return:0 lazy:(null)
0 arguments
Looking at the vmlinux_path (6 entries long)
Using /lib/modules/3.11.0+/build/vmlinux for symbols
found inline addr: 0xffffffff8119bb70
Probe point found: getname_flags+0
found inline addr: 0xffffffff8119bcb6
Probe point found: getname+6
found inline addr: 0xffffffff811a06a6
Probe point found: user_path_at_empty+6
find 3 probe_trace_events.
Opening /sys/kernel/debug//tracing/kprobe_events write=1
Added new events:
Writing event: p:probe/getname_flags getname_flags+0
Failed to write event: No such file or directory
Error: Failed to add events. (-1)

Because the debuginfo knows only the original (non suffix) symbol name,
it uses the original symbol for probe address but the kernel (kallsyms)
knows only suffixed symbol. Then, the kernel rejects that original
symbol.

This patch uses dwfl_module_addrsym() to get the correct (suffixed)
symbol from symtab when a probe point is found.

Reported-by: Arnaldo Carvalho de Melo <[email protected]>
Signed-off-by: Masami Hiramatsu <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
---
tools/perf/util/probe-finder.c | 77 ++++++++++++++++++++++--------------------
tools/perf/util/probe-finder.h | 3 ++
2 files changed, 44 insertions(+), 36 deletions(-)

diff --git a/tools/perf/util/probe-finder.c b/tools/perf/util/probe-finder.c
index 20c7299..371476c 100644
--- a/tools/perf/util/probe-finder.c
+++ b/tools/perf/util/probe-finder.c
@@ -118,7 +118,6 @@ static const Dwfl_Callbacks offline_callbacks = {
static int debuginfo__init_offline_dwarf(struct debuginfo *self,
const char *path)
{
- Dwfl_Module *mod;
int fd;

fd = open(path, O_RDONLY);
@@ -129,11 +128,11 @@ static int debuginfo__init_offline_dwarf(struct debuginfo *self,
if (!self->dwfl)
goto error;

- mod = dwfl_report_offline(self->dwfl, "", "", fd);
- if (!mod)
+ self->mod = dwfl_report_offline(self->dwfl, "", "", fd);
+ if (!self->mod)
goto error;

- self->dbg = dwfl_module_getdwarf(mod, &self->bias);
+ self->dbg = dwfl_module_getdwarf(self->mod, &self->bias);
if (!self->dbg)
goto error;

@@ -676,37 +675,42 @@ static int find_variable(Dwarf_Die *sc_die, struct probe_finder *pf)
}

/* Convert subprogram DIE to trace point */
-static int convert_to_trace_point(Dwarf_Die *sp_die, Dwarf_Addr paddr,
- bool retprobe, struct probe_trace_point *tp)
+static int convert_to_trace_point(Dwarf_Die *sp_die, Dwfl_Module *mod,
+ Dwarf_Addr paddr, bool retprobe,
+ struct probe_trace_point *tp)
{
Dwarf_Addr eaddr, highaddr;
- const char *name;
-
- /* Copy the name of probe point */
- name = dwarf_diename(sp_die);
- if (name) {
- if (dwarf_entrypc(sp_die, &eaddr) != 0) {
- pr_warning("Failed to get entry address of %s\n",
- dwarf_diename(sp_die));
- return -ENOENT;
- }
- if (dwarf_highpc(sp_die, &highaddr) != 0) {
- pr_warning("Failed to get end address of %s\n",
- dwarf_diename(sp_die));
- return -ENOENT;
- }
- if (paddr > highaddr) {
- pr_warning("Offset specified is greater than size of %s\n",
- dwarf_diename(sp_die));
- return -EINVAL;
- }
- tp->symbol = strdup(name);
- if (tp->symbol == NULL)
- return -ENOMEM;
- tp->offset = (unsigned long)(paddr - eaddr);
- } else
- /* This function has no name. */
- tp->offset = (unsigned long)paddr;
+ GElf_Sym sym;
+ const char *symbol;
+
+ /* Verify the address is correct */
+ if (dwarf_entrypc(sp_die, &eaddr) != 0) {
+ pr_warning("Failed to get entry address of %s\n",
+ dwarf_diename(sp_die));
+ return -ENOENT;
+ }
+ if (dwarf_highpc(sp_die, &highaddr) != 0) {
+ pr_warning("Failed to get end address of %s\n",
+ dwarf_diename(sp_die));
+ return -ENOENT;
+ }
+ if (paddr > highaddr) {
+ pr_warning("Offset specified is greater than size of %s\n",
+ dwarf_diename(sp_die));
+ return -EINVAL;
+ }
+
+ /* Get an appropriate symbol from symtab */
+ symbol = dwfl_module_addrsym(mod, paddr, &sym, NULL);
+ if (!symbol) {
+ pr_warning("Failed to find symbol at 0x%lx\n",
+ (unsigned long)paddr);
+ return -ENOENT;
+ }
+ tp->offset = (unsigned long)(paddr - sym.st_value);
+ tp->symbol = strdup(symbol);
+ if (!tp->symbol)
+ return -ENOMEM;

/* Return probe must be on the head of a subprogram */
if (retprobe) {
@@ -1149,7 +1153,7 @@ static int add_probe_trace_event(Dwarf_Die *sc_die, struct probe_finder *pf)
tev = &tf->tevs[tf->ntevs++];

/* Trace point should be converted from subprogram DIE */
- ret = convert_to_trace_point(&pf->sp_die, pf->addr,
+ ret = convert_to_trace_point(&pf->sp_die, tf->mod, pf->addr,
pf->pev->point.retprobe, &tev->point);
if (ret < 0)
return ret;
@@ -1181,7 +1185,7 @@ int debuginfo__find_trace_events(struct debuginfo *self,
{
struct trace_event_finder tf = {
.pf = {.pev = pev, .callback = add_probe_trace_event},
- .max_tevs = max_tevs};
+ .mod = self->mod, .max_tevs = max_tevs};
int ret;

/* Allocate result tevs array */
@@ -1250,7 +1254,7 @@ static int add_available_vars(Dwarf_Die *sc_die, struct probe_finder *pf)
vl = &af->vls[af->nvls++];

/* Trace point should be converted from subprogram DIE */
- ret = convert_to_trace_point(&pf->sp_die, pf->addr,
+ ret = convert_to_trace_point(&pf->sp_die, af->mod, pf->addr,
pf->pev->point.retprobe, &vl->point);
if (ret < 0)
return ret;
@@ -1289,6 +1293,7 @@ int debuginfo__find_available_vars_at(struct debuginfo *self,
{
struct available_var_finder af = {
.pf = {.pev = pev, .callback = add_available_vars},
+ .mod = self->mod,
.max_vls = max_vls, .externs = externs};
int ret;

diff --git a/tools/perf/util/probe-finder.h b/tools/perf/util/probe-finder.h
index 17e94d0..3b7d630 100644
--- a/tools/perf/util/probe-finder.h
+++ b/tools/perf/util/probe-finder.h
@@ -23,6 +23,7 @@ static inline int is_c_varname(const char *name)
/* debug information structure */
struct debuginfo {
Dwarf *dbg;
+ Dwfl_Module *mod;
Dwfl *dwfl;
Dwarf_Addr bias;
};
@@ -77,6 +78,7 @@ struct probe_finder {

struct trace_event_finder {
struct probe_finder pf;
+ Dwfl_Module *mod; /* For solving symbols */
struct probe_trace_event *tevs; /* Found trace events */
int ntevs; /* Number of trace events */
int max_tevs; /* Max number of trace events */
@@ -84,6 +86,7 @@ struct trace_event_finder {

struct available_var_finder {
struct probe_finder pf;
+ Dwfl_Module *mod; /* For solving symbols */
struct variable_list *vls; /* Found variable lists */
int nvls; /* Number of variable lists */
int max_vls; /* Max no. of variable lists */

Subject: Re: [PATCH -tip ] [BUGFIX] perf probe: Fix to probe on symbols with optimization suffix

Hi Arnaldo,

BTW, I also found another issue which the perf probe -l showed
incorrect line number and file name for probes on such inline
functions. :(
I found the root causes (the line info is not correct and
perf probe failed to handle nested inline functions). I'll send
the bugfix patch soon.

Thank you,

(2013/09/26 0:38), Arnaldo Carvalho de Melo wrote:
> Em Wed, Sep 25, 2013 at 10:16:16PM +0900, Masami Hiramatsu escreveu:
>> Fix perf probe to probe on some symbols which have some
>> optimzation suffixes, e.g. ".part", ".isra", and ".constprop".
>> To fix this issue, instead of using DIE name, perf probe
>> uses symbol name found by dwfl_module_addrsym().
>
> Thanks Masami! Now it behaves _exactly_ as I expected and need:
>
> [root@zoo linux]# perf probe -L getname_flags:65
> <getname_flags@/home/git/linux/fs/namei.c:65>
> 65 result->uptr = filename;
> 66 audit_getname(result);
> return result;
>
> error:
> 70 final_putname(result);
> 71 return err;
> 72 }
>
> struct filename *
> getname(const char __user * filename)
>
> [root@zoo linux]# perf probe -V getname_flags:65
> Available variables at getname_flags:65
> @<getname_flags.part.35+178>
> char* filename
> int* empty
> long int max
> struct filename* result
> [root@zoo linux]# perf probe 'getname_flags:66 pathname=result->name:string'
> Added new event:
> probe:getname_flags (on getname_flags:66 with pathname=result->name:string)
>
> You can now use it in all perf tools, such as:
>
> perf record -e probe:getname_flags -aR sleep 1
>
> [root@zoo linux]# perf record -a -e probe:getname_flags
> ^C[ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 1.252 MB perf.data (~54692 samples) ]
> [root@zoo linux]# perf script | grep -v '# | head -5
>> ^C
> [root@zoo linux]# perf script | grep -v '^#' | head -5
> libvirtd 1163 [001] 100606.469450: probe:getname_flags: (ffffffff811a2f89) pathname="/proc/cpuinfo"
> libvirtd 1163 [001] 100606.469563: probe:getname_flags: (ffffffff811a2f89) pathname="/sys/devices/system/node"
> libvirtd 1163 [001] 100606.469596: probe:getname_flags: (ffffffff811a2f89) pathname="/sys/devices/system/node/node0"
> libvirtd 1163 [001] 100606.469612: probe:getname_flags: (ffffffff811a2f89) pathname="/sys/devices/system/node/node0/cpu0/online"
> libvirtd 1163 [001] 100606.469628: probe:getname_flags: (ffffffff811a2f89) pathname="/sys/devices/system/node/node0/cpu0/topology/physical_package_id"
> [root@zoo linux]#
>
> Thanks a lot, applied to my perf/urgent branch,
>
> - Arnaldo
>


--
Masami HIRAMATSU
IT Management Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: [email protected]