When "perf record" was used on a large machine with a lot of CPUs, the
perf post-processing time (the time after the workload was done until
the perf command itself exited) could take a lot of minutes and even
hours depending on how large the resulting perf.data file was.
While running AIM7 1500-user high_systime workload on a 80-core x86-64
system with a 3.9 kernel (with only the -s -a options used), the
workload itself took about 2 minutes to run and the perf.data file had a
size of 1108.746 MB. However, the post-processing step took more than 10
minutes.
With a gprof-profiled perf binary, the time spent by perf was as
follows:
% cumulative self self total
time seconds seconds calls s/call s/call name
96.90 822.10 822.10 192156 0.00 0.00 dsos__find
0.81 828.96 6.86 172089958 0.00 0.00 rb_next
0.41 832.44 3.48 48539289 0.00 0.00 rb_erase
So 97% (822 seconds) of the time was spent in a single dsos_find()
function. After analyzing the call-graph data below:
-----------------------------------------------
0.00 822.12 192156/192156 map__new [6]
[7] 96.9 0.00 822.12 192156 vdso__dso_findnew [7]
822.10 0.00 192156/192156 dsos__find [8]
0.01 0.00 192156/192156 dsos__add [62]
0.01 0.00 192156/192366 dso__new [61]
0.00 0.00 1/45282525 memdup [31]
0.00 0.00 192156/192230 dso__set_long_name [91]
-----------------------------------------------
822.10 0.00 192156/192156 vdso__dso_findnew [7]
[8] 96.9 822.10 0.00 192156 dsos__find [8]
-----------------------------------------------
It was found that the vdso__dso_findnew() function failed to locate
VDSO__MAP_NAME ("[vdso]") in the dso list and have to insert a new
entry at the end for 192156 times. This problem is due to the fact that
there are 2 types of name in the dso entry - short name and long name.
The initial dso__new() adds "[vdso]" to both the short and long names.
After that, vdso__dso_findnew() modifies the long name to something
like /tmp/perf-vdso.so-NoXkDj. The dsos__find() function only compares
the long name. As a result, the same vdso entry is duplicated many
time in the dso list. This bug increases memory consumption as well
as slows the symbol processing time to a crawl.
To resolve this problem, the dsos__find() function interface was
modified to enable searching either the long name or the short
name. The vdso__dso_findnew() will now search only the short name
while the other call sites search for the long name as before.
With this change, the cpu time of perf was reduced from 848.38s to
15.77s and dsos__find() only accounted for 0.06% of the total time.
0.06 15.73 0.01 192151 0.00 0.00 dsos__find
Signed-off-by: Waiman Long <Waiman.Long@hp.com>
Acked-by: Ingo Molnar <mingo@kernel.org>
Cc: "Chandramouleeswaran, Aswin" <aswin@hp.com>
Cc: "Norton, Scott J" <scott.norton@hp.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/r/1368110568-64714-1-git-send-email-Waiman.Long@hp.com
[ replaced TRUE/FALSE with stdbool.h equivalents, fixing builds where
those macros are not present (NO_LIBPYTHON=1 NO_LIBPERL=1), fix from Jiri Olsa ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
per realloc above the length of the buffer is alloc_size, not BUFSIZ.
Adjust length per size as done for buf start.
Addresses some valgrind complaints:
==1870== Syscall param read(buf) points to unaddressable byte(s)
==1870== at 0x4E3F610: __read_nocancel (in /lib64/libpthread-2.14.90.so)
==1870== by 0x44AEE1: event_format__new (unistd.h:45)
==1870== by 0x44B025: perf_evsel__newtp (evsel.c:158)
==1870== by 0x451919: add_tracepoint_event (parse-events.c:395)
==1870== by 0x479815: parse_events_parse (parse-events.y:292)
==1870== by 0x45463A: parse_events_option (parse-events.c:861)
==1870== by 0x44FEE4: get_value (parse-options.c:113)
==1870== by 0x450767: parse_options_step (parse-options.c:192)
==1870== by 0x450C40: parse_options (parse-options.c:422)
==1870== by 0x42735F: cmd_record (builtin-record.c:918)
==1870== by 0x419D72: run_builtin (perf.c:319)
==1870== by 0x4195F2: main (perf.c:376)
==1870== Address 0xcffebf0 is 0 bytes after a block of size 8,192 alloc'd
==1870== at 0x4C2A62F: malloc (vg_replace_malloc.c:270)
==1870== by 0x4C2A7A3: realloc (vg_replace_malloc.c:662)
==1870== by 0x44AF07: event_format__new (evsel.c:121)
==1870== by 0x44B025: perf_evsel__newtp (evsel.c:158)
==1870== by 0x451919: add_tracepoint_event (parse-events.c:395)
==1870== by 0x479815: parse_events_parse (parse-events.y:292)
==1870== by 0x45463A: parse_events_option (parse-events.c:861)
==1870== by 0x44FEE4: get_value (parse-options.c:113)
==1870== by 0x450767: parse_options_step (parse-options.c:192)
==1870== by 0x450C40: parse_options (parse-options.c:422)
==1870== by 0x42735F: cmd_record (builtin-record.c:918)
==1870== by 0x419D72: run_builtin (perf.c:319)
Signed-off-by: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/1372793245-4136-2-git-send-email-dsahern@gmail.com
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Currently we have symbol_conf.exclude_other being set as true every time
so the -x/--exclude-other has nothing to do.
Also we have no way to see the data with symbol_conf.exclude_other being
false which is useful sometimes.
Fixing it by making symbol_conf.exclude_other false by default.
1) Example without -x option:
$ perf report -i perf.data.delete -p perf_session__delete -s parent
+ 99.91% [other]
+ 0.08% perf_session__delete
+ 0.00% perf_session__delete_dead_threads
+ 0.00% perf_session__delete_threads
2) Example with -x option:
$ ./perf report -i perf.data.delete -p perf_session__delete -s parent -x
+ 96.22% perf_session__delete
+ 1.89% perf_session__delete_dead_threads
+ 1.89% perf_session__delete_threads
In Example 1) we get the sorted out data together with the rest
"[other]". This could help us estimate how much time we spent in the
sorted data.
In Example 2) the total is just the sorted data.
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Corey Ashford <cjashfor@linux.vnet.ibm.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Link: http://lkml.kernel.org/n/tip-sg8fvu0fyqohf9ur9l38lhkw@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
When perf tries to start a workload, it relies on a pipe which the
workload was blocked for reading. After closing the pipe on the parent,
the workload (child) can start the actual work via exec().
However, if another process was forked after creating a workload, this
mechanism cannot work since the other process (child) also inherits the
pipe, so that closing the pipe in parent cannot unblock the workload.
Fix it by using explicit write call can then closing it.
For similar reason, the pipe fd on parent should be marked as CLOEXEC so
that it can be closed after another child exec'ed.
Signed-off-by: Namhyung Kim <namhyung@kernel.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Stephane Eranian <eranian@google.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1372230862-15861-13-git-send-email-namhyung@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
This patch fixes a problem with perf stat whereby on termination it may
send a SIGTERM signal to random processes on systems with high PID
recycling. I got some actual bug reports on this.
There is race between the SIGCHLD and sig_atexit() handlers. This patch
addresses this problem by clearing child_pid in the SIGCHLD handler.
Signed-off-by: Stephane Eranian <eranian@google.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: http://lkml.kernel.org/r/20130604154426.GA2928@quad
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Fixing build errors with O and DESTDIR make vars set:
$ make prefix=/usr/local O=$builddir DESTDIR=$destdir -C tools/ perf
...
make[1]: Entering directory `.../.source/perf/tools/perf'
CC .../.build/perf/perf/util/parse-events.o
util/parse-events.c:14:32: fatal error: parse-events-bison.h: No such file or directory
compilation terminated.
make[1]: *** [.../.build/perf/perf/util/parse-events.o] Error 1
...
and:
LINK /.../.build/perf/perf/perf
gcc: error: /.../.build/perf/perf//.../.source/perf/tools/lib/lk/liblk.a: No such file or directory
Signed-off-by: Robert Richter <robert.richter@linaro.org>
Signed-off-by: Robert Richter <rric@kernel.org>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Robert Richter <rric@kernel.org>
Link: http://lkml.kernel.org/r/1370964158-4135-1-git-send-email-rric@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Pull x86 UV update from Ingo Molnar:
"There's a single commit in this tree, which adds support for a new SGI
UV GRU (Global Reference Unit - fast NUMA messaging ASIC) hardware
feature to scale up and beyond: an optional distributed mode that will
allow per-node address mapping of local GRU space, as opposed to
mapping all GRU hardware to the same contiguous high space"
* 'x86-uv-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip:
x86/UV: Add GRU distributed mode mappings
Pull x86 tracing updates from Ingo Molnar:
"This tree adds IRQ vector tracepoints that are named after the handler
and which output the vector #, based on a zero-overhead approach that
relies on changing the IDT entries, by Seiji Aguchi.
The new tracepoints look like this:
# perf list | grep -i irq_vector
irq_vectors:local_timer_entry [Tracepoint event]
irq_vectors:local_timer_exit [Tracepoint event]
irq_vectors:reschedule_entry [Tracepoint event]
irq_vectors:reschedule_exit [Tracepoint event]
irq_vectors:spurious_apic_entry [Tracepoint event]
irq_vectors:spurious_apic_exit [Tracepoint event]
irq_vectors:error_apic_entry [Tracepoint event]
irq_vectors:error_apic_exit [Tracepoint event]
[...]"
* 'x86-tracing-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip:
x86/tracing: Add config option checking to the definitions of mce handlers
trace,x86: Do not call local_irq_save() in load_current_idt()
trace,x86: Move creation of irq tracepoints from apic.c to irq.c
x86, trace: Add irq vector tracepoints
x86: Rename variables for debugging
x86, trace: Introduce entering/exiting_irq()
tracing: Add DEFINE_EVENT_FN() macro
Pull x86 RAS update from Ingo Molnar:
"The changes in this tree are:
- ACPI APEI (ACPI Platform Error Interface) improvements, by Chen
Gong
- misc MCE fixes/cleanups"
* 'x86-ras-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip:
x86/mce: Update MCE severity condition check
mce: acpi/apei: Add comments to clarify usage of the various bitfields in the MCA subsystem
ACPI/APEI: Update einj documentation for param1/param2
ACPI/APEI: Add parameter check before error injection
ACPI, APEI, EINJ: Fix error return code in einj_init()
x86, mce: Fix "braodcast" typo
Pull x86 platform updates from Ingo Molnar:
"Two changes:
- A Kconfig dependency fix/cleanup
- Introduce the 'make kvmconfig' KVM configuration helper utility
that turns the current .config into a KVM-bootable config. Useful
for debugging specific native kernel configs that have no KVM
config options enabled on VM setups."
* 'x86-platform-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip:
x86/platform: Make X86_GOLDFISH depend on X86_EXTENDED_PLATFORM
x86/platform: Add kvmconfig to the phony targets
x86, platform, kvm, kconfig: Turn existing .config's into KVM-capable configs
Pull x86 mm changes from Ingo Molnar:
"Misc improvements:
- Fix /proc/mtrr reporting
- Fix ioremap printout
- Remove the unused pvclock fixmap entry on 32-bit
- misc cleanups"
* 'x86-mm-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip:
x86/ioremap: Correct function name output
x86: Fix /proc/mtrr with base/size more than 44bits
ix86: Don't waste fixmap entries
x86/mm: Drop unneeded include <asm/*pgtable, page*_types.h>
x86_64: Correct phys_addr in cleanup_highmap comment
Waiman Long
Adrian Hunter
David Ahern
Runzhen Wang
Jiri Olsa
Namhyung Kim
Stephane Eranian
Joonsoo Kim
Kirill A. Shutemov
Robert Richter
Robert Richter
Peter Zijlstra
Linus Torvalds