perf tools event parsing code

perf tools event parsing code

[Arnaldo Carvalho de Melo]

Trying to figure out why this cset, by Wangnan:

https://git.kernel.org/cgit/linux/kernel/git/acme/linux.git/commit/?h=perf/ebpf&id=42cb6deef348f6afece0ad6fd7b034bfb532000e

doesn't make the routine he associated with parsing '--event bpf_program.o',
ended up in this:

#0  parse_events__scan_bytes (yybytes=yybytes@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", _yybytes_len=22, yyscanner=0x18e4c30)
    at util/parse-events-flex.c:3312
#1  0x00000000004addb3 in parse_events__scan_string (yystr=<optimized out>, yystr@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", yyscanner=<optimized out>)
    at util/parse-events-flex.c:3274
#2  0x000000000048a5e7 in parse_events__scanner (str=str@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", data=data@entry=0x7fffffff83f0, 
    start_token=start_token@entry=259) at util/parse-events.c:1081
#3  0x000000000048ca52 in parse_events_terms (terms=terms@entry=0x18e4a88, str=str@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n")
    at util/parse-events.c:1104
#4  0x00000000004b2497 in __perf_pmu__new_alias (list=list@entry=0x7fffffffa700, dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", 
    name=name@entry=0x18d864b "cache-references", desc=desc@entry=0x0, val=val@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n") at util/pmu.c:224
#5  0x00000000004b25c0 in perf_pmu__new_alias (list=list@entry=0x7fffffffa700, dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", 
    name=name@entry=0x18d864b "cache-references", file=file@entry=0x18d67e0) at util/pmu.c:258
#6  0x00000000004b2788 in pmu_aliases_parse (dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", head=head@entry=0x7fffffffa700)
    at util/pmu.c:313
#7  0x00000000004b2864 in pmu_aliases (name=name@entry=0x5b9c47 "cpu", head=head@entry=0x7fffffffa700) at util/pmu.c:340
#8  0x00000000004b328a in pmu_lookup (name=<optimized out>, name@entry=0x5b9c47 "cpu") at util/pmu.c:477
#9  0x00000000004b33de in perf_pmu__find (name=name@entry=0x5b9c47 "cpu") at util/pmu.c:541
#10 0x000000000048a445 in perf_pmu__parse_init () at util/parse-events.c:1008
#11 0x000000000048b86d in perf_pmu__parse_check (name=name@entry=0x18d6c40 "file.c") at util/parse-events.c:1054
#12 0x00000000004ad4e2 in pmu_str_check (scanner=scanner@entry=0x18d6f20) at util/parse-events.l:74
#13 0x00000000004af78b in parse_events_lex (yylval_param=yylval_param@entry=0x7fffffffa900, yylloc_param=yylloc_param@entry=0x7fffffffa920, 
    yyscanner=yyscanner@entry=0x18d6f20) at util/parse-events.l:267
#14 0x00000000004b042c in parse_events_parse (_data=_data@entry=0x7fffffffbec0, scanner=0x18d6f20) at util/parse-events-bison.c:1570
#15 0x000000000048a5f6 in parse_events__scanner (str=str@entry=0x7fffffffe778 "file.c", data=data@entry=0x7fffffffbec0, start_token=start_token@entry=258)
    at util/parse-events.c:1086
#16 0x000000000048b955 in parse_events (evlist=0x18d7b90, str=str@entry=0x7fffffffe778 "file.c", err=err@entry=0x7fffffffbf10) at util/parse-events.c:1126
#17 0x000000000048b9f7 in parse_events_option (opt=<optimized out>, str=0x7fffffffe778 "file.c", unset=<optimized out>) at util/parse-events.c:1224
#18 0x0000000000487f30 in get_value (p=p@entry=0x7fffffffc0b0, opt=0x831c00 <__record_options>, flags=flags@entry=1) at util/parse-options.c:151
#19 0x000000000048823e in parse_short_opt (p=p@entry=0x7fffffffc0b0, options=<optimized out>, options@entry=0x831c00 <__record_options>)
    at util/parse-options.c:230
