解释perf脚本列

Question

对于以下perf record命令

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，然后查看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])