Re: [PATCH -tip perf/probes 00/10] x86 insn decoder bugfixes

[Ingo Molnar <mingo@elte.hu>]

* Masami Hiramatsu <mhiramat@redhat.com> wrote:

> Hi Ingo,
> 
> Here are bugfixes and some enhances of x86-insn decoder and perf-probe.
>  - x86 insn decoder supports AVX and FMA.
>  - perf-probe syntax change.
>  - perf-probe supports function-relative line number.
>  - minor bugfixes.
> 
> New perf-probe syntax is below:
> 
>   perf probe 'PROBE'
> 
>  or 
> 
>   perf probe --add 'PROBE'
> 
>  where, PROBE is
> 
>   <source>:<line-number>
> 
>  or
> 
>   <function>[:<rel-lineno>|+<byte-offset>|%return][@<source>]
> 
>  e.g.
> 
>   perf probe 'schedule:10@kernel/sched.c'
> 
>   puts a probe at 10th line from entry line of schedule() function
>   in kernel/sched.c." and
> 
>   perf probe 'vmalloc%return'
> 
>   puts a return probe at the returning of vmalloc.
> 
> TODO:
>  - Support --line option to show which lines user can probe.
>  - Support lazy string matching.

Ok, i like these fixes and improvements - thanks Masami!

One detail i noticed is that we are still not very smart about finding 
our vmlinux file. I booted the kernel on a box and it gave:

 aldebaran:~/linux/linux> perf probe schedule
   Fatal: vmlinux/module file open
 aldebaran:~/linux/linux> ls -l vmlinux
 -rwxrwxr-x 1 mingo mingo 21589717 2009-10-29 09:04 vmlinux

Firstly, it should print something more meaningful, such as:

 aldebaran:~/linux/linux> perf probe schedule
   Fatal: Could not open vmlinux/module file

Secondly, we should look beyond these places:

25806 open("/lib/modules/2.6.32-rc5-tip-01760-g2c4b5e0-dirty/build/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
25806 open("/usr/lib/debug/lib/modules/2.6.32-rc5-tip-01760-g2c4b5e0-dirty/vmlinux", O_RDONLY) = -1 ENOENT (No such file or directory)
25806 open("/boot/vmlinux-debug-2.6.32-rc5-tip-01760-g2c4b5e0-dirty", O_RDONLY) = -1 ENOENT (No such file or directory)
25806 write(2, "  Fatal: vmlinux/module file open"..., 34) = 34
25806 exit_group(128)                   = ?

and look into the current directory as well.

Thirdly, i think we should expose the build-id of the kernel and the 
path to the vmlinux (and modules) via /proc/build-id or so. That way 
tooling can find the vmlinux file and can validate that it matches the 
kernel's signature. (maybe include a file date as well - that's a faster 
check than a full build-id checksum, especially for large kernels)

Another problem i noticed is that a vmlinux without DEBUG_INFO will fail 
in this way:

 aldebaran:~/linux/linux> perf probe schedule
   Fatal: Failed to call dwarf_init(). Maybe, not a dwarf file.

this is not meaningful to a user. A more usable message would be:

 aldebaran:~/linux/linux> perf probe schedule
   Fatal: Have not found dwarf info in the vmlinux - please rebuild with CONFIG_DEBUG_INFO

but ... we should really not force DEBUG_INFO for a simple probe that is 
based on an ELF symbol. We already parse ELF symbols so 'perf probe 
schedule' should be able to figure out where to put the probe point.

Not forcing debuginfo for simple usecases is extremely important for 
usability.

And once i had these fixed, i got:

 aldebaran:~/linux/linux> perf probe schedule
   Fatal: kprobe_events open

Which is not a meaningful error message either. This error occured due 
to CONFIG_KPROBE_TRACER not being enabled.

What we want here is two fold:

 - enable kprobes event support when perf events is enabled and kprobes
   is enabled. We dont want another config option for it.

 - and we need to improve error messages so that users can figure out 
   what is the problem.

Once i had this third roadblock out of the way i noticed that the _real_ 
reason for the error was that i was not root and had no privilege to 
insert a kprobe.

Once root, the probe worked well:

 # perf probe schedule
 Adding new event: p:perfprobe/schedule_0 schedule+0

And it seems to be precise:

aldebaran:/home/mingo> perf stat -e perfprobe:__switch_to_0 -e cs -a ./hackbench 1
Time: 0.018

 Performance counter stats for './hackbench 1':

           7358  perfprobe:__switch_to_0  #      0.000 M/sec
           7364  context-switches         #      0.000 M/sec

    0.119152919  seconds time elapsed

(The difference of 6 context-switches should be investigated i suspect.)

Btw., very small nit, it would be better to put that sentence into past 
tense:

 # perf probe schedule
 Added new event: p:perfprobe/schedule_0 schedule+0

To make sure the user knows that the action has been pursued already.

I'd expect the typical user give up much sooner than i did so we really 
need to address these usability details - emit useful error messages and 
be more successful in getting the user what he wants.

But the basic UI is already pretty promising!

A few further (and very small) UI tweaks i'd suggest:

Firstly, could we please make the first probe inserted named plain after 
the symbol it specifies, with no _0 postfix? I.e. instead of:

           7358  perfprobe:__switch_to_0  #      0.000 M/sec

we'd get:

           7358  perfprobe:__switch_to    #      0.000 M/sec

Subsequent probes for the same symbol can be named _1, _2 - but the 
first symbol should not have this needless post-fix.

Secondly, i think we should remove the 'perf' bit from the probe name. 
I.e. instead of:

           7358  perfprobe:__switch_to    #      0.000 M/sec

we should do:

           7358  probe:__switch_to        #      0.000 M/sec

as that's really what the user cares about. The user already knows that 
we are in perf - no need to repeat that in every event specification.

Thanks,

	Ingo