19

我一直在寻找一种方法来找出我的程序花费时间的地方。我阅读了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
4

3 回答 3

12

来自https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times的第二个 perf 命令有一条错误消息-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 看起来不太人性化...

...但它被添加到 perf 以使错误更加用户友好：http ://lwn.net/Articles/460520/ Stephane Eranian 的“perf: make perf.data more self-descriptive (v5)”，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,

write_build_id()因此，如果我没记错的话，听起来 perf injection 无法写入有关构建 ID 的信息（来自 util/header.c 的函数错误）。有两种情况会导致错误：调用不成功perf_session__read_build_ids()或写入 buildid 表失败dsos__write_buildid_table（这不是我们的情况，因为没有“写入 buildid 表失败”错误消息；检查write_build_id）

您可以检查一下，您是否拥有会话所需的所有 buildid。rm -rf ~/.debug此外，清除您的buildid 缓存（

更新：在评论中，Pavel 说他的 pref 记录没有任何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。

为了使用名称如( , , ) 的任何perf软件跟踪点事件，我们必须在启用选项的情况下重新编译内核，并替换没有此选项的默认 Debian、RedHat 或 Fedora 内核。sched:sched_stat_*sched:sched_stat_waitsched:sched_stat_sleepsched:sched_stat_iowaitCONFIG_SCHEDSTATS

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

于 2014-02-18T17:05:16.143 回答
7

我终于找到了如何让它工作。问题是默认的 debian 内核是在没有一些配置选项的情况下构建的，perf 需要能够监控睡眠时间。看起来CONFIG_SCHEDSTATS应该启用以使内核收集调度程序统计信息。这被告知有一些运行时开销。我还启用CONFIG_SCHED_TRACER了一些锁定跟踪选项，但我不确定它们在我的情况下是否重要。无论如何，如果没有CONFIG_SCHEDSTATS（请参阅kernel/sched/内核源代码目录），调度程序中不会收集任何统计数据。

此外，还有一篇由 Brendan Gregg 撰写的关于 perf 的非常好的文章，其中包含许多有用的示例和一些使 perf 正常工作所需的内核选项。

更新：我在 debian 中检查了 CONFIG_SCHEDSTATS 的历史记录。我已经检查了 debian 内核补丁和构建脚本 repo：

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 年 3 月 14 日在提交 10837 中添加到 repo 中，并带有注释“debian/config: Do complete reorganization”。此外，在这个和这个（感谢osgx）错误报告中，它被告知 CONFIG_LATENCYTOP、CONFIG_SCHEDSTATS 选项未启用，因为它们会影响内核性能。所以，我认为它只是在默认的 debian 内核中从未打开过。不过，我还没有找到关于调度程序统计选项的讨论。如果我这样做，我会在这里写回。

于 2014-05-11T16:18:49.383 回答
1

这适用于“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)
#
}
于 2014-02-16T08:55:55.423 回答