python perf_如何使用Perf和Python分析系统
python perf 现代计算机的性能和容量不断提高。 如果不能很好地利用增加的容量，则无关紧要。 以下是对“ curt”背后动机和工作的描述，curt是Linux系统的一种新工具，用于使用perf命令的Python脚本功能按进程，任务和CPU测量和分解系统利用率。我有幸在Texas Linux Fest 2018上提出了这个话题，在这里我对细节进行了更深入的介绍，包括指向更多信息的链接...
python perf
现代计算机的性能和容量不断提高。 如果不能很好地利用增加的容量，则无关紧要。 以下是对“ curt”背后动机和工作的描述，curt是Linux系统的一种新工具，用于使用perf命令的Python脚本功能按进程，任务和CPU测量和分解系统利用率。
我有幸在Texas Linux Fest 2018上提出了这个话题，在这里我对细节进行了更深入的介绍，包括指向更多信息的链接，并扩大了我的演讲范围。
系统利用率
在讨论计算时，让我们从一些断言开始：
- 每个计算系统都无所事事地很快。
- 创建计算系统来做事。
- 计算系统在做某事时比做某事不做时要好。
现代计算系统具有许多执行流：
- 通常，从字面上将较小的系统连接在一起会创建非常大的系统。 在IBM，这些较小的系统有时称为CEC（Central Electronics Complexs的缩写，发音为“ keks”）。
- 每个系统中有多个用于处理器模块的插槽。
- 有时每个插槽有多个芯片（以双芯片模块DCM或多芯片模块MCM的形式）。
- 每个芯片有多个内核。
- 每个内核有多个线程。
总而言之，单个计算系统中可能有数千个执行线程。
单个执行流（CPU线程）的利用率是线程安排和运行任务的时间百分比。 （请注意，我没有说“做有用的工作。”创建一种测量有用工作的工具留给读者练习。）通过扩展， 系统利用率是系统所有执行流拥有的总时间百分比计划和运行任务。 类似地，可以针对单个任务定义利用率。 任务利用率是在任何CPU线程上主动运行所花费的任务生命周期的百分比。 通过扩展， 过程利用率是其任务的集体利用率。利用率测量工具
有一些工具可以测量系统利用率： uptime ， vmstat ， mpstat ， nmon等。有一些工具可以测量单个进程的利用率： time 。 没有多少工具可以衡量系统范围内每个进程和每个任务的利用率。 一个这样的命令被curt AIX上。 根据IBM知识中心的说法：“ curt命令将AIX跟踪文件作为输入，并生成许多与处理器（CPU）利用率和进程/线程/ pthread活动有关的统计信息。”
AIX curt命令报告应用程序处理（用户时间），系统调用（系统时间），系统管理程序调用，内核线程，中断和空闲时间的系统范围，每个处理器，每个进程和每个任务的统计信息。
对于Linux系统，使用类似命令似乎是一个很好的模型。
利用率数据
在开始创建用于利用率分析的任何工具之前，重要的是要知道需要什么数据。 由于利用率与任务是否正在运行直接相关，因此需要相关的计划事件：使任务何时运行以及何时暂停？ 跟踪任务在哪个CPU上运行非常重要，因此隐式迁移需要迁移事件。 也有某些系统调用会强制进行显式迁移。 创建和删除任务显然很重要。 由于我们想了解用户时间，系统时间，系统管理程序时间和中断时间，因此需要显示这些任务状态之间转换的事件。
Linux内核包含所有这些事件的“跟踪点”。 它可以启用跟踪直接在内核的那些事件debugfs文件系统，通常安装在/sys/kernel/debug ，在tracing目录（ /sys/kernel/debug/tracing ）。
记录跟踪数据的一种简单方法是使用Linux perf命令。
性能命令
perf是一个非常强大的用户空间命令，用于跟踪或计数硬件和软件事件。
软件事件是在内核中预定义的，可以在用户空间代码中预定义，并且可以在内核或用户空间代码中动态创建（作为“探针”）。
perf可以做的不仅仅是跟踪和计数。
性能统计
perf的stat子命令将运行一个命令，计算一些通常被发现有趣的事件，并生成一个简单的报告：
Performance counter stats for './load 100000':
90537.006424 task-clock:u (msec) # 1.000 CPUs utilized
0 context-switches:u # 0.000 K/sec
0 cpu-migrations:u # 0.000 K/sec
915 page-faults:u # 0.010 K/sec
386,836,206,133 cycles:u # 4.273 GHz (66.67%)
3,488,523,420 stalled-cycles-frontend:u # 0.90% frontend cycles idle (50.00%)
287,222,191,827 stalled-cycles-backend:u # 74.25% backend cycles idle (50.00%)
291,102,378,513 instructions:u # 0.75 insn per cycle
# 0.99 stalled cycles per insn (66.67%)
43,730,320,236 branches:u # 483.010 M/sec (50.00%)
822,030,340 branch-misses:u # 1.88% of all branches (50.00%)
90.539972837 seconds time elapsed
性能记录，性能报告和性能注释
为了进行更有趣的分析，还可以使用perf命令来记录事件以及事件发生时与任务状态相关的信息：
$ perf record ./some-command
[ perf record: Woken up 55 times to write data ]
[ perf record: Captured and wrote 13.973 MB perf.data (366158 samples) ]
$ perf report --stdio --show-nr-samples --percent-limit 4
# Samples: 366K of event 'cycles:u'
# Event count (approx.): 388851358382
#
# Overhead Samples Command Shared Object Symbol
# ........ ............ ....... ................. ................................................
#
62.31% 228162 load load [.] main
19.29% 70607 load load [.] sum_add
18.33% 67117 load load [.] sum_sub
此示例显示了一个程序，其运行时间的约60％花费在函数main而子函数sum_sub和sum_add分别sum_sub约20％的sum_add 。 请注意， perf record使用的默认事件是“周期”。 后面的示例将显示如何将perf record与其他事件一起使用。
perf report可以通过源代码行进一步报告运行时统计信息（如果使用-g标志执行编译以产生调试信息）：
$ perf report --stdio --show-nr-samples --percent-limit 4 --sort=srcline
# Samples: 366K of event 'cycles:u'
# Event count (approx.): 388851358382
#
# Overhead Samples Source:Line
# ........ ............ ...................................
#
19.40% 71031 load.c:58
16.16% 59168 load.c:18
15.11% 55319 load.c:14
13.30% 48690 load.c:66
13.23% 48434 load.c:70
4.58% 16767 load.c:62
4.01% 14677 load.c:56
此外， perf annotate可以显示程序的每个指令的统计信息：
$ perf annotate --stdio
Percent | Source code & Disassembly of load for cycles:u (70607 samples)
------------------------------------------------------------------------------
: 0000000010000774 <sum_add>:
: int sum_add(int sum, int value) {
12.60 : 10000774: std r31,-8(r1)
0.02 : 10000778: stdu r1,-64(r1)
0.00 : 1000077c: mr r31,r1
41.90 : 10000780: mr r10,r3
0.00 : 10000784: mr r9,r4
0.05 : 10000788: stw r10,32(r31)
23.78 : 1000078c: stw r9,36(r31)
: return (sum + value);
0.76 : 10000790: lwz r10,32(r31)
0.00 : 10000794: lwz r9,36(r31)
14.75 : 10000798: add r9,r10,r9
0.00 : 1000079c: extsw r9,r9
: }
6.09 : 100007a0: mr r3,r9
0.02 : 100007a4: addi r1,r31,64
0.03 : 100007a8: ld r31,-8(r1)
0.00 : 100007ac: blr
（ 注意：此代码未优化。 ）
性能顶部
类似于top命令（以固定的更新间隔显示）使用最多CPU时间的进程， perf top将显示系统上所有进程中使用CPU时间最多的功能 。
性能列表
到目前为止，这些示例都使用了默认事件，即运行周期。 有成百上千种不同类型的事件。 perf list将全部显示。 以下只是一些示例：
$ perf list
instructions [Hardware event]
context-switches OR cs [Software event]
L1-icache-loads [Hardware cache event]
mem_access OR cpu/mem_access/ [Kernel PMU event]
cache:
pm_data_from_l2
[The processor's data cache was reloaded from local core's L2 due to a demand load]
floating point:
pm_fxu_busy
[fxu0 busy and fxu1 busy]
frontend:
pm_br_mpred_cmpl
[Number of Branch Mispredicts]
memory:
pm_data_from_dmem
[The processor's data cache was reloaded from another chip's memory on the same Node or Group (Distant) due to a demand load]
pm_data_from_lmem
[The processor's data cache was reloaded from the local chip's Memory due to a demand load]
rNNN [Raw hardware event descriptor]
raw_syscalls:sys_enter [Tracepoint event]
syscalls:sys_enter_chmod [Tracepoint event]
sdt_libpthread:pthread_create [SDT event]
标记为Hardware event ， Hardware cache event ， Kernel PMU event以及类别（如cache ， floating point ， frontend和memory ）下的大多数（如果不是全部）事件是由硬件计算的硬件事件，每次在特定时间触发达到计数。 触发后，将使用相关任务的当前状态进入内核跟踪缓冲区。 Raw hardware event代码是Raw hardware event的字母数字编码。 当硬件比内核新，并且用户需要启用该硬件的新事件时，通常需要这些。 用户很少，甚至永远不需要使用原始事件代码。
标有Tracepoint event嵌入在内核中。 当内核执行该部分代码时，将触发这些事件。 内核支持的每个系统调用都有“ syscalls”事件。 每个系统调用都会触发raw_syscalls事件。 由于对活动跟踪的事件数量有限制，因此当需要跟踪大量系统调用时， raw_syscalls事件可能更实用。
标有SDT event适用于软件定义的跟踪点（SDT）。 这些可以嵌入到应用程序或库代码中，并根据需要启用。 启用后，它们的行为就像其他事件一样：当执行该部分代码时（通过在系统上跟踪的任何任务），将在内核跟踪缓冲区中创建具有相关任务当前状态的条目。 这是一项非常强大的功能，可以证明非常有用。
perf buildid-cache和perf探针
启用SDT很容易。 首先，使perf知道某个库的SDT：
$ perf buildid-cache -v --add /lib/powerpc64le-linux-gnu/libpthread.so.0
$ perf list | grep libpthread
[…]
sdt_libpthread:pthread_create [SDT event]
[…]
然后，将SDT定义转换为可用的跟踪点：
$ /usr/bin/sudo perf probe sdt_libpthread:pthread_create
Added new event:
sdt_libpthread:pthread_create (on %pthread_create in /lib/powerpc64le-linux-gnu/libpthread-2.27.so)
You can now use it in all perf tools, such as:
perf record -e sdt_libpthread:pthread_create -aR sleep 1
$ perf record -a -e sdt_libpthread:pthread_create ./test
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.199 MB perf.data (9 samples) ]
请注意，可以将应用程序或库中的任何位置设为跟踪点。 要在应用程序中查找可以–funcs为跟踪点的函数， –funcs perf probe与–funcs ：
$ perf probe –x ./load --funcs
[…]
main
sum_add
sum_sub
要将./load应用程序的main函数用作跟踪点：
/usr/bin/sudo perf probe –x ./load main
Added new event:
probe_load:main (on main in /home/pc/projects/load-2.1pc/load)
You can now use it in all perf tools, such as:
perf record –e probe_load:main –aR sleep 1
$ perf list | grep load:main
probe_load:main [Tracepoint event]
$ perf record –e probe_load:main ./load
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.024 MB perf.data (1 samples) ]
性能脚本
继续前面的示例， perf script可用于遍历perf.data文件并输出每个记录的内容：
$ perf script
Load 16356 [004] 80526.760310: probe_load:main: (4006a2)
处理性能跟踪数据
前面的讨论和实施例表明perf可以收集系统利用率分析所需的数据。 但是，如何处理该数据以产生期望的结果？
绩效eBPF
带有perf相对较新的新兴技术称为eBPF 。 BPF是Berkeley Packet Filter的首字母缩写，它是一种类似C的语言，最初用于内核中的网络数据包过滤也就不足为奇了。 eBPF是扩展BPF（扩展BPF）的缩写，扩展BPF是类似的但更健壮的基于BPF的类似于C的语言。
perf最新版本可用于将已编译的eBPF代码合并到内核中，以出于多种目的安全且智能地处理事件，但有一些限制。
该功能非常强大，对于与事件相关的数据和统计信息的实时，连续更新非常有用。
但是，随着这种功能的出现，当前发行版的Linux发行版中对支持的支持有所不同。 这有点复杂（或者换句话说，我还没有弄清楚）。 它也仅用于在线使用； 没有离线功能。 由于这些原因，在此不再赘述。
性能数据文件
perf record产生一个perf.data文件。 该文件是结构化的二进制文件，没有特别好的文档说明，没有用于访问的编程接口，并且不清楚存在哪些兼容性保证。 由于这些原因，我选择不直接使用perf.data文件。
性能脚本
上面的最后一个示例显示了如何使用perf script遍历perf.data文件并发出有关每个记录的基本信息。 对于处理文件和跟踪状态更改以及计算系统利用率分析所需的统计信息而言，这是一个合适的模型。
perf script具有几种操作模式，包括perf随附的一些更高级别的脚本，这些脚本基于perf.data文件中的跟踪数据生成统计信息。
$ perf script -l
List of available trace scripts:
rw-by-pid system-wide r/w activity
rwtop [interval] system-wide r/w top
wakeup-latency system-wide min/max/avg wakeup latency
failed-syscalls [comm] system-wide failed syscalls
rw-by-file <comm> r/w activity for a program, by file
failed-syscalls-by-pid [comm] system-wide failed syscalls, by pid
intel-pt-events print Intel PT Power Events and PTWRITE
syscall-counts-by-pid [comm] system-wide syscall counts, by pid
export-to-sqlite [database name] [columns] [calls] export perf data to a sqlite3 database
futex-contention futext contention measurement
sctop [comm] [interval] syscall top
event_analyzing_sample analyze all perf samples
net_dropmonitor display a table of dropped frames
compaction-times [-h] [-u] [-p|-pv] [-t | [-m] [-fs] [-ms]] [pid|pid-range|comm-regex] display time taken by mm compaction
export-to-postgresql [database name] [columns] [calls] export perf data to a postgresql database
stackcollapse produce callgraphs in short form for scripting use
netdev-times [tx] [rx] [dev=] [debug] display a process of packet and processing time
syscall-counts [comm] system-wide syscall counts
sched-migration sched migration overview
$ perf script failed-syscalls-by-pid /bin/ls
syscall errors:
comm [pid] count
------------------------------ ----------
ls [18683]
syscall: access
err = ENOENT 1
syscall: statfs
err = ENOENT 1
syscall: ioctl
err = ENOTTY 3
这些脚本是什么样的？ 让我们找出答案。
$ locate failed-syscalls-by-pid
/usr/libexec/perf-core/scripts/python/failed-syscalls-by-pid.py
[…]
$ rpm –qf /usr/libexec/perf-core/scripts/python/failed-syscalls-by-pid.py
perf-4.14.0-46.el7a.x86_64
$ $ ls /usr/libexec/perf-core/scripts
perl python
$ perf script -s lang
Scripting language extensions (used in perf script -s [spec:]script.[spec]):
Perl [Perl]
pl [Perl]
Python [Python]
py [Python]
因此，这些脚本与perf一起提供，并且Python和Perl都是受支持的语言。
请注意，对于本文的全部内容，我将仅引用Python。
性能脚本
这些脚本如何工作？ 以下是/usr/libexec/perf-core/scripts/python/failed-syscalls-by-pid.py重要摘录：
def raw_syscalls__sys_exit
( event_name
, context
, common_cpu
,
common_secs
, common_nsecs
, common_pid
, common_comm
,
common_callchain
,
id
, ret
) :
[ …
]
if ret
<
0 :
[ …
]
syscalls
[ common_comm
]
[ common_pid
]
[
id
]
[ ret
] +
=
1
函数raw_syscalls__sys_exit具有用于关联事件的所有数据的参数。 该函数的其余部分仅增加与命令，进程ID和系统调用关联的计数器。 其余的代码没有做那么多。 大多数复杂性都在事件处理例程的函数签名中。
幸运的是， perf可以很容易地为各种跟踪点事件处理功能找出正确的签名。
性能脚本–gen-script
对于raw_syscalls事件，我们可以生成仅包含这些事件的跟踪：
$ perf list | grep raw_syscalls
raw_syscalls:sys_enter [Tracepoint event]
raw_syscalls:sys_exit [Tracepoint event]
$ perf record -e 'raw_syscalls:*' /bin/ls >/dev/null
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.025 MB perf.data (176 samples) ]
然后，我们可以让perf生成一个脚本，该脚本包含perf.data文件中事件的事件处理函数的示例实现：
$ perf script --gen-script python
generated Python script: perf-script.py
我们在脚本中找到了什么？
def raw_syscalls__sys_exit
( event_name
, context
, common_cpu
,
common_secs
, common_nsecs
, common_pid
, common_comm
,
common_callchain
,
id
, ret
) :
[ …
]
def raw_syscalls__sys_enter
( event_name
, context
, common_cpu
,
common_secs
, common_nsecs
, common_pid
, common_comm
,
common_callchain
,
id
, args
) :
这两个事件处理函数均使用其签名指定。 真好！
请注意，此脚本与perf script –s ：
$ perf script -s ./perf-script.py
in trace_begin
raw_syscalls__sys_exit 7 94571.445908134 21117 ls id=0, ret=0
raw_syscalls__sys_enter 7 94571.445942946 21117 ls id=45, args= ?bc ?
[…]
现在，我们有了一个模板，可以在此模板上编写Python脚本来解析感兴趣的事件，以报告系统利用率。
性能脚本
perf script –gen-script生成的Python脚本不能直接执行。 它们必须由perf调用：
$ perf script –s ./perf-script.py
这到底是怎么回事？
- 首先，
perf开始。script子命令的-s选项指示将使用外部脚本。 -
perf建立一个Python运行时环境。 -
perf加载指定的脚本。 -
perf运行脚本。 该脚本可以执行常规初始化，甚至可以处理命令行参数，尽管传递参数有些尴尬，在perf和脚本的参数之间需要使用--分隔符：$ perf script -s ./perf-script.py -- --script-arg1 [...] -
perf处理跟踪文件的每个记录，并在脚本中调用适当的事件处理函数。 这些事件处理功能可以执行所需的任何操作。
使用率
似乎perf脚本具有足够的功能来提供可行的解决方案。 生成系统利用率统计信息需要什么样的信息？
- 任务创建（
fork，pthread_create） - 任务终止（
exit） - 任务替换（
exec） - 任务迁移（显式或隐式）以及当前CPU
- 任务调度
- 系统调用
- 系统管理程序调用
- 中断
了解任务在各种系统调用，处理中断或显式调用虚拟机管理程序上花费的时间是有帮助的。 这些时间类别中的每一个都可以视为任务的“状态”，并且需要跟踪从一种状态过渡到另一种状态的方法：
该图最重要的一点是每个状态转换都有事件。
- 任务创建：
clone系统调用 - 任务终止：
sched: sched_process_exit - 任务替换：
sched: sched_process_exec - 任务迁移：
sched_setaffinity系统调用（显式），sched: sched_migrate_task（隐式） - 任务计划：
sched: sched_switch - 系统调用：
raw_syscalls: sys_enter，raw_syscalls: sys_exit - 系统管理程序调用：（特定于POWER）
powerpc: hcall_entry，powerpc: hcall_exit - 中断：
irq:irq_handler_entry，irq:irq_handler_exit
Linux的curt命令
perf提供了合适的基础结构，可用来捕获必要的数据以用于系统利用。 Linux内核中有足够的事件集可用于跟踪。 Python脚本功能允许使用强大而灵活的方式来处理跟踪数据。 是时候编写工具了。
高级设计
在处理每个事件时，必须更新受影响任务的相关状态：
- 新任务？ 创建和初始化数据结构以跟踪任务的状态
- 命令
- 进程ID
- 任务ID
- 迁移计数（0）
- 当前CPU
- 要为此任务使用新的CPU？ 为特定于CPU的数据创建和初始化数据结构
- 用户时间（0）
- 系统时间（0）
- 管理程序时间（0）
- 中断时间（0）
- 空闲时间（0）
- 这项任务有新交易吗？ 创建和初始化特定于交易的数据的数据结构
- 经过时间（0）
- 数（0）
- 最小（maxint），最大（0）
- 现有任务？
- 累积前一状态的时间
- 交易结束？ 累积交易时间，调整最小值，最大值
- 设定新状态
- 保存当前时间（输入当前时间）
- 移民？ 增量迁移计数
高级示例
对于raw_syscalls:sys_enter事件：
- 如果以前没有看到此任务，请分配并初始化一个新的任务数据结构
- 如果CPU是用于此任务的新CPU，请分配并初始化新的CPU数据结构
- 如果此任务是新的系统调用，请分配并初始化新的调用数据结构
- 在任务数据结构中：
- 累计自当前状态（“用户”）的存储桶中的最后一个状态更改以来的时间
- 设置新状态（“系统”）
- 将当前时间戳记保存为新状态的该时间段的开始
边缘情况
sys_exit作为任务的第一个事件
如果任务跟踪中的第一个事件是raw_syscalls:sys_exit ：
- 没有匹配的
raw_syscalls:sys_enter来确定此系统调用的开始时间。 - 自跟踪开始以来的累积时间全部用在了系统调用中，需要将其添加到对该系统调用的所有调用中所花费的总经过时间中。
- 该系统调用的经过时间未知。
- 在此系统调用的平均，最小或最大统计信息中考虑此经过的时间是不准确的。
在这种情况下，该工具为系统调用中花费的时间创建了一个单独的存储区，称为“待处理”，而该时间无法在平均值，最小值或最大值中考虑。
所有事务事件（系统调用，系统管理程序调用和中断）都需要一个“挂起”的存储桶。
sys_enter作为任务的最后一个事件
同样，如果任务跟踪中的最后一个事件是raw_syscalls:sys_enter ：
- 没有匹配的
raw_syscalls:sys_exit来确定此系统调用的结束时间。 - 从系统调用开始到跟踪结束的累积时间全部用在了系统调用中，需要将其累加到对该系统调用的所有调用中所花费的总经过时间中。
- 该系统调用的经过时间未知。
- 在此系统调用的平均，最小或最大统计信息中考虑此经过的时间是不准确的。
该经过的时间也累积在“待处理”存储区中。
所有事务事件（系统调用，系统管理程序调用和中断）都需要一个“挂起”的存储桶。
由于只能在跟踪的末尾发现此条件，因此在该工具中需要执行最后的“总结”步骤，在该步骤中，所有已知任务的统计信息将根据其最终状态完成。
不确定状态
非常繁忙的任务（或简短的跟踪）可能永远不会看到任务的事件，可以从中确定任务的状态。 例如，如果仅看到任务的sched:sched_switch或sched:sched_task_migrate事件，则无法确定该任务的状态。 但是，已知该任务存在并正在运行。
由于无法确定实际状态，因此任务的运行时会累积在一个单独的存储桶中，该存储桶可任意称为“忙-未知”。 为了完整起见，此时间还将显示在最终报告中。
隐形任务
对于非常繁忙的任务（或较短的跟踪），有可能在收集跟踪的整个过程中都有一个任务在积极运行，但是该任务没有任何事件出现在跟踪中。 它从未迁移，暂停或被迫等待。
该工具无法识别此类任务，这些任务也不会出现在报告中。
curt.py Python类
任务
- 每个任务一个
- 包含所有特定于任务的数据（命令，进程ID，状态，CPU，CPU数据结构列表[请参见下文]，迁移计数，按调用数据结构的列表[请参见下文]）
- 维持任务状态
呼叫
- 每个唯一事务，每个任务一个（例如，一个用于“打开”系统调用，一个用于“关闭”系统调用，一个用于IRQ 27，等等）
- 保留特定于呼叫的数据（例如，开始时间戳记，计数，经过的时间，最小，最大）
- 根据需要分配（延迟分配）
- 存储在任务中的Python字典中，该字典由调用的唯一标识符（例如，系统调用代码，IRQ编号等）索引
中央处理器
- 每个CPU上观察到一个正在运行的任务
- 保留每个CPU的任务数据（例如，用户时间，系统时间，系统管理程序调用时间，中断时间）
- 根据需要分配（延迟分配）
- 存储在任务中的Python字典中，该字典由CPU号索引
curt.py事件处理示例
如前所述， perf script将遍历跟踪中的所有事件，并为每个事件调用适当的事件处理函数。
鉴于上面的高级示例，首次尝试sys_exit的事件处理功能可能是：
tasks
=
{
}
def raw_syscalls__sys_enter
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, args
) :
# convert the multiple timestamp values into a single value
timestamp
= nsecs
( common_secs
, common_nsecs
)
# find this task's data structure
try :
task
= tasks
[ common_pid
]
except :
# new task!
task
= Task
(
)
# save the command string
task.
comm
= common_comm
# save the new task in the global list (dictionary) of tasks
tasks
[ common_pid
]
= task
if common_cpu
not
in task.
cpus :
# new CPU!
task.
cpu
= common_cpu
task.
cpus
[ common_cpu
]
= CPU
(
)
# compute time spent in the previous state ('user')
delta
= timestamp – task.
timestamp
# accumulate 'user' time for this task/CPU
task.
cpus
[ task.
cpu
] .
user +
= delta
if
id
not
in task.
syscalls :
# new system call for this task!
task.
syscalls
[
id
]
= Call
(
)
# change task's state
task.
mode
=
'sys'
# save the timestamp for the last event (this one) for this task
task.
timestamp
= timestamp
def raw_syscalls__sys_exit
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, ret
) :
# convert the multiple timestamp values into a single value
timestamp
= nsecs
( common_secs
, common_nsecs
)
# get the task data structure
task
= tasks
[ common_pid
]
# compute elapsed time for this system call
delta
= task.
timestamp - timestamp
# accumulate time for this task/system call
task.
syscalls
[
id
] .
elapsed +
= delta
# increment the tally for this task/system call
task.
syscalls
[
id
] .
count +
=
1
# adjust statistics
if delta
< task.
syscalls
[
id
] .
min :
task.
syscalls
[
id
] .
min
= delta
if delta
> task.
syscalls
[
id
] .
max :
task.
syscalls
[
id
] .
max
= delta
# accumulate time for this task's state on this CPU
task.
cpus
[ common_cpu
] .
system +
= delta
# change task's state
task.
mode
=
'user'
# save the timestamp for the last event (this one) for this task
task.
timestamp
= timestamp
处理边缘情况
以下是一些可能的必须处理的极端情况。
Sys_exit作为第一个事件
由于可以在任意时间启动系统范围的跟踪，因此任务的第一个事件当然可能是raw_syscalls:sys_exit 。 这需要增加从该事件处理函数新任务，发现同样的代码raw_syscalls:sys_enter的处理程序raw_syscalls:sys_exit 。 这个：
# get the task data structure
task
= tasks
[ common_pid
]
变成这个：
# find this task's data structure
try :
task
= tasks
[ common_pid
]
except :
# new task!
task
= Task
(
)
# save the command string
task.
comm
= common_comm
# save the new task in the global list (dictionary) of tasks
tasks
[ common_pid
]
= task
另一个问题是，由于没有用于开始系统调用的时间戳，因此无法正确累积此系统调用的数据。 从跟踪开始到此事件已被系统调用中的此任务花费的时间。 这次忽略不正确。 合并该时间以用于计算平均值，最小值或最大值也将是不准确的。 唯一合理的选择是将其分开累积，称为“等待”系统时间。 为了准确地计算该时间，必须知道跟踪的第一个事件的时间戳。 由于任何事件都可能是跟踪中的第一个事件，因此如果每个事件都是第一个事件，则必须有条件地保存其时间戳。 需要一个全局变量：
start_timestamp = 0
每个事件处理函数必须有条件地保存其时间戳：
# convert the multiple timestamp values into a single value
timestamp
= nsecs
( common_secs
, common_nsecs
)
If start_timestamp
=
0 :
start_timestamp
= timestamp
因此， raw_syscalls:sys_exit的事件处理函数变为：
def raw_syscalls__sys_exit
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, ret
) :
# convert the multiple timestamp values into a single value
timestamp
= nsecs
( common_secs
, common_nsecs
)
If start_timestamp
=
0 :
start_timestamp
= timestamp
# find this task's data structure
try :
task
= tasks
[ common_pid
]
# compute elapsed time for this system call
delta
= task.
timestamp - timestamp
# accumulate time for this task/system call
task.
syscalls
[
id
] .
elapsed +
= delta
# increment the tally for this task/system call
task.
syscalls
[
id
] .
count +
=
1
# adjust statistics
if delta
< task.
syscalls
[
id
] .
min :
task.
syscalls
[
id
] .
min
= delta
if delta
> task.
syscalls
[
id
] .
max :
task.
syscalls
[
id
] .
max
= delta
except :
# new task!
task
= Task
(
)
# save the command string
task.
comm
= common_comm
# save the new task in the global list (dictionary) of tasks
tasks
[ common_pid
]
= task
# compute elapsed time for this system call
delta
= start_timestamp - timestamp
# accumulate time for this task/system call
task.
syscalls
[
id
] .
pending +
= delta
# accumulate time for this task's state on this CPU
task.
cpus
[ common_cpu
] .
system +
= delta
# change task's state
task.
mode
=
'user'
# save the timestamp for the last event (this one) for this task
task.
timestamp
= timestamp
Sys_enter作为最后一个事件
与sys_exit作为任务的第一个事件类似的问题是，当sys_enter是任务的最后一个事件时。 为了完整起见，必须累积在系统调用中花费的时间，但不能准确地影响平均值，最小值或最大值。 此时间也将累积为单独的“挂起”状态。
为了准确地确定挂起的系统调用所花费的时间，从sys_entry到跟踪周期结束，需要跟踪文件中最终事件的时间戳。 不幸的是，在该事件已被处理之前，无法知道哪个事件是最后一个事件。 因此， 所有事件都必须将其各自的时间戳保存在全局变量中。
可能许多任务处于最后看到的事件是sys_enter 。 因此，在处理完最后一个事件之后，需要执行最后的“总结”步骤来完成这些任务的统计信息。 幸运的是，有一个trace_end函数，在处理完最后一个事件之后， perf会调用该函数。
最后，我们需要保存的id的系统调用在每一个 sys_enter 。
curr_timestamp
=
0
def raw_syscalls__sys_enter
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, args
) :
# convert the multiple timestamp values into a single value
curr_timestamp
= nsecs
( common_secs
, common_nsecs
)
[ …
]
task.
syscall
=
id
[ …
]
def trace_end
(
) :
for tid
in tasks.
keys
(
) :
task
= tasks
[ tid
]
# if this task ended while executing a system call
if task.
mode
==
'sys' :
# compute the time from the entry to the system call to the end of the trace period
delta
= curr_timestamp - task.
timestamp
# accumulate the elapsed time for this system call
task.
syscalls
[ task.
syscall
] .
pending +
= delta
# accumulate the system time for this task/CPU
task.
cpus
[ task.
cpu
] .
sys +
= delta
移居
任务迁移是指将一个CPU上运行的任务移动到另一个CPU上。 这可以通过以下任一方式发生：
- 显式请求（例如，对
sched_setaffinity的调用），或 - 由内核暗含（例如，负载平衡或使正在脱机的CPU腾空）
检测到时：
- 任务的迁移计数应增加
- 前一个CPU的统计信息应更新
- 如果用于任务的CPU是新的，则可能需要更新和初始化新的CPU数据结构
- 任务的当前CPU设置为新CPU
为了获得准确的统计信息，必须尽快检测到任务迁移。 第一种情况是显式请求，发生在系统调用内，可以在该系统调用的sys_exit事件中检测到。 第二种情况有其自己的事件sched:sched_migrate_task ，因此它将需要一个新的事件处理函数。
def raw_syscalls__sys_exit
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, ret
) :
# convert the multiple timestamp values into a single value
timestamp
= nsecs
( common_secs
, common_nsecs
)
If start_timestamp
=
0 :
start_timestamp
= timestamp
# find this task's data structure
try :
task
= tasks
[ common_pid
]
# compute elapsed time for this system call
delta
= task.
timestamp - timestamp
# accumulate time for this task/system call
task.
syscalls
[
id
] .
elapsed +
= delta
# increment the tally for this task/system call
task.
syscalls
[
id
] .
count +
=
1
# adjust statistics
if delta
< task.
syscalls
[
id
] .
min :
task.
syscalls
[
id
] .
min
= delta
if delta
> task.
syscalls
[
id
] .
max :
task.
syscalls
[
id
] .
max
= delta
except :
# new task!
task
= Task
(
)
# save the command string
task.
comm
= common_comm
# save the new task in the global list (dictionary) of tasks
tasks
[ common_pid
]
= task
task.
cpu
= common_cpu
# compute elapsed time for this system call
delta
= start_timestamp - timestamp
# accumulate time for this task/system call
task.
syscalls
[
id
] .
pending +
= delta
If common_cpu
!= task.
cpu :
task.
migrations +
=
1
# divide the time spent in this syscall in half...
delta /
=
2
# and give have to the previous CPU, below, and half to the new CPU, later
task.
cpus
[ task.
cpu
] .
system +
= delta
# accumulate time for this task's state on this CPU
task.
cpus
[ common_cpu
] .
system +
= delta
# change task's state
task.
mode
=
'user'
# save the timestamp for the last event (this one) for this task
task.
timestamp
= timestamp
def sched__sched_migrate_task
( event_name
, context
, common_cpu
,
common_secs
, common_nsecs
, common_pid
, common_comm
,
common_callchain
, comm
, pid
, prio
, orig_cpu
,
dest_cpu
, perf_sample_dict
) :
If start_timestamp
=
0 :
start_timestamp
= timestamp
# find this task's data structure
try :
task
= tasks
[ common_pid
]
except :
# new task!
task
= Task
(
)
# save the command string
task.
comm
= common_comm
# save the new task in the global list (dictionary) of tasks
tasks
[ common_pid
]
= task
task.
cpu
= common_cpu
If common_cpu
not
in task.
cpus :
task.
cpus
[ common_cpu
]
= CPU
(
)
task.
migrations +
=
1
任务创建
为了准确地收集任务的统计信息，必须知道创建任务的时间。 可以使用创建新进程的fork()或创建相同进程内的新任务的pthread_create()创建任务。 幸运的是，两者都通过clone系统调用得到体现，并通过sched:sched_process_fork事件得到明显体现。 任务的生存期从sched_process_fork事件开始。 出现的极端情况是新任务的第一个可能事件是：
- 新任务开始运行时使用
sched_switch。 在此事件发生之前，应将新任务视为空闲状态 -
sys_exit用于clone系统调用。 新任务的初始状态需要基于创建它的任务的状态，包括在clone系统调用中。
必须处理的一个极端情况是，如果尚不知道创建任务（父级），则必须创建并初始化该任务，并且认为自跟踪开始以来，该任务一直在积极运行。
def sched__sched_process_fork
( event_name
, context
, common_cpu
,
common_secs
, common_nsecs
, common_pid
, common_comm
,
common_callchain
, parent_comm
, parent_pid
, child_comm
, child_pid
) :
global start_timestamp
, curr_timestamp
curr_timestamp
=
self .
timestamp
if
( start_timestamp
==
0
) :
start_timestamp
= curr_timestamp
# find this task's data structure
try :
task
= tasks
[ common_pid
]
except :
# new task!
task
= Task
(
)
# save the command string
task.
comm
= common_comm
# save the new task in the global list (dictionary) of tasks
tasks
[ common_pid
]
= task
try :
parent
= tasks
[
self .
parent_tid
]
except :
# need to create parent task here!
parent
= Task
( start_timestamp
,
self .
command
,
'sys'
,
self .
pid
)
parent.
sched_stat
=
True
# ?
parent.
cpu
=
self .
cpu
parent.
cpus
[ parent.
cpu
]
= CPU
(
)
tasks
[
self .
parent_tid
]
= parent
task.
resume_mode
= parent.
mode
task.
syscall
= parent.
syscall
task.
syscalls
[ task.
syscall
]
= Call
(
)
task.
syscalls
[ task.
syscall
] .
timestamp
=
self .
timestamp
任务出口
同样，对于完整而准确的任务统计，必须知道任务何时终止。 发生了一个事件： sched:sched_process_exit 。 这一步很容易处理，因为其工作只是关闭统计信息并适当地设置模式，因此任何跟踪结束处理都不会认为任务仍处于活动状态：
def sched__sched_process_exit_old
( event_name
, context
, common_cpu
,
common_secs
, common_nsecs
, common_pid
, common_comm
,
common_callchain
, comm
, pid
, prio
) :
global start_timestamp
, curr_timestamp
curr_timestamp
=
self .
timestamp
if
( start_timestamp
==
0
) :
start_timestamp
= curr_timestamp
# find this task's data structure
try :
task
= tasks
[ common_pid
]
except :
# new task!
task
= Task
(
)
# save the command string
task.
comm
= common_comm
task.
timestamp
= curr_timestamp
# save the new task in the global list (dictionary) of tasks
tasks
[ common_pid
]
= task
delta
= timestamp – task.
timestamp
task.
sys +
= delta
task.
mode
=
'exit'
输出量
下面是curt显示的报告的示例，将其略微重新格式化以适合更窄的页面宽度，并删除了空闲时间分类数据（这使输出非常宽），并且简洁起见。 看到两个进程1497和2857。进程1497有两个任务1497和1523。每个任务都有每个CPU的摘要和系统范围（“ ALL” CPU）的摘要。 每个任务的数据后跟该任务的系统调用数据（如果有），系统管理程序调用数据（如果有）和中断数据（如果有）。 在每个流程的各自任务之后是每个流程的摘要。 进程2857具有任务2857-0，该任务是exec（）系统调用替换进程映像之前的前一个任务映像。 毕竟，所有过程都是系统范围内的摘要。
1497:
-- [ task] command cpu user sys irq hv busy idle | util% moves
[ 1497] X 2 0.076354 0.019563 0.000000 0.000000 0.000000 15.818719 | 0.6%
[ 1497] X ALL 0.076354 0.019563 0.000000 0.000000 0.000000 15.818719 | 0.6% 0
-- ( ID)name count elapsed pending average minimum maximum
( 0)read 2 0.004699 0.000000 0.002350 0.002130 0.002569
(232)epoll_wait 1 9.968375 5.865208 9.968375 9.968375 9.968375
-- [ task] command cpu user sys irq hv busy idle | util% moves
[ 1523] InputThread 1 0.052598 0.037073 0.000000 0.000000 0.000000 15.824965 | 0.6%
[ 1523] InputThread ALL 0.052598 0.037073 0.000000 0.000000 0.000000 15.824965 | 0.6% 0
-- ( ID)name count elapsed pending average minimum maximum
( 0)read 14 0.011773 0.000000 0.000841 0.000509 0.002185
( 1)write 2 0.010763 0.000000 0.005381 0.004974 0.005789
(232)epoll_wait 1 9.966649 5.872853 9.966649 9.966649 9.966649
-- [ task] command cpu user sys irq hv busy idle | util% moves
[ ALL] ALL 0.128952 0.056636 0.000000 0.000000 0.000000 31.643684 | 0.6% 0
2857:
-- [ task] command cpu user sys irq hv busy idle | util% moves
[ 2857] execs.sh 1 0.257617 0.249685 0.000000 0.000000 0.000000 0.266200 | 65.6%
[ 2857] execs.sh 2 0.000000 0.023951 0.000000 0.000000 0.000000 0.005728 | 80.7%
[ 2857] execs.sh 5 0.313509 0.062271 0.000000 0.000000 0.000000 0.344279 | 52.2%
[ 2857] execs.sh 6 0.136623 0.128883 0.000000 0.000000 0.000000 0.533263 | 33.2%
[ 2857] execs.sh 7 0.527347 0.194014 0.000000 0.000000 0.000000 0.990625 | 42.1%
[ 2857] execs.sh ALL 1.235096 0.658804 0.000000 0.000000 0.000000 2.140095 | 46.9% 4
-- ( ID)name count elapsed pending average minimum maximum
( 9)mmap 15 0.059388 0.000000 0.003959 0.001704 0.017919
( 14)rt_sigprocmask 12 0.006391 0.000000 0.000533 0.000431 0.000711
( 2)open 9 2.253509 0.000000 0.250390 0.008589 0.511953
( 3)close 9 0.017771 0.000000 0.001975 0.000681 0.005245
( 5)fstat 9 0.007911 0.000000 0.000879 0.000683 0.001182
( 10)mprotect 8 0.052198 0.000000 0.006525 0.003913 0.018073
( 13)rt_sigaction 8 0.004281 0.000000 0.000535 0.000458 0.000751
( 0)read 7 0.197772 0.000000 0.028253 0.000790 0.191028
( 12)brk 5 0.003766 0.000000 0.000753 0.000425 0.001618
( 8)lseek 3 0.001766 0.000000 0.000589 0.000469 0.000818
-- [ task] command cpu user sys irq hv busy idle | util% moves
[2857-0] perf 6 0.053925 0.191898 0.000000 0.000000 0.000000 0.827263 | 22.9%
[2857-0] perf 7 0.000000 0.656423 0.000000 0.000000 0.000000 0.484107 | 57.6%
[2857-0] perf ALL 0.053925 0.848321 0.000000 0.000000 0.000000 1.311370 | 40.8% 1
-- ( ID)name count elapsed pending average minimum maximum
( 0)read 0 0.000000 0.167845 -- -- --
( 59)execve 0 0.000000 0.000000 -- -- --
ALL:
-- [ task] command cpu user sys irq hv busy idle | util% moves
[ ALL] ALL 10.790803 29.633170 0.160165 0.000000 0.137747 54.449823 | 7.4% 50
-- ( ID)name count elapsed pending average minimum maximum
( 1)write 2896 1.623985 0.000000 0.004014 0.002364 0.041399
(102)getuid 2081 3.523861 0.000000 0.001693 0.000488 0.025157
(142)sched_setparam 691 7.222906 32.012841 0.024925 0.002024 0.662975
( 13)rt_sigaction 383 0.235087 0.000000 0.000614 0.000434 0.014402
( 8)lseek 281 0.169157 0.000000 0.000602 0.000452 0.013404
( 0)read 133 2.782795 0.167845 0.020923 0.000509 1.864439
( 7)poll 96 8.583354 131.889895 0.193577 0.000626 4.596280
( 4)stat 93 7.036355 1.058719 0.183187 0.000981 3.661659
( 47)recvmsg 85 0.146644 0.000000 0.001725 0.000646 0.019067
( 3)close 79 0.171046 0.000000 0.002165 0.000428 0.020659
( 9)mmap 78 0.311233 0.000000 0.003990 0.001613 0.017919
(186)gettid 74 0.067315 0.000000 0.000910 0.000403 0.014075
( 2)open 71 3.081589 0.213059 0.184248 0.001921 0.937946
(202)futex 62 5.145112 164.286154 0.405566 0.000597 11.587437
-- ( ID)name count elapsed pending average minimum maximum
( 12)i8042 10 0.160165 0.000000 0.016016 0.010920 0.032805
Total Trace Time: 15.914636 ms
障碍与问题
以下是curt开发中遇到的一些问题。
乱序事件
更具挑战性的问题之一是发现perf.data文件中的事件可能不按时间顺序。 对于试图仔细监视状态转换的程序，这是一个严重的问题。 例如，跟踪可能包含以下事件序列，显示的顺序与它们在跟踪文件中的显示方式相同：
time 0000: sys_enter syscall1
time 0007: sys_enter syscall2
time 0006: sys_exit syscall1
time 0009: sys_exit syscall2
仅按照将它们呈现给各自事件处理功能的顺序（错误的时间顺序）盲目处理这些事件，将导致错误的统计信息（或更糟糕的是）。
处理混乱事件的最人性化方式包括：
- 通过更改性能
perf record工作方式，首先避免跟踪出现乱序事件 - 提供一种方法，可以通过增强性能
perf inject来对跟踪文件中的事件重新排序 - 修改性能
perf script工作方式，以按时间顺序将事件呈现给事件处理函数
但是，用户友好性不像简单明了，也不容易。 同样，以上都不在用户的控制范围内。
我选择为传入事件实现一个队列，该队列的深度应足以允许对所有事件进行正确的重新排序。 这需要对代码进行重大的重新设计，包括实现每个事件的类，并将每个事件类型的事件处理移到该事件的类中的方法中。
在重新设计的代码中，实际的事件处理程序的唯一工作是将事件中的相关数据保存到事件类的实例中，将其排队，然后处理队列中最重要的（时间最久的）事件：
def raw_syscalls__sys_enter
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, args
) :
event
= Event_sys_enter
( nsecs
( common_secs
, common_nsecs
)
, common_cpu
, common_pid
, common_comm
,
id
)
process_event
( event
)
简单的可重排序排队机制具有一个共同的功能：
events
=
[
]
n_events
=
0
def process_event
( event
) :
global events
, n_events
, curr_timestamp
i
= n_events
while i
>
0
and events
[ i-
1
] .
timestamp
> event.
timestamp :
i
= i-
1
events.
insert
( i
, event
)
if n_events
< params.
window :
n_events
= n_events+
1
else :
event
= events
[
0
]
# need to delete from events list now,
# because event.process() could reenter here
del events
[
0
]
if event.
timestamp
< curr_timestamp:
sys .
stderr .
write
(
"Error: OUT OF ORDER events detected. \n Try increasing the size of the look-ahead window with --window=<n> \n "
)
event.
process
(
)
请注意，队列的大小是可配置的，主要是为了提高性能并限制内存消耗。 当该队列大小不足以消除乱序事件时，该函数将报告。 值得考虑是否将这种情况视为灾难性失败并选择终止程序。
为每种事件类型实现一个类会导致一些重构方面的考虑，以便通用代码可以合并为一个基类：
class Event
(
object
) :
def
__init__
(
self
) :
self .
timestamp
=
0
self .
cpu
=
0
self .
tid
=
0
self .
command
=
'unknown'
self .
mode
=
'unknown'
self .
pid
=
0
def process
(
self
) :
global start_timestamp
try :
task
= tasks
[
self .
tid
]
if task.
pid
==
'unknown' :
tasks
[
self .
tid
] .
pid
=
self .
pid
except :
task
= Task
( start_timestamp
,
self .
command
,
self .
mode
,
self .
pid
)
tasks
[
self .
tid
]
= task
if
self .
cpu
not
in task.
cpus :
task.
cpus
[
self .
cpu
]
= CPU
(
)
if task.
cpu
==
'unknown' :
task.
cpu
=
self .
cpu
if
self .
cpu
!= task.
cpu :
task.
cpu
=
self .
cpu
task.
migrations +
=
1
return task
然后，将为每个事件类型类似地构造一个类：
class Event_sys_enter
( Event
) :
def
__init__
(
self
, timestamp
, cpu
, tid
, comm
,
id
, pid
) :
self .
timestamp
= timestamp
self .
cpu
= cpu
self .
tid
= tid
self .
command
= comm
self .
id
=
id
self .
pid
= pid
self .
mode
=
'busy-unknown'
def process
(
self
) :
global start_timestamp
, curr_timestamp
curr_timestamp
=
self .
timestamp
if
( start_timestamp
==
0
) :
start_timestamp
= curr_timestamp
task
=
super
( Event_sys_enter
,
self
) .
process
(
)
if task.
mode
==
'busy-unknown' :
task.
mode
=
'user'
for cpu
in task.
cpus :
task.
cpus
[ cpu
] .
user
= task.
cpus
[ cpu
] .
busy_unknown
task.
cpus
[ cpu
] .
busy_unknown
=
0
task.
syscall
=
self .
id
if
self .
id
not
in task.
syscalls :
task.
syscalls
[
self .
id
]
= Call
(
)
task.
syscalls
[
self .
id
] .
timestamp
= curr_timestamp
task.
change_mode
( curr_timestamp
,
'sys'
)
同样，上面的重构也很明显，将基于任务状态更改和状态更改本身更新相关统计信息的通用代码移到Task类的change_mode方法中。
跟踪开始时间戳
如上所述，对于依赖于经过时间的脚本，除了强制每个事件处理函数有条件地将其时间戳保存为跟踪开始时间戳外，应该有一种更简单的方法来获取跟踪中的第一个时间戳。
尴尬的调用
调用perf Python脚本（包括脚本参数）的语法有些尴尬：
$ perf script –s ./curt. py -- --window = 80
另外， perf Python脚本本身也不可执行，这很尴尬。
curt.py脚本可直接执行，并将调用perf ，后者又将调用该脚本。 实现有点混乱，但易于使用：
$ ./curt. py --window = 80
该脚本必须检测何时直接调用了它。 perf建立的Python环境是一个虚拟模块， perf Python脚本可从该虚拟模块导入：
try :
from perf_trace_context
import *
如果此导入失败，则直接调用脚本。 在这种情况下，脚本将exec perf ，将自身指定为要运行的脚本，并传递任何命令行参数：
except :
if
len
( params.
file_or_command
)
==
0 :
params.
file_or_command
=
[
"perf.data"
]
sys .
argv
=
[
'perf'
,
'script'
,
'-i'
] + params.
file_or_command +
[
'-s'
,
sys .
argv
[
0
]
]
sys .
argv .
append
(
'--'
)
sys .
argv +
=
[
'--window'
,
str
( params.
window
)
]
if params.
debug :
sys .
argv .
append
(
'--debug'
)
sys .
argv +
=
[
'--api'
,
str
( params.
api
)
]
if params.
debug :
print
sys .
argv
os .
execvp
(
"perf"
,
sys .
argv
)
sys .
exit
(
1
)
这样，该脚本不仅可以直接运行，还可以使用perf script命令运行。
需要同时进行事件注册
perf启用事件的方式可能会导致意外的跟踪数据。 例如，指定：
$ perf record –a –e raw_syscalls:sys_enter –e raw_syscalls:sys_exit ./command
将生成一个跟踪文件，该跟踪文件以单个任务的以下一系列事件（ perf命令本身）开头：
sys_enter
sys_enter
sys_enter
…
发生这种情况是因为perf将为系统上的每个CPU注册sys_enter事件（由于-a参数），然后它将为每个CPU注册sys_exit事件。 在后一种情况下，由于已经为每个CPU启用了sys_enter事件，因此该事件将显示在跟踪中。 但是由于sys_exit尚未每个CPU上启用直到调用返回之后， sys_exit调用不会在跟踪显示。 相反的问题发生在跟踪文件的末尾，跟踪中有一系列sys_exit事件，因为sys_enter事件已被禁用。
解决此问题的方法是对事件进行分组，但记录不充分：
$ perf record –e '{raw_syscalls:sys_enter,raw_syscalls:sys_exit}' ./command
使用此语法，可以同时启用sys_enter和sys_exit事件。
尴尬的录音步骤
计算任务的完整统计信息需要很多不同的事件。 这导致一个非常长而复杂的录制命令：
$ perf record -e '{raw_syscalls:*,sched:sched_switch,sched:sched_migrate_task,sched:sched_process_exec,sched:sched_process_fork,sched:sched_process_exit,sched:sched_stat_runtime,sched:sched_stat_wait,sched:sched_stat_sleep,sched:sched_stat_blocked,sched:sched_stat_iowait,powerpc:hcall_entry,powerpc:hcall_exit}' -a *command --args*
解决此问题的方法是使脚本本身可以调用perf来执行记录步骤。 记录完成后将进行进一步的增强，并报告该记录的统计信息：
if params.
record :
# [ed. Omitting here the list of events for brevity]
eventlist
=
'{' + eventlist +
'}'
# group the events
command
=
[
'perf'
,
'record'
,
'--quiet'
,
'--all-cpus'
,
'--event'
, eventlist
] + params.
file_or_command
if params.
debug :
print command
subprocess .
call
( command
)
记录和报告所需的命令语法为：
$ ./curt.py --record ./command
进程ID和性能API更改
通过perf脚本对进程ID进行比较灵活的处理。 上面请注意，用于生成的事件处理函数的公共参数之一称为common_pid 。 这不是进程ID，而是任务ID。 实际上，在许多当前的基于Linux的发行版中，无法从perf Python脚本中确定任务的进程ID。 对于想要计算流程统计信息的脚本，这带来了一个严重的问题。
幸运的是，在Linux内核v4.14中，为每个事件处理函数提供了一个附加参数perf_sample_dict可从中提取进程ID的字典：（ perf_sample_dict['sample']['pid'] ）。
不幸的是，当前的Linux发行版可能没有该版本的Linux内核。 如果编写脚本时期望该额外参数，则脚本将失败并报告错误：
TypeError: irq__irq_handler_exit_new() takes exactly 11 arguments (10 given)
理想情况下，可以使用一种自动发现是否传递了附加参数的方法，以允许脚本轻松地与新旧API一起运行，并在新API可用时利用新API。 不幸的是，这种方法并不容易理解。
由于使用新API确定流程范围的统计信息显然具有价值，因此curt提供了使用新API的命令行选项。 curt然后利用Python的惰性函数绑定在运行时调整要使用的API：
if params.
api
==
1 :
dummy_dict
=
{
}
dummy_dict
[
'sample'
]
=
{
}
dummy_dict
[
'sample'
]
[
'pid'
]
=
'unknown'
raw_syscalls__sys_enter
= raw_syscalls__sys_enter_old
[ …
]
else :
raw_syscalls__sys_enter
= raw_syscalls__sys_enter_new
[ …
]
对于每个事件，这需要两个功能：
def raw_syscalls__sys_enter_new
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, args
, perf_sample_dict
) :
event
= Event_sys_enter
( nsecs
( common_secs
, common_nsecs
)
, common_cpu
, common_pid
, common_comm
,
id
, perf_sample_dict
[
'sample'
]
[
'pid'
]
)
process_event
( event
)
def raw_syscalls__sys_enter_old
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, args
) :
global dummy_dict
raw_syscalls__sys_enter_new
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
,
id
, args
, dummy_dict
)
请注意，旧版API的事件处理函数将利用新版API的函数，传递一个静态定义的字典，该字典仅包含足够的数据，以便像perf_sample_dict['sample']['pid']进行访问（导致'unknown' ）。
在其他CPU上报告的事件
并非所有引用任务的事件都是从运行任务的CPU报告的。 这可能会导致人为地增加迁移计数和其他不正确的统计信息。 对于这些类型的事件（ sched_stat ），将忽略事件CPU。
显式迁移（无sched_migrate事件）
While there is conveniently an event for when the kernel decides to migrate a task from one CPU to another, there is no event for when the task requests a migration on its own. These are effected by system calls ( sched_setaffinity ), so the sys_exit event handler must compare the event CPU to the task's CPU, and if different, presume a migration has occurred. (This is described above, but repeated here in the "issues" section for completeness.)
Mapping system call IDs to names is architecture-specific
System calls are identified in events only as unique numeric identifiers. These identifiers are not readily interpreted by humans in the report. These numeric identifiers are not readily mapped to their mnemonics because they are architecture-specific, and new system calls can be added in newer kernels. Fortunately, perf provides a means to map system call numeric identifiers to system call names. A simple example follows:
from Util
import syscall_name
def raw_syscalls__sys_enter
( event_name
, context
, common_cpu
,
common_secs
, common_nsecs
, common_pid
, common_comm
,
common_callchain
,
id
, args
, perf_sample_dict
) :
print
"%s id=%d" %
( syscall_name
(
id
)
,
id
)
Unfortunately, using syscall_name introduces a dependency on the audit python bindings. This dependency is being removed in upstream versions of perf.
Mapping hypervisor call IDs to names is non-existent
Similar to system calls, hypervisor calls are also identified only with numeric identifiers. For IBM's POWER hypervisor, they are statically defined. Unfortunately, perf does not provide a means to map hypervisor call identifiers to mnemonics. curt includes a (hardcoded) function to do just that:
hcall_to_name
=
{
'0x4' :
'H_REMOVE'
,
'0x8' :
'H_ENTER'
,
'0xc' :
'H_READ'
,
'0x10' :
'H_CLEAR_MOD'
,
[ …
]
}
def hcall_name
( opcode
) :
try :
return hcall_to_name
[
hex
( opcode
)
]
except :
return
str
( opcode
)
Command strings as bytearrays
perf stores command names and string arguments in Python bytearrays. Unfortunately, printing bytearrays in Python prints every character in the bytearray—even if the string is null-terminated. 例如：
$ perf record –a –e 'sched:sched_switch' sleep 3
$ perf script –g Python
generated Python script: perf-script.py
$ perf script -s ./perf-script.py
in trace_begin
sched__sched_switch 3 664597.912692243 21223 perf prev_comm=perf^@-terminal-^@, prev_pid=21223, prev_prio=120, prev_state=, next_comm=migration/3^@^@^@^@^@, next_pid=23, next_prio=0
[…]
One solution is to truncate the length of these bytearrays based on null termination, as needed before printing:
def null
( ba
) :
null
= ba.
find
(
' \x 00'
)
if null
>=
0 :
ba
= ba
[
0 :null
]
return ba
def sched__sched_switch
( event_name
, context
, common_cpu
,
common_secs
, common_nsecs
, common_pid
, common_comm
,
common_callchain
, prev_comm
, prev_pid
, prev_prio
, prev_state
,
next_comm
, next_pid
, next_prio
, perf_sample_dict
) :
print
"prev_comm=%s, prev_pid=%d, prev_prio=%d, " \
"prev_state=%s, next_comm=%s, next_pid=%d, " \
"next_prio=%d" % \
( null
( prev_comm
)
, prev_pid
, prev_prio
,
flag_str
(
"sched__sched_switch"
,
"prev_state"
, prev_state
)
,
null
( next_comm
)
, next_pid
, next_prio
)
Which nicely cleans up the output:
sched__sched_switch 3 664597.912692243 21223 perf prev_comm=perf, prev_pid=21223, prev_prio=120, prev_state=, next_comm=migration/3, next_pid=23, next_prio=0
Dynamic mappings, like IRQ number to name
Dissimilar to system calls and hypervisor calls, interrupt numbers (IRQs) are dynamically assigned by the kernel on demand, so there can't be a static table mapping an IRQ number to a name. Fortunately, perf passes the name to the event's irq_handler_entry routine. This allows a script to create a dictionary that maps the IRQ number to a name:
irq_to_name
=
{
}
def irq__irq_handler_entry_new
( event_name
, context
, common_cpu
, common_secs
, common_nsecs
, common_pid
, common_comm
, common_callchain
, irq
, name
, perf_sample_dict
) :
irq_to_name
[ irq
]
= name
event
= Event_irq_handler_entry
( nsecs
( common_secs
, common_nsecs
)
, common_cpu
, common_pid
, common_comm
, irq
, name
, getpid
( perf_sample_dict
)
)
process_event
( event
)
Somewhat oddly, perf does not pass the name to the irq_handler_exit routine. So, it is possible that a trace may only see an irq_handler_exit for an IRQ and must be able to tolerate that. Here, instead of mapping the IRQ to a name, the IRQ number is returned as a string instead:
def irq_name
( irq
) :
if irq
in irq_to_name:
return irq_to_name
[ irq
]
return
str
( irq
)
Task 0
Task 0 shows up everywhere. It's not a real task. It's a substitute for the "idle" state. It's the task ID given to the sched_switch event handler when the CPU is going to (or coming from) the "idle" state. It's often the task that is "interrupted" by interrupts. Tracking the statistics for task 0 as if it were a real task would not make sense. Currently, curt ignores task 0. However, this loses some information, like some time spent in interrupt processing. curt should, but currently doesn't, track interesting (non-idle) time for task 0.
Spurious sched_migrate_task events (same CPU)
Rarely, a sched_migrate_task event occurs in which the source and target CPUs are the same. In other words, the task is not migrated. To avoid artificially inflated migration counts, this case must be explicitly ignored:
class Event_sched_migrate_task
( Event
) :
def process
(
self
) :
[ …
]
if
self .
cpu
==
self .
dest_cpu :
return
exec
The semantics of the exec system call are that the image of the current process is replaced by a completely new process image without changing the process ID. This is awkward for tracking the statistics of a process (really, a task) based on the process (task) ID. The change is significant enough that the statistics for each task should be accumulated separately, so the current task's statistics need to be closed out and a new set of statistics should be initialized. The challenge is that both the old and new tasks have the same process (task) ID. curt addresses this by tagging the task's task ID with a numeric suffix:
class Event_sched_process_exec
( Event
) :
def process
(
self
) :
global start_timestamp
, curr_timestamp
curr_timestamp
=
self .
timestamp
if
( start_timestamp
==
0
) :
start_timestamp
= curr_timestamp
task
=
super
( Event_sched_process_exec
,
self
) .
process
(
)
new_task
= Task
(
self .
timestamp
,
self .
command
, task.
mode
,
self .
pid
)
new_task.
sched_stat
=
True
new_task.
syscall
= task.
syscall
new_task.
syscalls
[ task.
syscall
]
= Call
(
)
new_task.
syscalls
[ task.
syscall
] .
timestamp
=
self .
timestamp
task.
change_mode
( curr_timestamp
,
'exit'
)
suffix
=
0
while
True :
old_tid
=
str
(
self .
tid
) +
"-" +
str
( suffix
)
if old_tid
in tasks:
suffix +
=
1
else :
break
tasks
[ old_tid
]
= tasks
[
self .
tid
]
del tasks
[
self .
tid
]
tasks
[
self .
tid
]
= new_task
This will clearly separate the statistics for the different process images. In the example below, the perf command (task "9614-0") exec 'd exec.sh (task "9614-1"), which in turn exec 'd itself (task "9614"):
-- [ task] command cpu user sys irq hv busy idle | util% moves
[ 9614] execs.sh 4 1.328238 0.485604 0.000000 0.000000 0.000000 2.273230 | 44.4%
[ 9614] execs.sh 7 0.000000 0.201266 0.000000 0.000000 0.000000 0.003466 | 98.3%
[ 9614] execs.sh ALL 1.328238 0.686870 0.000000 0.000000 0.000000 2.276696 | 47.0% 1
-- [ task] command cpu user sys irq hv busy idle | util% moves
[9614-0] perf 3 0.000000 0.408588 0.000000 0.000000 0.000000 2.298722 | 15.1%
[9614-0] perf 4 0.059079 0.028269 0.000000 0.000000 0.000000 0.611355 | 12.5%
[9614-0] perf 5 0.000000 0.067626 0.000000 0.000000 0.000000 0.004702 | 93.5%
[9614-0] perf ALL 0.059079 0.504483 0.000000 0.000000 0.000000 2.914779 | 16.2% 2
-- [ task] command cpu user sys irq hv busy idle | util% moves
[9614-1] execs.sh 3 1.207972 0.987433 0.000000 0.000000 0.000000 2.435908 | 47.4%
[9614-1] execs.sh 4 0.000000 0.341152 0.000000 0.000000 0.000000 0.004147 | 98.8%
[9614-1] execs.sh ALL 1.207972 1.328585 0.000000 0.000000 0.000000 2.440055 | 51.0% 1
Distribution support
Surprisingly, there is currently no support for perf 's Python bindings in Ubuntu. Follow the saga for more detail.
Limit on number of traced events
As curt gets more sophisticated, it is likely that more and more events may be required to be included in the trace file. perf currently requires one file descriptor per event per CPU. This becomes a problem when the maximum number of open file descriptors is not a large multiple of the number of CPUs on the system. On systems with large numbers of CPUs, this quickly becomes a problem. For example, the default maximum number of open file descriptors is often 1,024. An IBM POWER8 system with four sockets may have 12 cores per socket and eight threads (CPUs) per core. Such a system has 4 * 12 * 8 = 392 CPUs. In that case, perf could trace only about two events! A workaround is to (significantly) increase the maximum number of open file descriptors ( ulimit –n if the system administrator has configured the hard limits high enough; or the administrator can set the limits higher in /etc/security/limits.conf for nofile ).
摘要
I hope this article shows the power of perf —and specifically the utility and flexibility of the Python scripting enabled with perf —to perform sophisticated processing of kernel trace data. Also, it shows some of the issues and edge cases that can be encountered when the boundaries of such technologies are tested.
Please feel free to download and make use of the curt tool described here, report problems, suggest improvements, or contribute code of your own on the curt GitHub page .
翻译自: https://opensource.com/article/18/7/fun-perf-and-python
python perf
更多推荐
0
0- 0
已为社区贡献6条内容
所有评论(0)