#20 0x0000000000488d6e in parse_options_step (ctx=ctx@entry=0x7fffffffc0b0, options=options@entry=0x831c00 <__record_options>, 
    usagestr=usagestr@entry=0x599850 <__record_usage>) at util/parse-options.c:401
#21 0x000000000048918c in parse_options_subcommand (argc=argc@entry=5, argv=argv@entry=0x7fffffffe520, options=0x831c00 <__record_options>, 
    subcommands=subcommands@entry=0x0, usagestr=0x599850 <__record_usage>, flags=flags@entry=2) at util/parse-options.c:518
#22 0x00000000004892da in parse_options (argc=argc@entry=5, argv=argv@entry=0x7fffffffe520, options=<optimized out>, usagestr=<optimized out>, 
    flags=flags@entry=2) at util/parse-options.c:553
#23 0x000000000042ad70 in cmd_record (argc=5, argv=0x7fffffffe520, prefix=<optimized out>) at builtin-record.c:1102
#24 0x0000000000474253 in run_builtin (p=p@entry=0x83c7f0 <commands+144>, argc=argc@entry=5, argv=argv@entry=0x7fffffffe520) at perf.c:370
#25 0x000000000047443f in handle_internal_command (argc=5, argv=0x7fffffffe520) at perf.c:429
#26 0x00000000004744b0 in run_argv (argcp=argcp@entry=0x7fffffffe38c, argv=argv@entry=0x7fffffffe380) at perf.c:473
#27 0x0000000000474726 in main (argc=5, argv=0x7fffffffe520) at perf.c:588
(gdb) 

/me trying to figure out this problem, but also how to avoid doing all this
seemingly unnecessary work, i.e. reading everything on the sysfs pmu files when
trying to figure out if this is a bpf filter event (-e foo.o).

Ideas?

- Arnaldo

Re: perf tools event parsing code

[Jiri Olsa]

On Fri, Jul 31, 2015 at 05:55:32PM -0300, Arnaldo Carvalho de Melo wrote:
> Trying to figure out why this cset, by Wangnan:
> 
> https://git.kernel.org/cgit/linux/kernel/git/acme/linux.git/commit/?h=perf/ebpf&id=42cb6deef348f6afece0ad6fd7b034bfb532000e
> 
> doesn't make the routine he associated with parsing '--event bpf_program.o',
> ended up in this:

that change looks ok to me, but this
backtrac eis from pmu cpu lookup/parsing, please check below
> 
> #0  parse_events__scan_bytes (yybytes=yybytes@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", _yybytes_len=22, yyscanner=0x18e4c30)
>     at util/parse-events-flex.c:3312
> #1  0x00000000004addb3 in parse_events__scan_string (yystr=<optimized out>, yystr@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", yyscanner=<optimized out>)
>     at util/parse-events-flex.c:3274
> #2  0x000000000048a5e7 in parse_events__scanner (str=str@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", data=data@entry=0x7fffffff83f0, 
>     start_token=start_token@entry=259) at util/parse-events.c:1081
> #3  0x000000000048ca52 in parse_events_terms (terms=terms@entry=0x18e4a88, str=str@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n")
>     at util/parse-events.c:1104
> #4  0x00000000004b2497 in __perf_pmu__new_alias (list=list@entry=0x7fffffffa700, dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", 
>     name=name@entry=0x18d864b "cache-references", desc=desc@entry=0x0, val=val@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n") at util/pmu.c:224
> #5  0x00000000004b25c0 in perf_pmu__new_alias (list=list@entry=0x7fffffffa700, dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", 
>     name=name@entry=0x18d864b "cache-references", file=file@entry=0x18d67e0) at util/pmu.c:258
> #6  0x00000000004b2788 in pmu_aliases_parse (dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", head=head@entry=0x7fffffffa700)
>     at util/pmu.c:313
> #7  0x00000000004b2864 in pmu_aliases (name=name@entry=0x5b9c47 "cpu", head=head@entry=0x7fffffffa700) at util/pmu.c:340
> #8  0x00000000004b328a in pmu_lookup (name=<optimized out>, name@entry=0x5b9c47 "cpu") at util/pmu.c:477
> #9  0x00000000004b33de in perf_pmu__find (name=name@entry=0x5b9c47 "cpu") at util/pmu.c:541
> #10 0x000000000048a445 in perf_pmu__parse_init () at util/parse-events.c:1008
> #11 0x000000000048b86d in perf_pmu__parse_check (name=name@entry=0x18d6c40 "file.c") at util/parse-events.c:1054
> #12 0x00000000004ad4e2 in pmu_str_check (scanner=scanner@entry=0x18d6f20) at util/parse-events.l:74

