Ideas to measure kernel function execution time using perf

Ideas to measure kernel function execution time using perf

[Qu Wenruo]

Hi,

Is there any method to measure kernel function execution time for 
specific functions using perf?

Current ftrace events can only record the timestamp when hitting the 
trace point (along with some other info).

I'm OK adding new ftrace events into kernel, but even after adding such 
ftrace events, is it possible to use perf to calculate the function 
execution time?

Any advice is welcomed.

Thanks,
Qu

Re: Ideas to measure kernel function execution time using perf

[Masami Hiramatsu]

On Tue, 19 Apr 2016 09:42:49 +0800
Qu Wenruo <quwenruo@cn.fujitsu.com> wrote:

> Hi,
> 
> Is there any method to measure kernel function execution time for 
> specific functions using perf?
> 
> Current ftrace events can only record the timestamp when hitting the 
> trace point (along with some other info).
> 
> I'm OK adding new ftrace events into kernel, but even after adding such 
> ftrace events, is it possible to use perf to calculate the function 
> execution time?

Would you mean "perf probe"? :)

Actually, kprobes on the function entry point (on x86) automatically
use ftrace and also you can get function parameters, e.g.

# perf probe -a 'YOUR_TARGET_FUNCTION $params'

And with using ftrace, you can get function duration and parameters,
for example,

# perf probe -a 'vfs_read $params'
Added new event:
  probe:vfs_read       (on vfs_read with $params)

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

	perf record -e probe:vfs_read -aR sleep 1

# cd /sys/kernel/debug/tracing/
# echo vfs_read > set_ftrace_filter
# echo 1 > events/probe/vfs_read/enable
# echo function_graph > current_tracer
# echo 0 > trace
# less trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 2)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff88036a959200 buf=0x7ffe460abb70 count=0x10 pos=0xffff880052d1bf20 */
 3)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff88024524b900 buf=0x7ffcdee7ec57 count=0x1 pos=0xffff88023942ff20 */
 2)   0.538 us    |  vfs_read();
 3)               |  vfs_read() {
 2)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff8803c24ba400 buf=0xd8efdc count=0x1ff0 pos=0xffff880052d1bf20 */
 2)   0.979 us    |  vfs_read();
...

Thanks,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: Ideas to measure kernel function execution time using perf

[Qu Wenruo]

Masami Hiramatsu wrote on 2016/04/20 08:37 +0900:
> On Tue, 19 Apr 2016 09:42:49 +0800
> Qu Wenruo <quwenruo@cn.fujitsu.com> wrote:
>
>> Hi,
>>
>> Is there any method to measure kernel function execution time for
>> specific functions using perf?
>>
>> Current ftrace events can only record the timestamp when hitting the
>> trace point (along with some other info).
>>
>> I'm OK adding new ftrace events into kernel, but even after adding such
>> ftrace events, is it possible to use perf to calculate the function
>> execution time?
>
> Would you mean "perf probe"? :)
>
> Actually, kprobes on the function entry point (on x86) automatically
> use ftrace and also you can get function parameters, e.g.
>
> # perf probe -a 'YOUR_TARGET_FUNCTION $params'
>
> And with using ftrace, you can get function duration and parameters,
> for example,
>
> # perf probe -a 'vfs_read $params'
> Added new event:
>    probe:vfs_read       (on vfs_read with $params)
>
> You can now use it in all perf tools, such as:
>
> 	perf record -e probe:vfs_read -aR sleep 1
>
> # cd /sys/kernel/debug/tracing/
> # echo vfs_read > set_ftrace_filter
> # echo 1 > events/probe/vfs_read/enable
> # echo function_graph > current_tracer
> # echo 0 > trace
> # less trace
> # tracer: function_graph
> #
> # CPU  DURATION                  FUNCTION CALLS
> # |     |   |                     |   |   |   |
>   2)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff88036a959200 buf=0x7ffe460abb70 count=0x10 pos=0xffff880052d1bf20 */
>   3)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff88024524b900 buf=0x7ffcdee7ec57 count=0x1 pos=0xffff88023942ff20 */
>   2)   0.538 us    |  vfs_read();
>   3)               |  vfs_read() {
>   2)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff8803c24ba400 buf=0xd8efdc count=0x1ff0 pos=0xffff880052d1bf20 */
>   2)   0.979 us    |  vfs_read();
> ...
>
> Thanks,
>
Wow, that's cool.

Thanks for the info, I think it would be good enough for my use case.

Thanks,
Qu

Re: Ideas to measure kernel function execution time using perf

[Arnaldo Carvalho de Melo]

