From mboxrd@z Thu Jan 1 00:00:00 1970 From: Qu Wenruo Subject: Re: Ideas to measure kernel function execution time using perf Date: Wed, 20 Apr 2016 08:52:27 +0800 Message-ID: <5716D2CB.3060300@cn.fujitsu.com> References: <57158D19.7070307@cn.fujitsu.com> <20160420083757.cba5cdd3038c7d82391b3b4c@kernel.org> Mime-Version: 1.0 Content-Type: text/plain; charset="utf-8"; format=flowed Content-Transfer-Encoding: 7bit Return-path: Received: from cn.fujitsu.com ([59.151.112.132]:49839 "EHLO heian.cn.fujitsu.com" rhost-flags-OK-FAIL-OK-FAIL) by vger.kernel.org with ESMTP id S1751937AbcDTAwg (ORCPT ); Tue, 19 Apr 2016 20:52:36 -0400 In-Reply-To: <20160420083757.cba5cdd3038c7d82391b3b4c@kernel.org> Sender: linux-perf-users-owner@vger.kernel.org List-ID: To: Masami Hiramatsu Cc: linux-perf-users@vger.kernel.org Masami Hiramatsu wrote on 2016/04/20 08:37 +0900: > On Tue, 19 Apr 2016 09:42:49 +0800 > Qu Wenruo 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