From: "Jin, Yao" <yao.jin@linux.intel.com>
To: Jiri Olsa <jolsa@redhat.com>
Cc: acme@kernel.org, jolsa@kernel.org, peterz@infradead.org,
mingo@redhat.com, alexander.shishkin@linux.intel.com,
Linux-kernel@vger.kernel.org, ak@linux.intel.com,
kan.liang@intel.com, yao.jin@intel.com
Subject: Re: [PATCH v2] perf diff: Report noisy for cycles diff
Date: Tue, 6 Aug 2019 19:46:38 +0800 [thread overview]
Message-ID: <3efff55b-511c-0748-432c-e7ef4718c506@linux.intel.com> (raw)
In-Reply-To: <20190806083421.GH7695@krava>
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
next prev parent reply other threads:[~2019-08-06 11:46 UTC|newest]
Thread overview: 8+ messages / expand[flat|nested] mbox.gz Atom feed top
2019-07-24 22:14 [PATCH v2] perf diff: Report noisy for cycles diff Jin Yao
2019-08-06 0:16 ` Jin, Yao
2019-08-06 8:34 ` Jiri Olsa
2019-08-06 11:39 ` Jin, Yao
2019-08-06 8:34 ` Jiri Olsa
2019-08-06 11:46 ` Jin, Yao [this message]
2019-08-06 8:34 ` Jiri Olsa
2019-08-06 11:32 ` Jin, Yao
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=3efff55b-511c-0748-432c-e7ef4718c506@linux.intel.com \
--to=yao.jin@linux.intel.com \
--cc=Linux-kernel@vger.kernel.org \
--cc=acme@kernel.org \
--cc=ak@linux.intel.com \
--cc=alexander.shishkin@linux.intel.com \
--cc=jolsa@kernel.org \
--cc=jolsa@redhat.com \
--cc=kan.liang@intel.com \
--cc=mingo@redhat.com \
--cc=peterz@infradead.org \
--cc=yao.jin@intel.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.