* perf probe + uprobes missing events
@ 2020-04-06 14:53 Arnaldo Carvalho de Melo
2020-04-06 14:54 ` Arnaldo Carvalho de Melo
2020-04-07 12:39 ` Masami Hiramatsu
0 siblings, 2 replies; 4+ messages in thread
From: Arnaldo Carvalho de Melo @ 2020-04-06 14:53 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: Jiri Olsa, Kajol Jain, Andi Kleen, Linux Kernel Mailing List,
linux-perf-users
Hi Masami,
I'm trying to use 'perf probe' to debug 'perf test', but I'm not
getting repeatable results, take a look:
I'm trying to figure out which expresssions are _really_ being tested
byu the 'perf test expr' testcase, so I added a probe to the
expr__parse() routine, asking for the expr string to be printed:
[root@five ~]# perf probe -x ~/bin/perf -L expr__parse
<expr__parse@/home/acme/git/perf/tools/perf/util/expr.c:0>
0 int expr__parse(double *final_val, struct expr_parse_ctx *ctx, const char *expr, int runtime)
1 {
2 return __expr__parse(final_val, ctx, expr, EXPR_PARSE, runtime) ? -1 : 0;
3 }
static bool
already_seen(const char *val, const char *one, const char **other,
[root@five ~]#
[root@five ~]# perf probe -x ~/bin/perf expr__parse expr:string
Target program is compiled without optimization. Skipping prologue.
Probe on address 0x5cb11b to force probing at the function entry.
Added new event:
probe_perf:expr__parse (on expr__parse in /home/acme/bin/perf with expr:string)
You can now use it in all perf tools, such as:
perf record -e probe_perf:expr__parse -aR sleep 1
[root@five ~]#
[root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
0.000 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
0.015 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
0.018 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
0.020 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
0.023 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
0.026 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
0.029 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
0.031 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
0.034 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
0.036 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
0.039 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
0.041 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
[root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
0.000 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
0.021 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
0.025 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
0.029 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
0.033 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
0.041 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
0.044 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
[root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
0.000 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
0.020 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
0.025 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
0.029 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
0.032 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
0.037 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
0.040 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
0.043 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
0.046 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
0.049 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
0.053 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
0.056 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
[root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
[root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
[root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
[root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
[root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
0.000 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
0.014 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
0.017 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
0.021 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
0.024 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
0.030 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
0.032 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
0.035 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
0.038 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
0.040 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
0.044 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
0.046 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
[root@five ~]#
Do you have any idea why that happens?
- Arnaldo
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: perf probe + uprobes missing events
2020-04-06 14:53 perf probe + uprobes missing events Arnaldo Carvalho de Melo
@ 2020-04-06 14:54 ` Arnaldo Carvalho de Melo
2020-04-07 12:39 ` Masami Hiramatsu
1 sibling, 0 replies; 4+ messages in thread
From: Arnaldo Carvalho de Melo @ 2020-04-06 14:54 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: Jiri Olsa, Kajol Jain, Andi Kleen, Linux Kernel Mailing List,
linux-perf-users
Em Mon, Apr 06, 2020 at 11:53:56AM -0300, Arnaldo Carvalho de Melo escreveu:
> Hi Masami,
Sorry, details about the system:
[root@five ~]# uname -a
Linux five 5.5.10-200.fc31.x86_64 #1 SMP Wed Mar 18 14:21:38 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
[root@five ~]# perf -vv
perf version 5.6.gea05cf482862
dwarf: [ on ] # HAVE_DWARF_SUPPORT
dwarf_getlocations: [ on ] # HAVE_DWARF_GETLOCATIONS_SUPPORT
glibc: [ on ] # HAVE_GLIBC_SUPPORT
gtk2: [ on ] # HAVE_GTK2_SUPPORT
syscall_table: [ on ] # HAVE_SYSCALL_TABLE_SUPPORT
libbfd: [ on ] # HAVE_LIBBFD_SUPPORT
libelf: [ on ] # HAVE_LIBELF_SUPPORT
libnuma: [ on ] # HAVE_LIBNUMA_SUPPORT
numa_num_possible_cpus: [ on ] # HAVE_LIBNUMA_SUPPORT
libperl: [ on ] # HAVE_LIBPERL_SUPPORT
libpython: [ on ] # HAVE_LIBPYTHON_SUPPORT
libslang: [ on ] # HAVE_SLANG_SUPPORT
libcrypto: [ on ] # HAVE_LIBCRYPTO_SUPPORT
libunwind: [ on ] # HAVE_LIBUNWIND_SUPPORT
libdw-dwarf-unwind: [ on ] # HAVE_DWARF_SUPPORT
zlib: [ on ] # HAVE_ZLIB_SUPPORT
lzma: [ on ] # HAVE_LZMA_SUPPORT
get_cpuid: [ on ] # HAVE_AUXTRACE_SUPPORT
bpf: [ on ] # HAVE_LIBBPF_SUPPORT
aio: [ on ] # HAVE_AIO_SUPPORT
zstd: [ on ] # HAVE_ZSTD_SUPPORT
[root@five ~]# rpm -q elfutils
elfutils-0.178-7.fc31.x86_64
[root@five ~]#
> I'm trying to use 'perf probe' to debug 'perf test', but I'm not
> getting repeatable results, take a look:
>
> I'm trying to figure out which expresssions are _really_ being tested
> byu the 'perf test expr' testcase, so I added a probe to the
> expr__parse() routine, asking for the expr string to be printed:
>
> [root@five ~]# perf probe -x ~/bin/perf -L expr__parse
> <expr__parse@/home/acme/git/perf/tools/perf/util/expr.c:0>
> 0 int expr__parse(double *final_val, struct expr_parse_ctx *ctx, const char *expr, int runtime)
> 1 {
> 2 return __expr__parse(final_val, ctx, expr, EXPR_PARSE, runtime) ? -1 : 0;
> 3 }
>
> static bool
> already_seen(const char *val, const char *one, const char **other,
>
> [root@five ~]#
>
> [root@five ~]# perf probe -x ~/bin/perf expr__parse expr:string
> Target program is compiled without optimization. Skipping prologue.
> Probe on address 0x5cb11b to force probing at the function entry.
>
> Added new event:
> probe_perf:expr__parse (on expr__parse in /home/acme/bin/perf with expr:string)
>
> You can now use it in all perf tools, such as:
>
> perf record -e probe_perf:expr__parse -aR sleep 1
>
> [root@five ~]#
>
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> 0.000 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
> 0.015 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
> 0.018 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
> 0.020 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
> 0.023 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
> 0.026 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
> 0.029 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
> 0.031 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
> 0.034 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
> 0.036 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
> 0.039 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
> 0.041 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> 0.000 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
> 0.021 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
> 0.025 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
> 0.029 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
> 0.033 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
> 0.041 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
> 0.044 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> 0.000 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
> 0.020 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
> 0.025 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
> 0.029 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
> 0.032 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
> 0.037 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
> 0.040 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
> 0.043 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
> 0.046 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
> 0.049 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
> 0.053 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
> 0.056 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> 0.000 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
> 0.014 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
> 0.017 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
> 0.021 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
> 0.024 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
> 0.030 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
> 0.032 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
> 0.035 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
> 0.038 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
> 0.040 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
> 0.044 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
> 0.046 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
> [root@five ~]#
>
>
> Do you have any idea why that happens?
>
> - Arnaldo
--
- Arnaldo
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: perf probe + uprobes missing events
2020-04-06 14:53 perf probe + uprobes missing events Arnaldo Carvalho de Melo
2020-04-06 14:54 ` Arnaldo Carvalho de Melo
@ 2020-04-07 12:39 ` Masami Hiramatsu
2020-04-08 3:14 ` Masami Hiramatsu
1 sibling, 1 reply; 4+ messages in thread
From: Masami Hiramatsu @ 2020-04-07 12:39 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Jiri Olsa, Kajol Jain, Andi Kleen, Linux Kernel Mailing List,
linux-perf-users
Hi Arnaldo,
On Mon, 6 Apr 2020 11:53:56 -0300
Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> Hi Masami,
>
> I'm trying to use 'perf probe' to debug 'perf test', but I'm not
> getting repeatable results, take a look:
>
> I'm trying to figure out which expresssions are _really_ being tested
> byu the 'perf test expr' testcase, so I added a probe to the
> expr__parse() routine, asking for the expr string to be printed:
>
> [root@five ~]# perf probe -x ~/bin/perf -L expr__parse
> <expr__parse@/home/acme/git/perf/tools/perf/util/expr.c:0>
> 0 int expr__parse(double *final_val, struct expr_parse_ctx *ctx, const char *expr, int runtime)
> 1 {
> 2 return __expr__parse(final_val, ctx, expr, EXPR_PARSE, runtime) ? -1 : 0;
> 3 }
>
> static bool
> already_seen(const char *val, const char *one, const char **other,
>
> [root@five ~]#
>
> [root@five ~]# perf probe -x ~/bin/perf expr__parse expr:string
> Target program is compiled without optimization. Skipping prologue.
> Probe on address 0x5cb11b to force probing at the function entry.
>
> Added new event:
> probe_perf:expr__parse (on expr__parse in /home/acme/bin/perf with expr:string)
>
> You can now use it in all perf tools, such as:
>
> perf record -e probe_perf:expr__parse -aR sleep 1
>
> [root@five ~]#
Hmm, These operation looks good to me. However,
>
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> 0.000 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
> 0.015 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
> 0.018 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
> 0.020 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
> 0.023 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
> 0.026 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
> 0.029 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
> 0.031 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
> 0.034 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
> 0.036 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
> 0.039 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
> 0.041 :2994175/2994175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> 0.000 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
> 0.021 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
> 0.025 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
> 0.029 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
> 0.033 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
> 0.041 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
> 0.044 perf/2996042 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> 0.000 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
> 0.020 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
> 0.025 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
> 0.029 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
> 0.032 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
> 0.037 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
> 0.040 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
> 0.043 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
> 0.046 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
> 0.049 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
> 0.053 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
> 0.056 perf/2996416 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> [root@five ~]# perf trace -e probe_perf:expr_* perf test -F expr
> 7: Simple expression parser : Ok
> 0.000 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1")
> 0.014 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO+BAR")
> 0.017 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(BAR/2)%2")
> 0.021 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1 - -4")
> 0.024 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "(FOO-1)*2 + (BAR/2)%2 - -4")
> 0.030 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 | 1")
> 0.032 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1-1 & 1")
> 0.035 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "min(1,2) + 1")
> 0.038 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "max(1,2) + 1")
> 0.040 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "1+1 if 3*4 else 0")
> 0.044 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "FOO/0")
> 0.046 :2998175/2998175 probe_perf:expr__parse(__probe_ip: 6074674, expr_string: "BAR/")
> [root@five ~]#
Strange. This seems bug in uprobes. Did you try to enable ftrace event
and dump ftrace trace buffer for each time?
Also, it may help if you dump the /sys/kernel/debug/tracing/uprobe_profile.
It may indicate how many times the probe is hit and missed.
OK, I'll also try to reproduce it.
Thank you,
>
>
> Do you have any idea why that happens?
>
> - Arnaldo
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: perf probe + uprobes missing events
2020-04-07 12:39 ` Masami Hiramatsu
@ 2020-04-08 3:14 ` Masami Hiramatsu
0 siblings, 0 replies; 4+ messages in thread
From: Masami Hiramatsu @ 2020-04-08 3:14 UTC (permalink / raw)
To: Arnaldo Carvalho de Melo
Cc: Masami Hiramatsu, Jiri Olsa, Kajol Jain, Andi Kleen,
Linux Kernel Mailing List, linux-perf-users
Hi Arnaldo,
This seems like a perf (perf's ringbuffer?) issue.
Actually, we can not enable perf and ftrace on same uprobe event yet, but the hit counter (uprobe_profile) works.
1) Setup the event.
$ sudo ./perf probe -x ./perf expr__parse expr:string
Added new event:
probe_perf:expr__parse (on expr__parse in /home/mhiramat/ksrc/linux/tools/perf/perf with expr:string)
You can now use it in all perf tools, such as:
perf record -e probe_perf:expr__parse -aR sleep 1
$ sudo cat /sys/kernel/debug/tracing/uprobe_profile
/home/mhiramat/ksrc/linux/tools/perf/perf expr__parse 0
2) run the test command
$ sudo ./perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
0.000 perf/9789 probe_perf:expr__parse(__probe_ip: 94836726971904, expr_string: "1+1")
$ sudo cat /sys/kernel/debug/tracing/uprobe_profile
/home/mhiramat/ksrc/linux/tools/perf/perf expr__parse 12
OK, this shows the perf trace command only shows 1 event, but uprobe_event itself hits 12 times.
3) run the test command again
$ sudo ./perf trace -e probe_perf:expr_* perf test -F expr
7: Simple expression parser : Ok
0.000 perf/9847 probe_perf:expr__parse(__probe_ip: 94778335464960, expr_string: "1+1")
0.014 perf/9847 probe_perf:expr__parse(__probe_ip: 94778335464960, expr_string: "FOO+BAR")
0.018 perf/9847 probe_perf:expr__parse(__probe_ip: 94778335464960, expr_string: "(BAR/2)%2")
$ sudo cat /sys/kernel/debug/tracing/uprobe_profile
/home/mhiramat/ksrc/linux/tools/perf/perf expr__parse 24
Again, the perf trace shows only 3 events, but uprobe event hits +12 times
4) run the test command with ftrace.
$ echo 1 | sudo tee /sys/kernel/debug/tracing/events/probe_perf/enable
1
$ ./perf test -F expr
7: Simple expression parser : Ok
$ sudo cat /sys/kernel/debug/tracing/uprobe_profile
/home/mhiramat/ksrc/linux/tools/perf/perf expr__parse 36
Hit +12 times and the ftrace shows all events correctly.
$ sudo cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 24/24 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
perf-9883 [003] d... 9287.936678: expr__parse: (0x55ea35ce9e00) expr_string="1+1"
perf-9883 [003] d... 9287.936694: expr__parse: (0x55ea35ce9e00) expr_string="FOO+BAR"
perf-9883 [003] d... 9287.936699: expr__parse: (0x55ea35ce9e00) expr_string="(BAR/2)%2"
perf-9883 [003] d... 9287.936704: expr__parse: (0x55ea35ce9e00) expr_string="1 - -4"
perf-9883 [003] d... 9287.936707: expr__parse: (0x55ea35ce9e00) expr_string="(FOO-1)*2 + (BAR/2)%2 - -4"
perf-9883 [003] d... 9287.936712: expr__parse: (0x55ea35ce9e00) expr_string="1-1 | 1"
perf-9883 [003] d... 9287.936716: expr__parse: (0x55ea35ce9e00) expr_string="1-1 & 1"
perf-9883 [003] d... 9287.936719: expr__parse: (0x55ea35ce9e00) expr_string="min(1,2) + 1"
perf-9883 [003] d... 9287.936723: expr__parse: (0x55ea35ce9e00) expr_string="max(1,2) + 1"
perf-9883 [003] d... 9287.936726: expr__parse: (0x55ea35ce9e00) expr_string="1+1 if 3*4 else 0"
perf-9883 [003] d... 9287.936731: expr__parse: (0x55ea35ce9e00) expr_string="FOO/0"
perf-9883 [003] d... 9287.936734: expr__parse: (0x55ea35ce9e00) expr_string="BAR/"
It seems that the perf ring buffer returns only early events
(since expr_string="1+1" is always shown), so I guess there is
a timing issue when the ring buffer is read.
Can we delay the read timing?
Thank you,
--
Masami Hiramatsu <mhiramat@kernel.org>
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2020-04-08 3:14 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2020-04-06 14:53 perf probe + uprobes missing events Arnaldo Carvalho de Melo
2020-04-06 14:54 ` Arnaldo Carvalho de Melo
2020-04-07 12:39 ` Masami Hiramatsu
2020-04-08 3:14 ` Masami Hiramatsu
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).