分析睡眠时间与PERF [英] Profiling sleep times with perf

问题描述

我一直在寻找一种方式来找出我的程序花费的时间。我阅读 PERF教程并尝试，因为它是有描述来分析睡眠时间。我写的最简单可行的方案来分析：

 的#include＆LT;＆unistd.h中GT;
诠释主（）{
  睡眠（10）;
  返回0;
}
 

然后我PERF执行它：

  $ sudo的PERF记录-e章附表：sched_stat_sleep -e章附表：sched_switch -e章附表：sched_process_exit -g -o〜/ perf.data.raw ./a.out
[PERF记录：醒来1次写入数据]
[PERF记录：捕获并写了0.013 MB /home/pablo/perf.data.raw（〜578样本）
$ sudo的PERF注入-v -s -i〜/ perf.data.raw -o〜/ perf.data
建立[kernel.kallsyms]收到ID事件：d62870685909222126e7070d2bafdf029f7ed3b6
无法写入功能2
$ sudo的PERF报告--stdio  - 显示，总周期-i〜/ perf.data
错误：
该/home/pablo/perf.data文件没有样品！
 

是否有人知道如何避免这些错误？他们的意思是什么？ 未能写入功能2 看起来并不友好...

更新：

  $的uname -a
Linux的Debian的3.12-1-amd64的＃1 SMP的Debian 3.12.9-1（2014年2月1日）的x86_64 GNU / Linux的
 

解决方案

有从你的第二个PERF命令从<一个一个错误信息href=\"https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times\">https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times - PERF注射-S

  $ sudo的PERF注入-v -s -i〜/ perf.data.raw -o〜/ perf.data
建立[kernel.kallsyms]收到ID事件：d62870685909222126e7070d2bafdf029f7ed3b6
无法写入功能2
 

  

未能写入功能2看起来并不友好...

...但它加入到逆足造成的错误更加人性化： http://lwn.net/Articles/460520 / PERF：让perf.data更自我描述（V5）由斯特凡Eranian，2011年9月22日：

  +静态INT do_write_feat（INT FD，结构perf_header * H，int型的，...
+ pr_debug（无法写入功能％d个\\ N型）;
 

所有的功能都在这里<上市href=\"http://lxr.free-electrons.com/source/tools/perf/util/header.h#L13\">http://lxr.free-electrons.com/source/tools/perf/util/header.h#L13

  15 HEADER_TRACING_DATA = 1，
 16 HEADER_BUILD_ID，
 

所以，这听起来像PERF注入无法写有关建立IDS（从功能误差 write_build_id（）从UTIL / header.c）如果我没有错。有两种情况可能导致错误：不成功的调用 perf_session__read_build_ids（）或书面buildid表失败 dsos__write_buildid_table （这不是我们的情况下，因为没有失败写buildid表的错误信息;检查 write_build_id ）

您可以检查一下，你有没有需要的会话的所有buildids。此外，它可以清除您buildid缓存（ RM -rf〜/的.debug ），并检查是否有最多最新的vmlinux与调试信息或kallsyms启用有用在你的内核。

更新：的意见帕维尔说，他的preF记录没有任何章附表：写入perf.data sched_stat_sleep 事件：

须藤PERF记录-e章附表：sched_stat_sleep -e章附表：sched_switch -e章附表：sched_process_exit -g -o〜/ perf.data.raw ./a.out

他解释说在他的回答，他的默认的Debian内核具有 CONFIG_SCHEDSTATS 禁用与供应商的补丁选项。 RedHat的确实以来3.11版本的内核选项同样的事情，这是在红帽错​​误解释1013225 （乔什·博耶2013年10月28日，评论4）：

  

我们切换到实现只有在调试版本前一阵子。看来，与最终的3.11.0版本完全关闭，因为一直保持关闭。内部测试显示选项有上下文切换一个不平凡的性能影响。

  
  

我们可以在调试内核再次打开这一点，但我不知道这是值得的。

乔希Poimboeuf 2013年11月4日在评论8说，对性能的影响检测：

  

在我的测试中我做了很多方面的各种CPU负载下转换。我看到的平均上下文切换速度〜5-10％的跌幅已启用CONFIG_SCHEDSTATS时。 ...只打了性能似乎对后CFS内核发生（> = 2.6.23）。在previous O（1）调度似乎没有这个问题。

在非调试内核

禁用的Fedora在CONFIG_SCHEDSTAT 2013年7月12日[内核]禁用LATENCYTOP / SCHEDSTATS非调试版本。 通过戴夫·琼斯。首先内核禁用选项：3.11.0-0.rc0.git6.4

在为了使用名称的任何 PERF 软件跟踪点的事件，比如章附表：sched_stat _ * （章附表：sched_stat_wait ，章附表：sched_stat_sleep ，章附表：sched_stat_iowait ），我们必须重新编译 CONFIG_SCHEDSTATS 选项内核中启用的更换而没有此选项默认的Debian，红帽或Fedora内核。

感谢你，帕维尔·达维多夫。

I was looking for a way to find out where my program spends time. I read the perf tutorial and tried to profile sleep times as it is described there. I wrote the simplest possible program to profile:

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

then I executed it with 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!

Does anybody know how to avoid these errors? What do they mean? failed to write feature 2 doesn't look too user-friendly...

Update:

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

解决方案

There is a error message from your second perf command from https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times - 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

failed to write feature 2 doesn't look too user-friendly...

... but it was added to perf to made errors more user-friendly: http://lwn.net/Articles/460520/ "perf: make perf.data more self-descriptive (v5)" by Stephane Eranian , 22 Sep 2011:

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

All features are listed here http://lxr.free-electrons.com/source/tools/perf/util/header.h#L13

 15         HEADER_TRACING_DATA     = 1,
 16         HEADER_BUILD_ID,

So, it sounds like perf inject was not able to write information about build ids (error from function write_build_id() from util/header.c) if I'm not wrong. There are two cases which can lead to error: unsuccessful call to perf_session__read_build_ids() or failing in writing buildid table dsos__write_buildid_table (this is not our case because there is no "failed to write buildid table" error message; check write_build_id)

You may check, do you have all buildids needed for the session. Also it may be useful to clear your buildid cache (rm -rf ~/.debug), and check that you have up-to-date vmlinux with debugging info or kallsyms enabled in your kernel.

UPDATE: in comments Pavel says that his pref record had no any sched:sched_stat_sleep events written to 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

As he explains in his answer, his default debian kernel have CONFIG_SCHEDSTATS option disabled with vendor's patch. The redhat did the same thing with the option in release kernels since 3.11, and this is explained in Redhat Bug 1013225 (Josh Boyer 2013-10-28, comment 4):

We switched to enabling that only on debug builds a while ago. It seems that was turned off entirely with the final 3.11.0 build and has remained off since. Internal testing shows the option has a non-trivial performance impact for context switches.

We can turn this on in debug kernels again, but I'm not sure it's worthwhile.

Josh Poimboeuf 2013-11-04 in comment 8 says that performance impact is detectable:

In my tests I did a lot of context switches under various CPU loads. I saw a ~5-10% drop in average context switch speed when CONFIG_SCHEDSTATS was enabled. ...The performance hit only seemed to happen on post-CFS kernels (>= 2.6.23). The previous O(1) scheduler didn't seem to have this issue.

Fedora disabled CONFIG_SCHEDSTAT in non-debug kernels at 12 July 2013 "[kernel] Disable LATENCYTOP/SCHEDSTATS in non-debug builds." by Dave Jones. First kernel with disabled option: 3.11.0-0.rc0.git6.4.

In order to use any perf software tracepoint event with name like sched:sched_stat_* (sched:sched_stat_wait, sched:sched_stat_sleep, sched:sched_stat_iowait) we must recompile kernel with CONFIG_SCHEDSTATS option enabled and replace default Debian, RedHat or Fedora kernels which have no this option.

Thank you, Pavel Davydov.

这篇关于分析睡眠时间与PERF的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！