this is support for the event term shortcut, like using

  perf record -e mem-loads ...
    
instead of:
    
  perf record -e cpu/mem-loads/

it calls 'perf_pmu__find("cpu") which triggers 'cpu' pmu 
lookup 'pmu_lookup("cpu")'

and that one triggers alias parsing above as well  ;-)

> #13 0x00000000004af78b in parse_events_lex (yylval_param=yylval_param@entry=0x7fffffffa900, yylloc_param=yylloc_param@entry=0x7fffffffa920, 
>     yyscanner=yyscanner@entry=0x18d6f20) at util/parse-events.l:267
> #14 0x00000000004b042c in parse_events_parse (_data=_data@entry=0x7fffffffbec0, scanner=0x18d6f20) at util/parse-events-bison.c:1570
> #15 0x000000000048a5f6 in parse_events__scanner (str=str@entry=0x7fffffffe778 "file.c", data=data@entry=0x7fffffffbec0, start_token=start_token@entry=258)
>     at util/parse-events.c:1086
> #16 0x000000000048b955 in parse_events (evlist=0x18d7b90, str=str@entry=0x7fffffffe778 "file.c", err=err@entry=0x7fffffffbf10) at util/parse-events.c:1126

events parsing starts here ^^^

> #17 0x000000000048b9f7 in parse_events_option (opt=<optimized out>, str=0x7fffffffe778 "file.c", unset=<optimized out>) at util/parse-events.c:1224
> #18 0x0000000000487f30 in get_value (p=p@entry=0x7fffffffc0b0, opt=0x831c00 <__record_options>, flags=flags@entry=1) at util/parse-options.c:151
> #19 0x000000000048823e in parse_short_opt (p=p@entry=0x7fffffffc0b0, options=<optimized out>, options@entry=0x831c00 <__record_options>)
>     at util/parse-options.c:230
> #20 0x0000000000488d6e in parse_options_step (ctx=ctx@entry=0x7fffffffc0b0, options=options@entry=0x831c00 <__record_options>, 
>     usagestr=usagestr@entry=0x599850 <__record_usage>) at util/parse-options.c:401
> #21 0x000000000048918c in parse_options_subcommand (argc=argc@entry=5, argv=argv@entry=0x7fffffffe520, options=0x831c00 <__record_options>, 
>     subcommands=subcommands@entry=0x0, usagestr=0x599850 <__record_usage>, flags=flags@entry=2) at util/parse-options.c:518
> #22 0x00000000004892da in parse_options (argc=argc@entry=5, argv=argv@entry=0x7fffffffe520, options=<optimized out>, usagestr=<optimized out>, 
>     flags=flags@entry=2) at util/parse-options.c:553
> #23 0x000000000042ad70 in cmd_record (argc=5, argv=0x7fffffffe520, prefix=<optimized out>) at builtin-record.c:1102
> #24 0x0000000000474253 in run_builtin (p=p@entry=0x83c7f0 <commands+144>, argc=argc@entry=5, argv=argv@entry=0x7fffffffe520) at perf.c:370
> #25 0x000000000047443f in handle_internal_command (argc=5, argv=0x7fffffffe520) at perf.c:429
> #26 0x00000000004744b0 in run_argv (argcp=argcp@entry=0x7fffffffe38c, argv=argv@entry=0x7fffffffe380) at perf.c:473
> #27 0x0000000000474726 in main (argc=5, argv=0x7fffffffe520) at perf.c:588
> (gdb) 
> 
> /me trying to figure out this problem, but also how to avoid doing all this
> seemingly unnecessary work, i.e. reading everything on the sysfs pmu files when
> trying to figure out if this is a bpf filter event (-e foo.o).