Em Wed, Apr 20, 2016 at 08:37:57AM +0900, Masami Hiramatsu escreveu:
> On Tue, 19 Apr 2016 09:42:49 +0800
> Qu Wenruo <quwenruo@cn.fujitsu.com> wrote:
> > Is there any method to measure kernel function execution time for 
> > specific functions using perf?
> > 
> > Current ftrace events can only record the timestamp when hitting the 
> > trace point (along with some other info).
> > 
> > I'm OK adding new ftrace events into kernel, but even after adding such 
> > ftrace events, is it possible to use perf to calculate the function 
> > execution time?
 
> Would you mean "perf probe"? :)
 
> Actually, kprobes on the function entry point (on x86) automatically
> use ftrace and also you can get function parameters, e.g.
 
> # perf probe -a 'YOUR_TARGET_FUNCTION $params'
 
> And with using ftrace, you can get function duration and parameters,
> for example,
 
> # perf probe -a 'vfs_read $params'
> Added new event:
>   probe:vfs_read       (on vfs_read with $params)
 
> You can now use it in all perf tools, such as:
 
> 	perf record -e probe:vfs_read -aR sleep 1

Humm, so this will automagically make function_graph hook in the
function exit, so that it can take the second timestamp to do the
measurement?

I.e. sortof this:

[root@jouet ~]# perf probe -a 'vfs_read_entry=vfs_read $params' 'vfs_read_exit=vfs_read%return'
Added new events:
  probe:vfs_read_entry (on vfs_read with $params)
  probe:vfs_read_exit  (on vfs_read%return)

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

	perf record -e probe:vfs_read_exit -aR sleep 1

[root@jouet ~]# perf trace -e read --ev probe:vfs_read* cat /etc/passwd > /dev/null
     0.005 ( 0.005 ms): cat/1167 read(fd: 3, buf: 0x7ffe9d8b63c0, count: 832                           ) ...
     0.005 (         ): probe:vfs_read_entry:(ffffffff8123c450) file=0xffff880161f79600 buf=0x7ffe9d8b63c0 count=0x340 pos=0xffff880109047ef0)
     0.008 (         ): probe:vfs_read_exit:(ffffffff8123c450 <- ffffffff8123d9c5))
     0.009 ( 0.009 ms): cat/1167  ... [continued]: read()) = 832
     0.348 ( 0.003 ms): cat/1167 read(fd: 3, buf: 0x7f33d6d08000, count: 131072                        ) ...
     0.348 (         ): probe:vfs_read_entry:(ffffffff8123c450) file=0xffff8802053ac400 buf=0x7f33d6d08000 count=0x20000 pos=0xffff880109047ef0)
     0.355 (         ): probe:vfs_read_exit:(ffffffff8123c450 <- ffffffff8123d9c5))
     0.356 ( 0.011 ms): cat/1167  ... [continued]: read()) = 2729
     0.361 ( 0.002 ms): cat/1167 read(fd: 3, buf: 0x7f33d6d08000, count: 131072                        ) ...
     0.361 (         ): probe:vfs_read_entry:(ffffffff8123c450) file=0xffff8802053ac400 buf=0x7f33d6d08000 count=0x20000 pos=0xffff880109047ef0)
     0.362 (         ): probe:vfs_read_exit:(ffffffff8123c450 <- ffffffff8123d9c5))
     0.364 ( 0.004 ms): cat/1167  ... [continued]: read()) = 0
[root@jouet ~]# 

But doing the combination of the pairs of vfs_read_{entry,exit} like is done in
'perf trace' for syscalls, i.e. for sys_{enter,exit}_SYSCALL_NAME?

- Arnaldo
 
> # cd /sys/kernel/debug/tracing/
> # echo vfs_read > set_ftrace_filter
> # echo 1 > events/probe/vfs_read/enable
> # echo function_graph > current_tracer
> # echo 0 > trace
> # less trace
> # tracer: function_graph
> #
> # CPU  DURATION                  FUNCTION CALLS
> # |     |   |                     |   |   |   |
>  2)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff88036a959200 buf=0x7ffe460abb70 count=0x10 pos=0xffff880052d1bf20 */
>  3)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff88024524b900 buf=0x7ffcdee7ec57 count=0x1 pos=0xffff88023942ff20 */
>  2)   0.538 us    |  vfs_read();
>  3)               |  vfs_read() {
>  2)               |  /* vfs_read: (vfs_read+0x0/0x130) file=0xffff8803c24ba400 buf=0xd8efdc count=0x1ff0 pos=0xffff880052d1bf20 */
>  2)   0.979 us    |  vfs_read();
> ...
> 
> Thanks,
> 
> -- 
> Masami Hiramatsu <mhiramat@kernel.org>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Ideas to measure kernel function execution time using perf

[Andi Kleen]

Qu Wenruo <quwenruo@cn.fujitsu.com> writes:

> Hi,
>
> Is there any method to measure kernel function execution time for
> specific functions using perf?

You can use processor trace on newer Intel CPUs (especially
Skylake) for this.

-Andi

-- 
ak@linux.intel.com -- Speaking for myself only