用性能分析睡眠时间

我正在寻找一种方法来找出我的程序在哪里花费时间。 我读了perf教程,并试图描述那里描述的睡眠时间。 我写了最简单的程序来描述:

#include <unistd.h> int main() { sleep(10); return 0; } 

然后我用perf来执行它:

 $ sudo perf record -e sched:sched_stat_sleep -e sched:sched_switch -e sched:sched_process_exit -g -o ~/perf.data.raw ./a.out [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.013 MB /home/pablo/perf.data.raw (~578 samples) ] $ sudo perf inject -v -s -i ~/perf.data.raw -o ~/perf.data build id event received for [kernel.kallsyms]: d62870685909222126e7070d2bafdf029f7ed3b6 failed to write feature 2 $ sudo perf report --stdio --show-total-period -i ~/perf.data Error: The /home/pablo/perf.data file has no samples! 

有谁知道如何避免这些错误? 他们的意思是什么? failed to write feature 2不看起来太人性化…

更新:

 $ uname -a Linux debian 3.12-1-amd64 #1 SMP Debian 3.12.9-1 (2014-02-01) x86_64 GNU/Linux 

Solutions Collecting From Web of "用性能分析睡眠时间"

https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times的第二个perf命令有一个错误信&#x606F; – perf inject -s

 $ sudo perf inject -v -s -i ~/perf.data.raw -o ~/perf.data build id event received for [kernel.kallsyms]: d62870685909222126e7070d2bafdf029f7ed3b6 failed to write feature 2 

未能写功能2不看起来太人性化…

…但它被添加到性能使错误更加用户友好: http ://lwn.net/Articles/460520/“perf:使perf.data更自我描述性(v5)”由Stephane Eranian,9月22日2011:

 +static int do_write_feat(int fd, struct perf_header *h, int type, .... + pr_debug("failed to write feature %d\n", type); 

所有功能在这里列出http://lxr.free-electrons.com/source/tools/perf/util/header.h#L13

  15 HEADER_TRACING_DATA = 1, 16 HEADER_BUILD_ID, 

所以,听起来perf perf无法写入关于构建id的信息write_build_id()来自util / write_build_id()函数write_build_id()错误),如果我没有错的话。 有两种情况可能会导致错误:调用perf_session__read_build_ids()失败或者编写buildid表失败dsos__write_buildid_table (这不是我们的情况,因为没有“编写失败的buildid表”错误消息;请检查write_build_id

你可以检查,你有所有buildids需要的会议。 清除buildid缓存( rm -rf ~/.debug -rf〜 rm -rf ~/.debug )也是有用的,并且检查你的内核是否有最新版本的vmlinux,并在内核中启用了调试信息或者kallsyms。

更新:在评论帕维尔说,他的sched:sched_stat_sleep记录没有任何sched:sched_stat_sleep事件写入perf.data:

sudo perf record -e sched:sched_stat_sleep -e sched:sched_switch -e sched:sched_process_exit -g -o ~/perf.data.raw ./a.out

正如他在他的回答中解释的,他的默认debian内核的CONFIG_SCHEDSTATS选项被供应商的补丁禁用 。 从3.11开始, Redhat与发行版内核中的选项做了同样的事情,这在Redhat Bug 1013225 (Josh Boyer 2013-10-28,评论4)中有解释:

我们切换到启用,只有在调试版本前一阵子。 似乎完全关闭了最后的3.11.0版本,并一直保持关闭。 内部测试显示该选项对上下文切换具有不重要的性能影响。

我们可以在调试内核中再次打开它,但我不确定这是否值得。

Josh Poimboeuf 2013-11-04在评论8中说,性能影响是可以检测到的:

在我的测试中,我在各种CPU负载下做了很多上下文切换。 当CONFIG_SCHEDSTATS被使能时,我看到平均上下文切换速度下降了5-10%。 …性能打击似乎只发生在CFS内核(> = 2.6.23)上。 以前的O(1)调度程序似乎没有这个问题。

Fedora在2013年7月12日的非调试内核中禁用CONFIG_SCHEDSTAT “[内核]在非调试版本中禁用LATENCYTOP / SCHEDSTATS”。 由戴夫琼斯。 先禁用内核的选项:3.11.0-0.rc0.git6.4。

为了使用类似sched:sched_stat_*sched:sched_stat_waitsched:sched_stat_sleepsched:sched_stat_iowait )的任何perf软件跟踪事件,我们必须使用CONFIG_SCHEDSTATS选项重新编译内核,并替换没有这个的默认Debian,RedHat或Fedora内核选项。

