From: Andi Kleen <andi@firstfloor.org>
To: Milian Wolff <milian.wolff@kdab.com>
Cc: linux-perf-users@vger.kernel.org,
Andi Kleen <andi@firstfloor.org>,
Arnaldo Carvalho de Melo <acme@kernel.org>,
linux-kernel@vger.kernel.org, peterz@infradead.org
Subject: Re: broken cycle counts from perf record in frequency mode [Was: Re: deducing CPU clock rate over time from cycle samples]
Date: Mon, 28 Aug 2017 10:28:08 -0700 [thread overview]
Message-ID: <20170828172808.GQ2482@two.firstfloor.org> (raw)
In-Reply-To: <6142297.1ke4zlptR7@milian-kdab2>
Adding Peter.
The original thread starts at
https://www.spinics.net/lists/linux-perf-users/msg03486.html
On Mon, Aug 28, 2017 at 04:40:43PM +0200, Milian Wolff wrote:
> On Monday, August 28, 2017 4:08:47 PM CEST Milian Wolff wrote:
> > On Sunday, June 18, 2017 9:53:05 PM CEST Milian Wolff wrote:
> > > On Sonntag, 18. Juni 2017 06:22:19 CEST Andi Kleen wrote:
> > > > Milian Wolff <milian.wolff@kdab.com> writes:
> > > > > But when I look at the naively calculated first derivative, to
> > > > > visualize
> > > > > CPU load, i.e. CPU clock rate in Hz, then things start to become
> > > > > somewhat
> > > > > confusing:
> > > > >
> > > > > ~~~~
> > > > > perf script -F time,period | awk 'BEGIN {lastTime = -1;} { time = $1 +
> > > > > 0.0; if (lastTime != -1) {printf("%.6f\t%f\n", time, $2 / (time -
> > > > > lastTime));} lastTime = time; }' | gnuplot -p -e "plot '-' with
> > > > > linespoints"
> > > > > ~~~~
> > > >
> > > > The perf time stamps approach the maximum precision of double (12 vs
> > > > 15 digits). Likely the division loses too many digits, which may cause
> > > > the bogus results. I've ran into similar problems before.
> > >
> > > I don't think so, just look at the raw values:
> > >
> > > $ perf script -F time,period --ns
> > > 71789.438122347: 1
> > > 71789.438127160: 1
> > > 71789.438129599: 7
> > > 71789.438131844: 94
> > > 71789.438134282: 1391
> > > 71789.438139871: 19106
> > > 71789.438156426: 123336
> > > ...
> > >
> > > $ qalc '123336/(71789.438156426s - 71789.438139871s) to Hz'
> > > 123336 / ((71789.438 * second) - (71789.438 * second)) = approx.
> > > 7.4500755E9 Hz
> > >
> > > > One way around is is to normalize the time stamps first that they
> > > > start with 0, but this only works for shorter traces.
> > > > Or use some bignum float library
> > >
> > > I take the time delta between two samples, so a normalization of the
> > > individual times to 0 would not affect my calculations - the delta stays
> > > the same after all.
> > >
> > > Also, using bignum in my calculations wouldn't change anything either. If
> > > perf tells me that 123336 cycles have been executed in 16.555 us, then it
> > > will always be larger than any expected value. At 3.2GHz it should be
> > > maximally 52976 cycles in such a short timeframe...
> > >
> > > > Also at the beginning of frequency the periods are very small, and
> > > > the default us resolution will give big jumps for such a calculation.
> > >
> > > OK, but who/what measures the large cycle values then? Is this a PMU
> > > limitation? Or is this an issue with the interaction with the kernel, when
> > > the algorithm tries to find a good frequency at the beginning?
> > >
> > > > It's better to use the script --ns option then, but that makes the
> > > > double precision problem event worse.
> > >
> > > See above, using `--ns` doesn't change anything. And qalc e.g. already
> > > uses
> > > bignum internally.
> > >
> > > > In generally you get better results by avoiding frequency mode,
> > > > but always specify a fixed period.
> > >
> > > This indeed removes the spikes at the beginning:
> > >
> > > perf record --switch-events --call-graph dwarf -P -c 500000
> > >
> > > The value is chosen to give a similar sample count to frequency mode.
> >
> > Hey all,
> >
> > I want to revive the above discussion as I'm still completely puzzled by the
> > observation. The tl;dr; for those who have not followed the previous
> > discussion:
> >
> > perf record in frequency mode (i.e. "record ~1000 samples per second")
> > sometimes reports excessively large cycle counts.
> >
> > In the previous mails I have outlined how to visualize this issue
> > graphically with gnuplot, by drawing the first derivative of the cycles
> > over time which gives nicely comparable numbers to ones CPU clock speed.
> >
> > Sometimes, this value goe up to 10Ghz and beyond. Sometimes the values are
> > so broken (i.e. so high), that they completely break the analysis with perf
> > report or similar, as they completely skew the total event count and
> > thereby drastically influence the fractional cost reported by perf. E.g.
> > just now I ran `perf record` on another application and got this result:
> >
> > ~~~~~
> > $ perf script | grep page_remove_rmap -C 10
> > QXcbEventReader 23866 605019.879412: 128193 cycles:ppp:
> > ffffffffbb23fbf5 __fget_light (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> > lab_mandelbrot 23865 605019.879469: 1 cycles:ppp:
> > ffffffffbb064504 native_write_msr
> > (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> > QXcbEventReader 23866 605019.879471: 1810360 cycles:ppp:
> > ffffffffbb1cb4ec find_vma (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> > lab_mandelbrot 23865 605019.879472: 1 cycles:ppp:
> > ffffffffbb064504 native_write_msr
> > (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> > lab_mandelbrot 23865 605019.879474: 10 cycles:ppp:
> > ffffffffbb064504 native_write_msr
> > (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> > lab_mandelbrot 23865 605019.879475: 216 cycles:ppp:
> > ffffffffbb064504 native_write_msr
> > (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> > lab_mandelbrot 23865 605019.879486: 5106 cycles:ppp:
> > ffffffffbb064504 native_write_msr
> > (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> > lab_mandelbrot 23865 605019.879489: 19381 cycles:ppp:
> > 7f85beae64ce QWaitCondition::wait (/usr/lib/libQt5Core.so.5.9.1)
> > lab_mandelbrot 23865 605019.879495: 251346 cycles:ppp:
> > 7f85bf2567c1 QScreen::~QScreen (/usr/lib/libQt5Gui.so.5.9.1)
> > lab_mandelbrot 23865 605019.880722: 3210571 cycles:ppp:
> > 7f85bd96f850 __cxa_finalize (/usr/lib/libc-2.25.so)
> > lab_mandelbrot 23865 605019.881592: 21110358010774 cycles:ppp:
> > ffffffffbb1d4218 page_remove_rmap (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> > ~~~~~
> >
> > Note the last sample's cycle cost of 21110358010774. This is so large, that
> > it completely dominates the total event count, which lies at
> > 21126914067278. The runtime for this perf record was about 4s, it was on a
> > single threaded application with 4.12.8-2-ARCH on a Intel(R) Core(TM)
> > i7-4770 CPU @ 3.40GHz. So that hardware should at most be capable of
> > running up to ~1.36E10 cycles over 4s. perf record, thanks to the last
> > sample, measured ~2.11E13 cycles - clearly off the charts.
> >
> > I have never seen this issue outside of perf's frequency mode. But then
> > again, that mode is the default and quite useful. Can anyone explain what
> > I'm seeing here?
> >
> > Is it a bug in the kernel?
> > Is it a bug/limitation in the PMU?
>
> I think this also sometimes manifests itself in lack of samples. I.e. for the
> same workload above I now only get a couple dozen samples over a timeframe of
> 4s in total:
>
> ~~~~~
> $ time perf record .../lab_mandelbrot -b 10
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.041 MB perf.data (131 samples) ]
>
> real 0m5.042s
> user 0m4.964s
> sys 0m0.054s
> ~~~~~
>
> Dmesg is silent here, so I don't think it's due to throttling:
>
> ~~~~~
> /proc/sys/kernel/perf_cpu_time_max_percent
> 25
> /proc/sys/kernel/perf_event_max_contexts_per_stack
> 8
> /proc/sys/kernel/perf_event_max_sample_rate
> 50400
> /proc/sys/kernel/perf_event_max_stack
> 127
> /proc/sys/kernel/perf_event_mlock_kb
> 516
> /proc/sys/kernel/perf_event_paranoid
> -1
> ~~~~~
>
> Rather, it's again the broken cycle counts which probably confuse the
> frequency algorithm in the kernel:
>
> ~~~~~
> $ perf script
> perf 5678 611709.152451: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> perf 5678 611709.152455: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> perf 5678 611709.152456: 8 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> perf 5678 611709.152457: 203 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> perf 5678 611709.152459: 5421 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.152461: 144518 cycles:ppp: ffffffffbb173fe0
> __perf_event__output_id_sample (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.152502: 1902383 cycles:ppp: ffffffffbb208e00
> unlock_page_memcg (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.153037: 18471563529604 cycles:ppp:
> 7f20085ecc58 _dl_map_object_from_fd (/usr/lib/ld-2.25.so)
> lab_mandelbrot 5679 611709.163192: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5679 611709.163195: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5679 611709.163197: 7 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5679 611709.163198: 158 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5679 611709.163200: 3376 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5679 611709.163202: 79849 cycles:ppp: 7f2005e50b10
> __ctype_init (/usr/lib/libc-2.25.so)
> lab_mandelbrot 5679 611709.163233: 1142185 cycles:ppp: ffffffffbb340a87
> clear_page_erms (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164503: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164505: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164507: 14 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164508: 264 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164510: 5234 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164513: 102113 cycles:ppp: ffffffffbb10928a
> sys_futex (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164540: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164543: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164545: 12 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164547: 217 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164548: 4154 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.164551: 82262 cycles:ppp: 7f2006a880a2
> pthread_cond_wait@@GLIBC_2.3.2 (/usr/lib/libpthread-2.25.so)
>
> .. this pattern repeats and already looks quite bogus I think ...
> .. eventually we hit completely broken values: ...
>
> lab_mandelbrot 5678 611709.167097: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.167099: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.167100: 17 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.167102: 435 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.167103: 11560 cycles:ppp: ffffffffbb031e7b
> nmi_handle (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.167107: 306222 cycles:ppp: 7f2006a848ef
> pthread_mutex_lock (/usr/lib/libpthread-2.25.so)
> lab_mandelbrot 5678 611709.167277: 2558928 cycles:ppp: ffffffffbb1bd9f5
> vmacache_update (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.168034: 2710380 cycles:ppp: 7f2005e9e72a
> _int_free (/usr/lib/libc-2.25.so)
> lab_mandelbrot 5678 611709.168772: 2483393 cycles:ppp: ffffffffbb220550
> get_empty_filp (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.169450: 23749385103571 cycles:ppp:
> 7f20086019d4 strcmp (/usr/lib/ld-2.25.so)
> lab_mandelbrot 5678 611709.190936: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.190939: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.190941: 9 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.190942: 194 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.190943: 4357 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.190946: 100515 cycles:ppp: ffffffffbb1086c3
> do_futex (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> lab_mandelbrot 5678 611709.190975: 1437218 cycles:ppp: 7f2005ea0ef4
> _int_realloc (/usr/lib/libc-2.25.so)
> QDBusConnection 5680 611709.191013: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> QDBusConnection 5680 611709.191015: 1 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> QDBusConnection 5680 611709.191026: 13 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> QDBusConnection 5680 611709.191027: 50 cycles:ppp: ffffffffbb064504
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> QDBusConnection 5680 611709.191028: 1395 cycles:ppp: ffffffffbb064506
> native_write_msr (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> QDBusConnection 5680 611709.191029: 38641 cycles:ppp: ffffffffbb65bce7
> schedule_hrtimeout_range_clock (/lib/modules/4.12.8-2-ARCH/build/vmlinux)
> QDBusConnection 5680 611709.191041: 934282 cycles:ppp: 7f1ffcde715f
> _dbus_first_type_in_signature (/usr/lib/libdbus-1.so.3.14.13)
> lab_mandelbrot 5678 611709.191535: 2815425 cycles:ppp: 7f1ff46dc8ef
> qMax<double> (/ssd2/milian/projects/compiled/kf5/lib/libKF5GuiAddons.so.
> 5.37.0)
> lab_mandelbrot 5678 611709.192280: 2620652 cycles:ppp: 7f200640230d
> [unknown] (/usr/lib/libm-2.25.so)
> lab_mandelbrot 5678 611709.192992: 23749385195574 cycles:ppp:
> 7f1ff644e442 QMap<KEntryKey, KEntry>::const_iterator::const_iterator (/ssd2/
> milian/projects/compiled/kf5/lib/libKF5ConfigCore.so.5.37.0)
> lab_mandelbrot 5678 611709.536988: 27340128 cycles:ppp: 565094e15c28
> drawMandelbrot (/ssd/milian/projects/kdab/training-material/addon/profiling/
> build/lab_mandelbrot/src/lab_mandelbrot)
> lab_mandelbrot 5678 611709.544397: 2308960570885 cycles:ppp:
> 7f20064029fc __hypot_finite (/usr/lib/libm-2.25.so)
> lab_mandelbrot 5678 611709.858996: 19754129 cycles:ppp: 7f2006402a37
> __hypot_finite (/usr/lib/libm-2.25.so)
> lab_mandelbrot 5678 611709.864538: 2308954751998 cycles:ppp:
> 7f2006402a77 __hypot_finite (/usr/lib/libm-2.25.so)
> lab_mandelbrot 5678 611710.183972: 14591525 cycles:ppp: 565094e14ce0
> cabs@plt (/ssd/milian/projects/kdab/training-material/addon/profiling/build/
> lab_mandelbrot/src/lab_mandelbrot)
> lab_mandelbrot 5678 611710.188004: 2638800790961 cycles:ppp:
> 7f20078dacc0 QColor::toRgb (/usr/lib/libQt5Gui.so.5.9.1)
> lab_mandelbrot 5678 611710.495016: 25617507 cycles:ppp: 7f20061cdc6d
> __muldc3 (/usr/lib/libgcc_s.so.1)
> lab_mandelbrot 5678 611710.501962: 2308959251991 cycles:ppp:
> 7f2006402a63 __hypot_finite (/usr/lib/libm-2.25.so)
> lab_mandelbrot 5678 611710.815734: 19739740 cycles:ppp: 7f20061cdc5c
> __muldc3 (/usr/lib/libgcc_s.so.1)
> lab_mandelbrot 5678 611710.821164: 2308954745231 cycles:ppp:
> 7f2006402b33 __hypot_finite (/usr/lib/libm-2.25.so)
> ~~~~~
>
> So, is my PMU messed up?
> --
> Milian Wolff | milian.wolff@kdab.com | Senior Software Engineer
> KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
> Tel: +49-30-521325470
> KDAB - The Qt Experts
next prev parent reply other threads:[~2017-08-28 17:28 UTC|newest]
Thread overview: 11+ messages / expand[flat|nested] mbox.gz Atom feed top
2017-06-17 19:07 deducing CPU clock rate over time from cycle samples Milian Wolff
2017-06-18 4:22 ` Andi Kleen
2017-06-18 19:53 ` Milian Wolff
2017-08-28 14:08 ` broken cycle counts from perf record in frequency mode [Was: Re: deducing CPU clock rate over time from cycle samples] Milian Wolff
2017-08-28 14:40 ` Milian Wolff
2017-08-28 17:28 ` Andi Kleen [this message]
2017-09-01 10:34 ` Milian Wolff
2017-09-01 16:48 ` Andi Kleen
2017-09-04 14:35 ` Milian Wolff
2017-09-05 3:40 ` Andi Kleen
2017-09-05 12:26 ` Milian Wolff
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=20170828172808.GQ2482@two.firstfloor.org \
--to=andi@firstfloor.org \
--cc=acme@kernel.org \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-perf-users@vger.kernel.org \
--cc=milian.wolff@kdab.com \
--cc=peterz@infradead.org \
/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.