使用perf分析睡眠時間

Question

我正在尋找一種方法來查明我的程序花費了多少時間。我讀了perf tutorial並試圖描述那裏描述的睡眠時間。我寫了一個最簡單的程序來分析：

#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 

Answer 1

目前從第二PERF命令從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...

...但它加入to perf使錯誤更加用戶友好：http://lwn.net/Articles/460520/「perf：使perf.data更具自描述性（v5）」by Stephane Eranian，2011年9月22日：

+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注入未能如果將信息寫入有關（從UTIL/header.c從功能write_build_id()錯誤）建立IDS我沒錯。有兩種情況可以導致錯誤：perf_session__read_build_ids()不成功的電話或書面buildid表dsos__write_buildid_table失敗（因爲沒有「失敗寫buildid表」的錯誤信息，這不是我們的情況;檢查write_build_id）

您可能檢查一下，你是否擁有會話所需的所有buildids。此外，清除buildid緩存（rm -rf ~/.debug）可能會很有用，並檢查您是否擁有內核中啓用了調試信息或kallsyms的最新vmlinux。

UPDATE：在評論帕維爾說，他PREF紀錄曾寫信給perf.data沒有任何sched:sched_stat_sleep事件：

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

正如他在his answer解釋說，他的默認的Debian內核有CONFIG_SCHEDSTATS選項禁用與供應商的補丁。自3以來，redhat在發佈內核中採用了相同的選擇。11，並且這在Redhat Bug 1013225說明（書博耶2013年10月28日，註釋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.

約什Poimboeuf 2013年11月4日在評論8說，對性能的影響是可檢測的：

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禁用CONFIG_SCHEDSTAT在2013 7月12日"[kernel] Disable LATENCYTOP/SCHEDSTATS in non-debug builds."戴維·瓊斯。第一個禁用的內核選項：3.11.0-0.rc0.git6.4。

爲了使用任何perf軟件跟蹤點事件與名稱類似sched:sched_stat_*（sched:sched_stat_wait，sched:sched_stat_sleep，sched:sched_stat_iowait）我們必須重新編譯內核CONFIG_SCHEDSTATS選項啓用和替換不具有此選項是默認Debian，紅帽或Fedora內核。

謝謝你，帕維爾·達維多夫。

Answer 2

這對我的作品的 「PERF版本3.11.1」 上 「的openSUSE 13.1（x86_64的）」 複選框。

這裏是輸出，如果你不在意：

# ======== 
# 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) 
# 
} 

Answer 3

我終於找到了如何使它發揮作用。問題在於，默認的debian內核是在沒有某些配置選項的情況下構建的，該perf需要能夠監視睡眠時間。看起來應該啓用CONFIG_SCHEDSTATS以使內核收集調度程序統計信息。這被告知有一些運行時間的開銷。另外我啓用了CONFIG_SCHED_TRACER和一些鎖定追蹤選項，但我不確定它們是否與我的情況有關。無論如何，在沒有CONFIG_SCHEDSTATS（參見內核源代碼目錄kernel/sched/）的調度程序中不收集統計數據。

此外，還有Brendan Gregg編寫的非常有用的示例和一些內核選項，以使perf性能正常工作。

更新：我在debian中檢查了CONFIG_SCHEDSTATS的歷史。我已經簽出debian的內核補丁和構建腳本回購：

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

然後發現有

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

此字符串添加到回購CONFIG_SCHEDSTATS選項在提交10837，上2008-03-14 ，並評論「debian/config：完成重組」。此外，在this和this（感謝osgx）錯誤報告被告知CONFIG_LATENCYTOP，CONFIG_SCHEDSTATS選項未啓用，因爲它們會影響內核更流暢。所以，我認爲它從來沒有在默認的debian內核中開啓。儘管如此，我還沒有找到關於調度程序統計信息選項的討論。如果我這樣做，我會在這裏寫回。