Re: [PATCH v2] perf diff: Report noisy for cycles diff

[Jin, Yao]

On 8/6/2019 4:34 PM, Jiri Olsa wrote:
> 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

Line is too long. While putting the histogram in a separate column may 
have better display. Let me try it.

Thanks
Jin Yao