解释 perf 脚本列

Question

对于下面的perf记录命令

perf record -e cycles:k -j any,k -a

当我通过perf script阅读它时，我看到了以下列

       nginx 12722 60659.641815:          1 cycles:k:  ffffffffa2a72f36 native_write_msr+0x6 (/lib/modules/4.19.119/build/vmlinux
       nginx 12722 60659.641828:          1 cycles:k:  ffffffffa2a72f36 native_write_msr+0x6 (/lib/modules/4.19.119/build/vmlinux
       nginx 12722 60659.641835:          3 cycles:k:  ffffffffa2a72f36 native_write_msr+0x6 (/lib/modules/4.19.119/build/vmlinux
       nginx 12722 60659.641842:         17 cycles:k:  ffffffffa2a72f36 native_write_msr+0x6 (/lib/modules/4.19.119/build/vmlinux
       nginx 12722 60659.641848:         97 cycles:k:  ffffffffa2a72f36 native_write_msr+0x6 (/lib/modules/4.19.119/build/vmlinux
       nginx 12722 60659.641855:        547 cycles:k:  ffffffffa2a72f36 native_write_msr+0x6 (/lib/modules/4.19.119/build/vmlinux
       nginx 12722 60659.641861:       3060 cycles:k:  ffffffffa2a72f36 native_write_msr+0x6 (/lib/modules/4.19.119/build/vmlinux
       nginx 12722 60659.641868:      17723 cycles:k:  ffffffffa2a72f36 native_write_msr+0x6 (/lib/modules/4.19.119/build/vmlinux
       nginx 12722 60659.641884:      99057 cycles:k:  ffffffffa2bbdaba irq_work_run_list+0xa (/lib/modules/4.19.119/build/vmlinu
       nginx 12722 60659.641939:     274693 cycles:k:  ffffffffa329ade4 sock_poll+0x44 (/lib/modules/4.19.119/build/vmlinux)
       nginx 12722 60659.642112:     397008 cycles:k:  ffffffffa333cc7b tcp_write_xmit+0xbb (/lib/modules/4.19.119/build/vmlinux)

我知道 12722 是 PID。我想知道什么是“60659.641815”和“1个周期”列？我猜前者是时间但不知道为什么它从60659.641815开始。

Answer 1

你是对的，“60659.641815”以seconds.microseconds为单位代表timestamp。此时间戳表示自系统启动以来的秒数。更多详情，请阅读this。

cycles:k 表示事件名称，值 1 与 cycles 无关。这些值 1、3、17、97、547 等代表采样周期。这意味着，如果您的采样周期为 x，则在第 x 次事件发生时，对应于 cycles 事件的硬件计数器溢出并写入了一个样本。

验证上述语句的快速简便的检查方法是运行 perf record，固定采样周期为 2，然后查看 perf script 输出，

perf record -e cycles:k -j any,k -c 2 -a
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.289 MB perf.data (8 samples) ]


perf script

            perf  5746 [000] 54322.047321:          2 cycles:k:  ffffffffb786ee9a native_write_msr+0xa ([kernel.kallsyms])
         swapper     0 [001] 54322.047350:          2 cycles:k:  ffffffffb786ee9a native_write_msr+0xa ([kernel.kallsyms])
         swapper     0 [002] 54322.047425:          2 cycles:k:  ffffffffb786ee9a native_write_msr+0xa ([kernel.kallsyms])
         swapper     0 [003] 54322.047449:          2 cycles:k:  ffffffffb786ee9a native_write_msr+0xa ([kernel.kallsyms])
         swapper     0 [004] 54322.047473:          2 cycles:k:  ffffffffb786ee9a native_write_msr+0xa ([kernel.kallsyms])
         swapper     0 [005] 54322.047496:          2 cycles:k:  ffffffffb786ee9a native_write_msr+0xa ([kernel.kallsyms])
         swapper     0 [006] 54322.047519:          2 cycles:k:  ffffffffb786ee9a native_write_msr+0xa ([kernel.kallsyms])
 MediaPl~back #3  2095 [007] 54322.047545:          2 cycles:k:  ffffffffb786ee9a native_write_msr+0xa ([kernel.kallsyms])