linux-perf-users.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* kprobe string
@ 2014-07-17  0:51 Brendan Gregg
  2014-07-17  4:41 ` David Ahern
  0 siblings, 1 reply; 6+ messages in thread
From: Brendan Gregg @ 2014-07-17  0:51 UTC (permalink / raw)
  To: linux-perf-use.

G'Day,

I'm not sure where else to ask this; I don't think this functionality
is in perf_events yet...

kprobes is supposed to be able to handle string arguments, but I've
not been able to find a single working example. I'm trying (on 3.16):

# cd /sys/kernel/debug/tracing
# echo 'r:getname getname $retval:string' > kprobe_events
-bash: echo: write error: Invalid argument
# echo 'p:myprobe do_sys_open %dx:string' > kprobe_events
-bash: echo: write error: Invalid argument

I'm following the syntax in Documentation/trace/kprobetrace.txt by
Masami Hiramatsu, and it is recognizing "string". But I'm getting
these errors:

# dmesg | tail -4
[98021.813560] string type has no corresponding fetch method.
[98021.813564] Parse error at argument[0]. (-22)
[98705.956199] string type has no corresponding fetch method.
[98705.956203] Parse error at argument[0]. (-22)

Anyone seen this work? I'm checking the source... Thanks in advance,

Brendan
-- 
http://www.brendangregg.com

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: kprobe string
  2014-07-17  0:51 kprobe string Brendan Gregg
@ 2014-07-17  4:41 ` David Ahern
  2014-07-17  6:29   ` Brendan Gregg
  0 siblings, 1 reply; 6+ messages in thread
From: David Ahern @ 2014-07-17  4:41 UTC (permalink / raw)
  To: Brendan Gregg, linux-perf-use.



On 07/16/2014 06:51 PM, Brendan Gregg wrote:
> G'Day,
>
> I'm not sure where else to ask this; I don't think this functionality
> is in perf_events yet...
>
> kprobes is supposed to be able to handle string arguments, but I've
> not been able to find a single working example. I'm trying (on 3.16):
>
> # cd /sys/kernel/debug/tracing
> # echo 'r:getname getname $retval:string' > kprobe_events
> -bash: echo: write error: Invalid argument
> # echo 'p:myprobe do_sys_open %dx:string' > kprobe_events
> -bash: echo: write error: Invalid argument
>
> I'm following the syntax in Documentation/trace/kprobetrace.txt by
> Masami Hiramatsu, and it is recognizing "string". But I'm getting
> these errors:
>
> # dmesg | tail -4
> [98021.813560] string type has no corresponding fetch method.
> [98021.813564] Parse error at argument[0]. (-22)
> [98705.956199] string type has no corresponding fetch method.
> [98705.956203] Parse error at argument[0]. (-22)
>
> Anyone seen this work? I'm checking the source... Thanks in advance,

Have you seen this:
https://lkml.org/lkml/2014/6/19/698

David

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: kprobe string
  2014-07-17  4:41 ` David Ahern
@ 2014-07-17  6:29   ` Brendan Gregg
  2014-07-17  7:24     ` Namhyung Kim
  0 siblings, 1 reply; 6+ messages in thread
From: Brendan Gregg @ 2014-07-17  6:29 UTC (permalink / raw)
  To: David Ahern; +Cc: linux-perf-use.

G'Day David,

On Wed, Jul 16, 2014 at 9:41 PM, David Ahern <dsahern@gmail.com> wrote:
>
>
> On 07/16/2014 06:51 PM, Brendan Gregg wrote:
>>
>> G'Day,
>>
>> I'm not sure where else to ask this; I don't think this functionality
>> is in perf_events yet...
>>
>> kprobes is supposed to be able to handle string arguments, but I've
>> not been able to find a single working example. I'm trying (on 3.16):
>>
>> # cd /sys/kernel/debug/tracing
>> # echo 'r:getname getname $retval:string' > kprobe_events
>> -bash: echo: write error: Invalid argument
>> # echo 'p:myprobe do_sys_open %dx:string' > kprobe_events
>> -bash: echo: write error: Invalid argument
>>
>> I'm following the syntax in Documentation/trace/kprobetrace.txt by
>> Masami Hiramatsu, and it is recognizing "string". But I'm getting
>> these errors:
>>
>> # dmesg | tail -4
>> [98021.813560] string type has no corresponding fetch method.
>> [98021.813564] Parse error at argument[0]. (-22)
>> [98705.956199] string type has no corresponding fetch method.
>> [98705.956203] Parse error at argument[0]. (-22)
>>
>> Anyone seen this work? I'm checking the source... Thanks in advance,
>
>
> Have you seen this:
> https://lkml.org/lkml/2014/6/19/698
>

