Интерпретация столбцов Perf-скриптов - PullRequest
Новая
       64

Интерпретация столбцов Perf-скриптов

0 голосов
/ 04 мая 2020

Для следующей 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.

1 Ответ

2 голосов
/ 04 мая 2020

Вы правы, "60659.641815" представляет timestamp в единицах seconds.microseconds. Эта временная метка представляет количество секунд с момента запуска системы. Для получения более подробной информации прочитайте this .

cycles:k представляет имя события, а значение 1 не связано с cycles. Эти значения 1,3,17,97, 547 et c. представляют период выборки. Это означает, что если у вас есть период выборки x, то в x-й момент возникновения события аппаратный счетчик, соответствующий событию cycles, переполнился, и образец был записан.

Быстрая и простая проверка, чтобы проверить вышеупомянутое утверждение, состоит в том, чтобы запустить perf record с фиксированным периодом выборки, скажем, 2, а затем увидеть perf script output, 

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])
...