谢谢帕维尔·达维多夫。

我终于找到了如何使它工作。 问题是默认的debian内核没有配置选项,那么perf需要能够监视睡眠时间。 看起来应该启用CONFIG_SCHEDSTATS来使内核收集调度程序统计信息。 这被告知有一些运行时间的开销。 另外我启用了CONFIG_SCHED_TRACER和一些锁定追踪选项,但我不确定他们是否在我的情况。 无论如何,没有统计数据在没有CONFIG_SCHEDSTATS调度程序中收集(参见kernel/sched/目录)。

此外,Brendan Gregg还写了一篇关于perf的非常好的文章 ,里面有很多有用的例子和一些内核选项,这些都是正确执行perf的工具。

更新:我在debian查了CONFIG_SCHEDSTATS的历史。 我已经检查了debian内核补丁和构建脚本回购:

 svn checkout svn://svn.debian.org/svn/kernel/dists/trunk/linux/debian 

然后在那里找到CONFIG_SCHEDSTATS选项

 $ grep -R CONFIG_SCHEDSTAT config/ config/config:# CONFIG_SCHEDSTATS is not set 

这个字符串在2008-03-14的提交10837中被添加到回购中,评论“debian / config:做完整的重组”。 另外,在这个和这个 (感谢osgx )错误报告中,告诉CONFIG_LATENCYTOP,CONFIG_SCHEDSTATS选项没有被启用,因为它们会影响内核性能。 所以,我认为这是从来没有在默认的debian内核打开。 尽管如此,我还没有找到关于调度程序统计信息的讨论。 如果我这样做,我会写在这里。

这适用于“openSUSE 13.1(x86_64)”框中的“perf version 3.11.1”。

这里是输出,如果你关心:

 # ======== # captured on: Sun Feb 16 09:49:38 2014 # hostname : ***************** # os release : 3.11.10-7-desktop # perf version : 3.11.1 # arch : x86_64 # nrcpus online : 8 # nrcpus avail : 8 # cpudesc : Intel(R) Core(TM) i7-3840QM CPU @ 2.80GHz # cpuid : GenuineIntel,6,58,9 # total memory : 32945368 kB # cmdline : /usr/bin/perf inject -v -s -i perf.data.raw -o perf.data # event : name = sched:sched_stat_sleep, type = 2, config = 0x48, config1 = 0x0, config2 = 0x # event : name = sched:sched_switch, type = 2, config = 0x51, config1 = 0x0, config2 = 0x0, e # event : name = sched:sched_process_exit, type = 2, config = 0x4e, config1 = 0x0, config2 = # HEADER_CPU_TOPOLOGY info available, use -I to display # HEADER_NUMA_TOPOLOGY info available, use -I to display # pmu mappings: cpu = 4, software = 1, tracepoint = 2, uncore_cbox_0 = 6, uncore_cbox_1 = 7, # ======== # # Samples: 0 of event 'sched:sched_stat_sleep' # Event count (approx.): 0 # # Overhead Period Command Shared Object Symbol # ........ ............ ....... ............. ...... # # Samples: 8 of event 'sched:sched_switch' # Event count (approx.): 80099958776 # # Overhead Period Command Shared Object Symbol # ........ ............ ....... ................. ................. # 100.00% 80099958776 bla [kernel.kallsyms] [k] thread_return | --- thread_return thread_return do_nanosleep hrtimer_nanosleep SyS_nanosleep system_call_fastpath 0x7fbc0dec6570 __GI___libc_nanosleep (nil) # Samples: 0 of event 'sched:sched_process_exit' # Event count (approx.): 0 # # Overhead Period Command Shared Object Symbol # ........ ............ ....... ............. ...... # # # (For a higher level overview, try: perf report --sort comm,dso) # }