Thanks! (I'm trying to keep up with all the perf messages on lkml, but
missed this.)

So, perf can already do this?? And it's the same syntax (":string") as kprobes?

I just tried it out (on 3.14.5):

# perf probe 'getname filename:string'
Added new event:
[...]
# perf record -e probe:getname -a sleep 5
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.234 MB perf.data (~10241 samples) ]
# perf script
            perf 13587 [000] 3576718.127120: probe:getname:
(ffffffff811bbd20)
filename_string="/home/bgregg-testtest/libexec/perf-core/sleep"
            perf 13587 [000] 3576718.127142: probe:getname:
(ffffffff811bbd20) filename_string="/usr/local/sbin/sleep"
            perf 13587 [000] 3576718.127151: probe:getname:
(ffffffff811bbd20) filename_string="/usr/local/bin/sleep"
            perf 13587 [000] 3576718.127159: probe:getname:
(ffffffff811bbd20) filename_string="/usr/sbin/sleep"
            perf 13587 [000] 3576718.127170: probe:getname:
(ffffffff811bbd20) filename_string="/usr/bin/sleep"
            perf 13587 [000] 3576718.127180: probe:getname:
(ffffffff811bbd20) filename_string="/sbin/sleep"
            perf 13587 [000] 3576718.127189: probe:getname:
(ffffffff811bbd20) filename_string="/bin/sleep"
           sleep 13587 [000] 3576718.162025: probe:getname:
(ffffffff811bbd20) filename_string="/etc/ld.so.cache"
           sleep 13587 [000] 3576718.162057: probe:getname:
(ffffffff811bbd20) filename_string="/lib/x86_64-linux-gnu/libc.so.6"
[...]

Wow.

Ok, so that's one solution! :-)

It does need debuginfo, which is a bit of a problem here (the Netflix
cloud, where instances are created and destroyed quickly, so they are
optimized to be small).

I did try just using the return value, which does work without
debuginfo, however, the :string modifier doesn't work. Eg, trying:

