On Thu, Jul 25, 2019 at 06:14:32AM +0800, Jin Yao wrote:
> This patch prints the stddev and hist for the cycles diff of
> program block. It can help us to understand if the cycles diff
> is noisy or not.
>
> This patch is inspired by Andi Kleen's patch
> https://lwn.net/Articles/600471/
>
> We create new option '-n or --noisy'.
>
> Example:
>
> perf record -b ./div
> perf record -b ./div
> perf diff -c cycles
>
> # Event 'cycles'
> #
> # Baseline [Program Block Range]
> Cycles Diff Shared Object Symbol
> # ........
> ......................................................................
> ................. ................................
> #
> 46.42% [div.c:40 ->
> div.c:40] 0 div [.] main
> 46.42% [div.c:42 ->
> div.c:44] 0 div [.] main
> 46.42% [div.c:42 ->
> div.c:39] 0 div [.] main
> 20.72% [random_r.c:357 ->
> random_r.c:394] -2 libc-2.27.so [.] __random_r
> 20.72% [random_r.c:357 ->
> random_r.c:380] -1 libc-2.27.so [.] __random_r
> 20.72% [random_r.c:388 ->
> random_r.c:388] 0 libc-2.27.so [.] __random_r
> 20.72% [random_r.c:388 ->
> random_r.c:391] 0 libc-2.27.so [.] __random_r
> 17.58% [random.c:288 ->
> random.c:291] 0 libc-2.27.so [.] __random
> 17.58% [random.c:291 ->
> random.c:291] 0 libc-2.27.so [.] __random
> 17.58% [random.c:293 ->
> random.c:293] 0 libc-2.27.so [.] __random
> 17.58% [random.c:295 ->
> random.c:295] 0 libc-2.27.so [.] __random
> 17.58% [random.c:295 ->
> random.c:295] 0 libc-2.27.so [.] __random
> 17.58% [random.c:298 ->
> random.c:298] 0 libc-2.27.so [.] __random
> 8.33% [div.c:22 ->
> div.c:25] 0 div [.] compute_flag
> 8.33% [div.c:27 ->
> div.c:28] 0 div [.] compute_flag
> 4.80% [rand.c:26 ->
> rand.c:27] 0 libc-2.27.so [.] rand
> 4.80% [rand.c:28 ->
> rand.c:28] 0 libc-2.27.so [.] rand
> 2.14% [rand@plt+0 ->
> rand@plt+0] 0 div [.] rand@plt
>
> When we enable the option '-n' or '--noisy', the output is
>
> perf diff -c cycles -n
>
> # Event 'cycles'
> #
> # Baseline [Program Block Range]/Cycles
> Diff/stddev/Hist Shared Object Symbol
> # ........
> ................................................................................
> ................. ................................
> #
> 46.42% [div.c:40 -> div.c:40] 0 ±
> 40.2% ▂███▁▂▁▁ div [.] main
> 46.42% [div.c:42 -> div.c:44] 0
> ±100.0% ▁▁▁▁█▁▁▁ div [.] main
> 46.42% [div.c:42 -> div.c:39] 0 ±
> 15.3% ▃▃▂▆▃▂█▁ div [.] main
> 20.72% [random_r.c:357 -> random_r.c:394] -2 ±
> 20.1% ▁▄▄▅▂▅█▁ libc-2.27.so [.] __random_r
> 20.72% [random_r.c:357 -> random_r.c:380] -1 ±
> 20.9% ▁▆▇▁█▅▇█ libc-2.27.so [.] __random_r
> 20.72% [random_r.c:388 -> random_r.c:388] 0 ±
> 0.0% libc-2.27.so [.] __random_r
> 20.72% [random_r.c:388 -> random_r.c:391] 0 ±
> 88.0% ▁▁▁▁▁▁▁█ libc-2.27.so [.] __random_r
> 17.58% [random.c:288 -> random.c:291] 0 ±
> 29.3% ▁████▁█▁ libc-2.27.so [.] __random
> 17.58% [random.c:291 -> random.c:291] 0 ±
> 29.3% ▁████▁▁█ libc-2.27.so [.] __random
> 17.58% [random.c:293 -> random.c:293] 0 ±
> 29.3% ▁████▁▁█ libc-2.27.so [.] __random
> 17.58% [random.c:295 -> random.c:295] 0 ±
> 0.0% libc-2.27.so [.] __random
> 17.58% [random.c:295 -> random.c:295] 0 ±
> 0.0% libc-2.27.so [.] __random
> 17.58% [random.c:298 -> random.c:298] 0 ±
> 0.0% libc-2.27.so [.] __random
> 8.33% [div.c:22 -> div.c:25] 0 ±
> 29.3% ▁████▁█▁ div [.] compute_flag
> 8.33% [div.c:27 -> div.c:28] 0 ±
> 48.8% ▁██▁▁▁█▁ div [.] compute_flag
> 4.80% [rand.c:26 -> rand.c:27] 0 ±
> 29.3% ▁████▁█▁ libc-2.27.so [.] rand
> 4.80% [rand.c:28 -> rand.c:28] 0 ±
> 0.0% libc-2.27.so [.] rand
> 2.14% [rand@plt+0 -> rand@plt+0] 0 ±
> 0.0% div [.] rand@plt
I'm getting some unaligned lines:
# Event 'cycles'
#
# Baseline [Program Block
Range]/Cycles Diff/stddev/Hist Shared Object Symbol
# ........
................................................................................
................... ..............................................
#
11.87% [do_syscall_64+0 -> do_syscall_64+30]
-22 ± 91.8% █▁ [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+0 -> do_syscall_64+47]
-3 ± 84.9% ▁▁▁▁▁▁█▂ [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+91 -> do_syscall_64+118]
-1 ± 33.5% ▁▁▅▃█▁▅█ [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+0 -> do_syscall_64+286]
0 ±100.0% ▁▁█▁▁▁▁▁ [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+0 -> do_syscall_64+332]
0 ± 0.0% [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+53 -> do_syscall_64+86]
0 ± 0.0% [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+124 -> do_syscall_64+148]
0 ± 26.3% ▁▆▂█▆▁██ [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+181 -> do_syscall_64+219]
0 ± 38.9% █▄▄▂▁▁▁▁ [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+278 -> do_syscall_64+281]
0 ± 0.0% [kernel.kallsyms] [k] do_syscall_64
11.87% [do_syscall_64+291 -> do_syscall_64+294]
0 ±100.0% ▁▁▁▁▁▁▁█ [kernel.kallsyms] [k] do_syscall_64
6.76% [psi_task_change+421 -> psi_task_change+440]
-5 ± 45.6% ▄▂▁▁▄▁█▁ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+0 -> psi_task_change+60]
-3 ± 47.9% ▁▃▁▂▁▁█▁ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+126 -> psi_task_change+225]
-2 ± 22.8% ▂▅█▇▃▁▃▅ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+126 -> psi_task_change+172]
-1 ± 48.8% ▁██▁█▁▁▁ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+476 -> psi_task_change+488]
-1 ± 39.9% █▁▁█▁▁▄█ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+80 -> psi_task_change+118]
0 ± 50.0% █▁▂▂▁▁▄▁ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+80 -> psi_task_change+129]
0 ± 48.9% ▁▁▁▇▁█▁█ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+126 -> psi_task_change+142]
0 ± 0.0% [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+230 -> psi_task_change+252]
0 ± 0.0% [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+230 -> psi_task_change+265]
0 ± 0.0% [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+254 -> psi_task_change+324]
0 ±100.0% ▁█▁▁▁▁▁▁ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+298 -> psi_task_change+307]
0 ± 0.0% [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+309 -> psi_task_change+332]
0 ± 37.8% ▁▁█▁▁███ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+326 -> psi_task_change+370]
0 ± 79.5% ▁█▁▁▁▁▁▁ [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+341 -> psi_task_change+348]
0 ± 0.0% [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+446 -> psi_task_change+456]
0 ± 0.0% [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+461 -> psi_task_change+475]
0 ± 0.0% [kernel.kallsyms] [k] psi_task_change
6.76% [psi_task_change+493 -> psi_task_change+497]
0 ± 77.8% █▁▁▁▁▁▃▁ [kernel.kallsyms] [k] psi_task_change
5.27% [syscall_return_via_sysret+0 ->
syscall_return_via_sysret+81] -21 ± 28.1% ▂▄█▄▅▂▁▁ [kernel.kallsyms] [k]
syscall_return_via_sysret
5.27% [syscall_return_via_sysret+0 ->
syscall_return_via_sysret+66] 0 ± 48.7% ▁▇▂▁▁▁█▁ [kernel.kallsyms] [k]
syscall_return_via_sysret
5.27% [syscall_return_via_sysret+83 ->
syscall_return_via_sysret+114] 0 ± 12.8% █▅▆▅▆▁▅▅ [kernel.kallsyms]
[k] syscall_return_via_sysret
4.22% [native_write_msr+0 -> native_write_msr+11]
0 ± 24.6% █▅▄▄▂▄▁▁ [kernel.kallsyms] [k] native_write_msr
2.84% [enqueue_task_fair+257 -> enqueue_task_fair+281]
-168 ± 94.5% ▁█ [kernel.kallsyms] [k] enqueue_task_fair
2.84% [enqueue_task_fair+904 -> enqueue_task_fair+916]
-122 ± 0.0% [kernel.kallsyms] [k] enqueue_task_fair
2.84% [enqueue_task_fair+93 -> enqueue_task_fair+98]
27 ± 8.6% ▁█ [kernel.kallsyms] [k] enqueue_task_fair
2.84% [enqueue_task_fair+286 -> enqueue_task_fair+289]
5 ± 85.5% ▁▁█ [kernel.kallsyms] [k] enqueue_task_fair
2.84% [enqueue_task_fair+0 -> enqueue_task_fair+120]
-3 ± 19.5% ▁█▁▃▂▄▆▃ [kernel.kallsyms] [k] enqueue_task_fair
thanks,
jirka