it's deep, but it's initialized only once.. after it's initialized,
there's no other parsing

jirka

Re: perf tools event parsing code

[Arnaldo Carvalho de Melo]

Em Sun, Aug 02, 2015 at 09:56:27PM +0200, Jiri Olsa escreveu:
> On Fri, Jul 31, 2015 at 05:55:32PM -0300, Arnaldo Carvalho de Melo wrote:
> > Trying to figure out why this cset, by Wangnan:

> > https://git.kernel.org/cgit/linux/kernel/git/acme/linux.git/commit/?h=perf/ebpf&id=42cb6deef348f6afece0ad6fd7b034bfb532000e

> > doesn't make the routine he associated with parsing '--event bpf_program.o',
> > ended up in this:
 
> that change looks ok to me, but this

Well, the function associated with parsing FOO.o with BPF is only called
when it is prefixed with './', i.e. needs some fix.

> backtrace is from pmu cpu lookup/parsing, please check below

Yeah, probably it is not called when we use ./bpf_program.o, will
check...

  (gdb) break pmu_str_check
  Breakpoint 1 at 0x4ad4ac: file util/parse-events.l, line 69.
  (gdb) run record -e ./bpf.o sleep 1
  Starting program: /root/bin/perf record -e ./bpf.o sleep 1
  [Thread debugging using libthread_db enabled]
  Using host libthread_db library "/lib64/libthread_db.so.1".
  libbpf: failed to open ./bpf.o: No such file or directory
  bpf: failed to load ./bpf.o
  invalid or unsupported event: './bpf.o'
  Run 'perf list' for a list of valid events

   usage: perf record [<options>] [<command>]
      or: perf record [<options>] -- <command> [<options>]

      -e, --event <event>   event selector. use 'perf list' to list available events
  [Inferior 1 (process 4722) exited with code 0201]
  (gdb)

- Arnaldo