# perf probe 'getname%return $retval:string'
Added new event:
Failed to write event: Invalid argument
  Error: Failed to add events. (-1)

 $retval really is a string (well, it's a struct filename *, where the
first member is a char *, so close enough), so perhaps perf could
enhanced to allow this, and I'd be able to trace strings without
debuginfo.  (Unless there's another workaround.)

So tools/perf/Documentation/perf-probe.txt does at least explain when
:string won't work: "You can specify 'string' type only for the local
variable or structure member which is an array of or a pointer to
'char' or 'unsigned char' type." I wonder if kprobes has this
restriction as well.

thanks,

Brendan

-- 
http://www.brendangregg.com

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: kprobe string
  2014-07-17  6:29   ` Brendan Gregg
@ 2014-07-17  7:24     ` Namhyung Kim
  2014-07-17  8:23       ` Brendan Gregg
  0 siblings, 1 reply; 6+ messages in thread
From: Namhyung Kim @ 2014-07-17  7:24 UTC (permalink / raw)
  To: Brendan Gregg; +Cc: David Ahern, linux-perf-use.

Hi Brendan,

On Wed, 16 Jul 2014 23:29:10 -0700, Brendan Gregg wrote:
> G'Day David,
>
> On Wed, Jul 16, 2014 at 9:41 PM, David Ahern <dsahern@gmail.com> wrote:
>>
>>
>> On 07/16/2014 06:51 PM, Brendan Gregg wrote:
>>>
>>> G'Day,
>>>
>>> I'm not sure where else to ask this; I don't think this functionality
>>> is in perf_events yet...
>>>
>>> kprobes is supposed to be able to handle string arguments, but I've
>>> not been able to find a single working example. I'm trying (on 3.16):
>>>
>>> # cd /sys/kernel/debug/tracing
>>> # echo 'r:getname getname $retval:string' > kprobe_events
>>> -bash: echo: write error: Invalid argument
>>> # echo 'p:myprobe do_sys_open %dx:string' > kprobe_events
>>> -bash: echo: write error: Invalid argument
>>>
>>> I'm following the syntax in Documentation/trace/kprobetrace.txt by
>>> Masami Hiramatsu, and it is recognizing "string". But I'm getting
>>> these errors:
>>>
>>> # dmesg | tail -4
>>> [98021.813560] string type has no corresponding fetch method.
>>> [98021.813564] Parse error at argument[0]. (-22)
>>> [98705.956199] string type has no corresponding fetch method.
>>> [98705.956203] Parse error at argument[0]. (-22)
>>>
>>> Anyone seen this work? I'm checking the source... Thanks in advance,
>>
>>
>> Have you seen this:
>> https://lkml.org/lkml/2014/6/19/698
>>
>
> Thanks! (I'm trying to keep up with all the perf messages on lkml, but
> missed this.)
>
> So, perf can already do this?? And it's the same syntax (":string") as kprobes?
>
> I just tried it out (on 3.14.5):
>
> # perf probe 'getname filename:string'
> Added new event:
> [...]
> # perf record -e probe:getname -a sleep 5
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.234 MB perf.data (~10241 samples) ]
> # perf script
>             perf 13587 [000] 3576718.127120: probe:getname:
> (ffffffff811bbd20)
> filename_string="/home/bgregg-testtest/libexec/perf-core/sleep"
>             perf 13587 [000] 3576718.127142: probe:getname:
> (ffffffff811bbd20) filename_string="/usr/local/sbin/sleep"
>             perf 13587 [000] 3576718.127151: probe:getname:
> (ffffffff811bbd20) filename_string="/usr/local/bin/sleep"
>             perf 13587 [000] 3576718.127159: probe:getname:
> (ffffffff811bbd20) filename_string="/usr/sbin/sleep"
>             perf 13587 [000] 3576718.127170: probe:getname:
> (ffffffff811bbd20) filename_string="/usr/bin/sleep"
>             perf 13587 [000] 3576718.127180: probe:getname:
> (ffffffff811bbd20) filename_string="/sbin/sleep"
>             perf 13587 [000] 3576718.127189: probe:getname:
> (ffffffff811bbd20) filename_string="/bin/sleep"
>            sleep 13587 [000] 3576718.162025: probe:getname:
> (ffffffff811bbd20) filename_string="/etc/ld.so.cache"
>            sleep 13587 [000] 3576718.162057: probe:getname:
> (ffffffff811bbd20) filename_string="/lib/x86_64-linux-gnu/libc.so.6"
> [...]
>
> Wow.
>
> Ok, so that's one solution! :-)
>
> It does need debuginfo, which is a bit of a problem here (the Netflix
> cloud, where instances are created and destroyed quickly, so they are
> optimized to be small).
>
> I did try just using the return value, which does work without
> debuginfo, however, the :string modifier doesn't work. Eg, trying:
>
> # perf probe 'getname%return $retval:string'
> Added new event:
> Failed to write event: Invalid argument
>   Error: Failed to add events. (-1)
>
>  $retval really is a string (well, it's a struct filename *, where the
> first member is a char *, so close enough), so perhaps perf could
> enhanced to allow this, and I'd be able to trace strings without
> debuginfo.  (Unless there's another workaround.)
>
> So tools/perf/Documentation/perf-probe.txt does at least explain when
> :string won't work: "You can specify 'string' type only for the local
> variable or structure member which is an array of or a pointer to
> 'char' or 'unsigned char' type." I wonder if kprobes has this
> restriction as well.

Currently, "retval" and "reg" (and some other) fetch methods don't support string
type.  But I guess it can be easily worked around by using "deref" method.
Have you tried something like below (untested)?

  # perf probe 'getname%return +0($retval):string'

Hmm.. maybe below (as you mentioned it's a char * in struct filename *).

  # perf probe 'getname%return +0(+0($retval)):string'


Thanks,
Namhyung

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: kprobe string
  2014-07-17  7:24     ` Namhyung Kim
@ 2014-07-17  8:23       ` Brendan Gregg
  2014-07-21  1:20         ` Brendan Gregg
  0 siblings, 1 reply; 6+ messages in thread
From: Brendan Gregg @ 2014-07-17  8:23 UTC (permalink / raw)
  To: Namhyung Kim; +Cc: David Ahern, linux-perf-use.

G'Day Namhyung,

On Thu, Jul 17, 2014 at 12:24 AM, Namhyung Kim <namhyung@kernel.org> wrote:
> Hi Brendan,
>
> On Wed, 16 Jul 2014 23:29:10 -0700, Brendan Gregg wrote:
>> G'Day David,
>>
>> On Wed, Jul 16, 2014 at 9:41 PM, David Ahern <dsahern@gmail.com> wrote:
>>>
>>>
>>> On 07/16/2014 06:51 PM, Brendan Gregg wrote:
>>>>
>>>> G'Day,
>>>>
>>>> I'm not sure where else to ask this; I don't think this functionality
>>>> is in perf_events yet...
>>>>
>>>> kprobes is supposed to be able to handle string arguments, but I've
>>>> not been able to find a single working example. I'm trying (on 3.16):
>>>>
[...]
>> Ok, so that's one solution! :-)
>>
>> It does need debuginfo, which is a bit of a problem here (the Netflix
>> cloud, where instances are created and destroyed quickly, so they are
>> optimized to be small).
>>
>> I did try just using the return value, which does work without
>> debuginfo, however, the :string modifier doesn't work. Eg, trying:
>>
>> # perf probe 'getname%return $retval:string'
>> Added new event:
>> Failed to write event: Invalid argument
>>   Error: Failed to add events. (-1)
>>
>>  $retval really is a string (well, it's a struct filename *, where the
>> first member is a char *, so close enough), so perhaps perf could
>> enhanced to allow this, and I'd be able to trace strings without
>> debuginfo.  (Unless there's another workaround.)
>>
>> So tools/perf/Documentation/perf-probe.txt does at least explain when
>> :string won't work: "You can specify 'string' type only for the local
>> variable or structure member which is an array of or a pointer to
>> 'char' or 'unsigned char' type." I wonder if kprobes has this
>> restriction as well.
>
> Currently, "retval" and "reg" (and some other) fetch methods don't support string
> type.  But I guess it can be easily worked around by using "deref" method.
> Have you tried something like below (untested)?
>
>   # perf probe 'getname%return +0($retval):string'
>
> Hmm.. maybe below (as you mentioned it's a char * in struct filename *).
>
>   # perf probe 'getname%return +0(+0($retval)):string'
>

Excellent, thanks!

And this is also working syntax for kprobes!

Here's 3.2, when getname() returned a char *:

# echo 'r:myprobe getname +0($retval):string' > kprobe_events
# echo 1 > events/kprobes/enable
# tail trace
        postgres-2421  [000] 1507756.012578: myprobe:
(do_sys_open+0xc3/0x240 <- getname) arg1="global/pg_filenode.map"
        postgres-2421  [000] 1507756.012629: myprobe:
(do_sys_open+0xc3/0x240 <- getname) arg1="global/pg_internal.init"
        postgres-2421  [000] 1507756.013443: myprobe:
(do_sys_open+0xc3/0x240 <- getname) arg1="base/16384/PG_VERSION"
        postgres-2421  [000] 1507756.013507: myprobe:
(do_sys_open+0xc3/0x240 <- getname) arg1="base/16384/pg_filenode.map"
[...]
# echo 0 > events/kprobes/enable

And 3.16, where getname() is the struct filename *:

# echo 'r:myprobe getname +0(+0($retval)):string' > kprobe_events
# echo 1 > events/kprobes/myprobe/enable
# tail trace
       supervise-1684  [001] d... 6157863.184014: myprobe:
(user_path_parent+0x2e/0x80 <- getname) arg1="supervise/status.new"
       supervise-1684  [001] d... 6157863.184016: myprobe:
(user_path_parent+0x2e/0x80 <- getname) arg1="supervise/status"
       supervise-1694  [000] d... 6157863.184016: myprobe:
(user_path_parent+0x2e/0x80 <- getname) arg1="supervise/status"
       supervise-16964 [001] d... 6157863.184242: myprobe:
(SyS_execve+0x20/0x40 <- getname) arg1="./run"
[...]
# echo 0 > events/kprobes/myprobe/enable

Wow... So now I know perf can do this, and, I have working examples of
kprobes via ftrace if needed (I am trying to use perf first, due to
the way it buffers, error handling, and concurrent usage).

Thanks!

Brendan

-- 
http://www.brendangregg.com

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: kprobe string
  2014-07-17  8:23       ` Brendan Gregg
@ 2014-07-21  1:20         ` Brendan Gregg
  0 siblings, 0 replies; 6+ messages in thread
From: Brendan Gregg @ 2014-07-21  1:20 UTC (permalink / raw)
  To: Namhyung Kim; +Cc: David Ahern, linux-perf-use.

On Thu, Jul 17, 2014 at 1:23 AM, Brendan Gregg
<brendan.d.gregg@gmail.com> wrote:
> G'Day Namhyung,
[...]
> Wow... So now I know perf can do this, and, I have working examples of
> kprobes via ftrace if needed (I am trying to use perf first, due to
> the way it buffers, error handling, and concurrent usage).
>

To follow up: I ended up using kprobes, as I wanted to match on the
calling function (the "(xxx <- yyy)" part), which wasn't showing
symbols for perf_events, but was for ftrace.

The outcome is a (hacky) Linux port of my popular opensnoop tool,
based on Linux ftrace:

# ./opensnoop
Tracing open()s. Ctrl-C to end.
COMM             PID      FD FILE
opensnoop        5881    0x3
<...>            5900    0x3 /etc/ld.so.cache
opensnoop        5899    0x3 /etc/ld.so.cache
opensnoop        5899    0x3 /lib/x86_64-linux-gnu/libm.so.6
<...>            5900    0x3 /lib/x86_64-linux-gnu/libc.so.6
opensnoop        5899    0x3 /lib/x86_64-linux-gnu/libc.so.6
<...>            5900    0x3 /usr/lib/locale/locale-archive
<...>            5900    0x3 trace_pipe
ls               5915    0x3 /etc/ld.so.cache
ls               5915    0x3 /lib/x86_64-linux-gnu/libselinux.so.1
ls               5915    0x3 /lib/x86_64-linux-gnu/librt.so.1
ls               5915    0x3 /lib/x86_64-linux-gnu/libacl.so.1
ls               5915    0x3 /lib/x86_64-linux-gnu/libc.so.6
ls               5915    0x3 /lib/x86_64-linux-gnu/libdl.so.2
ls               5915    0x3 /lib/x86_64-linux-gnu/libpthread.so.0
ls               5915    0x3 /lib/x86_64-linux-gnu/libattr.so.1
ls               5915    0x3 /proc/filesystems
ls               5915    0x3 /usr/lib/locale/locale-archive
supervise        1690    0x9 supervise/status.new
supervise        1681    0x9 supervise/status.new
supervise        1690    0x9 supervise/status.new
supervise        1681    0x9 supervise/status.new
[...]

This works by caching the getname() result, and reading it for
sys_exit_open. It works in my large environment of 3.2 servers,
without debuginfo, since I'm just using $retval:string.

If debuginfo is available I can improve opensnoop a bit by using just
the syscall tracepoints, and tracing filenames using "filename:string"
on sys_enter_open, but this adds a lot of lag to wait for a debuginfo
install when wanting to debug an issue (and having debuginfo installed
on all our servers isn't really practical). I couldn't find entry
argument versions of $retval, eg, $arg1, $arg2, etc. Such a thing
would let me use the syscall open tracepoint with $arg2:string,
without debuginfo, so I could avoid dynamic tracing of getname(), and
therefore improving stability a bit. I was trying to hack this up
using %ax, %bx, etc, but I think that's also brittle...

opensnoop supports various options:

# ./opensnoop -h
USAGE: opensnoop [-htx] [-d secs] [-f file] [-p PID] [-n name]
                 -d seconds      # trace duration, and use buffers
                 -f file         # match filename (partials ok)
                 -n name         # process name to match on I/O issue
                 -p PID          # PID to match on I/O issue
                 -t              # include time (seconds)
                 -x              # only show failed opens
                 -h              # this usage message
  eg,
        opensnoop                # watch open()s live (unbuffered)
        opensnoop -d 1           # trace 1 sec (buffered)
        opensnoop -f conf        # trace filenames containing "conf"
        opensnoop -p 181         # trace I/O issued by PID 181 only

It's on github: https://github.com/brendangregg/perf-tools

Brendan

-- 
http://www.brendangregg.com

^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2014-07-21  1:20 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2014-07-17  0:51 kprobe string Brendan Gregg
2014-07-17  4:41 ` David Ahern
2014-07-17  6:29   ` Brendan Gregg
2014-07-17  7:24     ` Namhyung Kim
2014-07-17  8:23       ` Brendan Gregg
2014-07-21  1:20         ` Brendan Gregg

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).