> > 
> > #0  parse_events__scan_bytes (yybytes=yybytes@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", _yybytes_len=22, yyscanner=0x18e4c30)
> >     at util/parse-events-flex.c:3312
> > #1  0x00000000004addb3 in parse_events__scan_string (yystr=<optimized out>, yystr@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", yyscanner=<optimized out>)
> >     at util/parse-events-flex.c:3274
> > #2  0x000000000048a5e7 in parse_events__scanner (str=str@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n", data=data@entry=0x7fffffff83f0, 
> >     start_token=start_token@entry=259) at util/parse-events.c:1081
> > #3  0x000000000048ca52 in parse_events_terms (terms=terms@entry=0x18e4a88, str=str@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n")
> >     at util/parse-events.c:1104
> > #4  0x00000000004b2497 in __perf_pmu__new_alias (list=list@entry=0x7fffffffa700, dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", 
> >     name=name@entry=0x18d864b "cache-references", desc=desc@entry=0x0, val=val@entry=0x7fffffff8480 "event=0x2e,umask=0x4f\n") at util/pmu.c:224
> > #5  0x00000000004b25c0 in perf_pmu__new_alias (list=list@entry=0x7fffffffa700, dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", 
> >     name=name@entry=0x18d864b "cache-references", file=file@entry=0x18d67e0) at util/pmu.c:258
> > #6  0x00000000004b2788 in pmu_aliases_parse (dir=dir@entry=0x7fffffff96b0 "/sys/bus/event_source/devices/cpu/events", head=head@entry=0x7fffffffa700)
> >     at util/pmu.c:313
> > #7  0x00000000004b2864 in pmu_aliases (name=name@entry=0x5b9c47 "cpu", head=head@entry=0x7fffffffa700) at util/pmu.c:340
> > #8  0x00000000004b328a in pmu_lookup (name=<optimized out>, name@entry=0x5b9c47 "cpu") at util/pmu.c:477
> > #9  0x00000000004b33de in perf_pmu__find (name=name@entry=0x5b9c47 "cpu") at util/pmu.c:541
> > #10 0x000000000048a445 in perf_pmu__parse_init () at util/parse-events.c:1008
> > #11 0x000000000048b86d in perf_pmu__parse_check (name=name@entry=0x18d6c40 "file.c") at util/parse-events.c:1054
> > #12 0x00000000004ad4e2 in pmu_str_check (scanner=scanner@entry=0x18d6f20) at util/parse-events.l:74
> 
> this is support for the event term shortcut, like using
> 
>   perf record -e mem-loads ...
>     
> instead of:
>     
>   perf record -e cpu/mem-loads/
> 
> it calls 'perf_pmu__find("cpu") which triggers 'cpu' pmu 
> lookup 'pmu_lookup("cpu")'
> 
> and that one triggers alias parsing above as well  ;-)
> 
> > #13 0x00000000004af78b in parse_events_lex (yylval_param=yylval_param@entry=0x7fffffffa900, yylloc_param=yylloc_param@entry=0x7fffffffa920, 
> >     yyscanner=yyscanner@entry=0x18d6f20) at util/parse-events.l:267
> > #14 0x00000000004b042c in parse_events_parse (_data=_data@entry=0x7fffffffbec0, scanner=0x18d6f20) at util/parse-events-bison.c:1570
> > #15 0x000000000048a5f6 in parse_events__scanner (str=str@entry=0x7fffffffe778 "file.c", data=data@entry=0x7fffffffbec0, start_token=start_token@entry=258)
> >     at util/parse-events.c:1086
> > #16 0x000000000048b955 in parse_events (evlist=0x18d7b90, str=str@entry=0x7fffffffe778 "file.c", err=err@entry=0x7fffffffbf10) at util/parse-events.c:1126
> 
> events parsing starts here ^^^
> 
> > #17 0x000000000048b9f7 in parse_events_option (opt=<optimized out>, str=0x7fffffffe778 "file.c", unset=<optimized out>) at util/parse-events.c:1224
> > #18 0x0000000000487f30 in get_value (p=p@entry=0x7fffffffc0b0, opt=0x831c00 <__record_options>, flags=flags@entry=1) at util/parse-options.c:151
> > #19 0x000000000048823e in parse_short_opt (p=p@entry=0x7fffffffc0b0, options=<optimized out>, options@entry=0x831c00 <__record_options>)
> >     at util/parse-options.c:230
> > #20 0x0000000000488d6e in parse_options_step (ctx=ctx@entry=0x7fffffffc0b0, options=options@entry=0x831c00 <__record_options>, 
> >     usagestr=usagestr@entry=0x599850 <__record_usage>) at util/parse-options.c:401
> > #21 0x000000000048918c in parse_options_subcommand (argc=argc@entry=5, argv=argv@entry=0x7fffffffe520, options=0x831c00 <__record_options>, 
> >     subcommands=subcommands@entry=0x0, usagestr=0x599850 <__record_usage>, flags=flags@entry=2) at util/parse-options.c:518
> > #22 0x00000000004892da in parse_options (argc=argc@entry=5, argv=argv@entry=0x7fffffffe520, options=<optimized out>, usagestr=<optimized out>, 
> >     flags=flags@entry=2) at util/parse-options.c:553
> > #23 0x000000000042ad70 in cmd_record (argc=5, argv=0x7fffffffe520, prefix=<optimized out>) at builtin-record.c:1102
> > #24 0x0000000000474253 in run_builtin (p=p@entry=0x83c7f0 <commands+144>, argc=argc@entry=5, argv=argv@entry=0x7fffffffe520) at perf.c:370
> > #25 0x000000000047443f in handle_internal_command (argc=5, argv=0x7fffffffe520) at perf.c:429
> > #26 0x00000000004744b0 in run_argv (argcp=argcp@entry=0x7fffffffe38c, argv=argv@entry=0x7fffffffe380) at perf.c:473
> > #27 0x0000000000474726 in main (argc=5, argv=0x7fffffffe520) at perf.c:588
> > (gdb) 
> > 
> > /me trying to figure out this problem, but also how to avoid doing all this
> > seemingly unnecessary work, i.e. reading everything on the sysfs pmu files when
> > trying to figure out if this is a bpf filter event (-e foo.o).
> 
> it's deep, but it's initialized only once.. after it's initialized,
> there's no other parsing
> 
> jirka