[RFC/PATCHSET 00/40] perf tools: Speed-up perf report by using multi thread (v4)

From: Namhyung Kim
Date: Sun May 17 2015 - 20:40:52 EST


Hello,

This patchset converts perf report to use multiple threads in order to
speed up the processing on large data files. I can see a minimum ~30%
of speedup with this change. The code is still experimental and
contains many rough edges. But I'd like to share and give some
feedbacks.

* changes in v4)
- rename to *_find(new)_by_time()
- also sort struct map by time
- use 'perf_has_index' global variable
- fix an off-by-one bug in index generation
- rebased onto the recent atomic thread refcounting
- remove missing threads tree in favor of thread rwlock

* changes in v3)
- handle header (metadata) same as sample data (at index 0)
- maintain libunwind address space in map_groups instead of thread
- use *_time API only for indexed data file
- resolve callchain with the *_time API
- use dso__data_get/put_fd() to protect access to fd
- synthesize COMM event for command line workload

* changes in v2)
- rework with single indexed data file rather than multiple files in
a directory

The perf report processes (sample) events like below:

1. preprocess sample to get matching thread/dso/symbol info
2. insert it to hists rbtree (with callchain tree) based on the info
3. optionally collapse hist entries that match given sort key(s)
4. resort hist entries (by overhead) for output
5. display the hist entries

The stage 1 is a preprocessing and mostly act like a read-only
operation in that it doesn't change a machine state during the sample
processing. Meta events like fork, comm and mmap can change the
machine/thread state but symbols can be loaded during the processing
(stage 2).

The stage 2 consumes most of the time especially with callchains and
--children option is enabled. And this work can be easily patitioned
as each sample is independent to others. But the resulting hists must
be combined/collapsed to a single global hists before going to further
steps.

The stage 3 is optional and only needed by certain sort keys - but
with stage 2 paralellized, it needs to be done always.

The stage 4 and 5 works on whole hists so must be done serially.

So my approach is like this:

Partially do stage 1 first - but only for meta events that changes
machine state. To do this I add a dummy tracking event to perf record
and make it collect such meta events only. They are saved as normal
data and processed before sample events at perf report time.

This also requires to handle multiple sample data concurrently and to
find a corresponding machine state when processing samples. On a
large profiling session, many tasks were created and exited so pid
might be recycled (even more than once!). To deal with it, I managed
to have thread, map_groups, map and comm in time sorted. The only
remaining thing is symbol loading as it's done lazily when sample
requires it.

With that being done, the stage 2 can be done by multiple threads. I
also save each sample data (per-cpu or per-thread) in separate files
during record and then merge them into a single data file with an
index table. On perf report time, each region of sample data will be
processed by each thread. And symbol loading is protected by a mutex
lock.

For DWARF post-unwinding, dso cache data also needs to be protected by
a lock and this caused a huge contention. I made it to search the
rbtree speculatively first and then, if it didn't find one, search it
again under the dso lock. Please take a look at it if it's acceptable.

The patch 1-8 are to support indexing for data file. With --index
option, perf record will create a intermediate directory and then save
meta events and sample data to separate files. And finally it'll
build an index table and concatenate the data files (and also remove
the intermediate direcotry).

The patch 9-24 are to manage machine and thread state using timestamp
so that it can be searched when processing samples. The patch 25-38
are to implement parallel report. And finally I implemented 'perf
data index' command to build an index table for a given data file.
The last patch is just to prevent segfault due to a bug in thread
refcounting and not inteneded to be merged.

This patchset didn't change perf record to use multi-thread. But I
think it can be easily done later if needed.

Note that output has a slight difference to original version when
compared using indexed data file. But they're mostly unresolved
symbols for callchains.

Here is the result:

This is just elapsed time measured by 'perf stat -r 5'. Note that
overall performance in v4 slows down than v3 by ~30% possibly due to
atomic thread refcounting and rwlock acquisition.

The data file was recorded during kernel build with fp callchain and
size is 2.1GB. The machine has 6 core with hyper-threading enabled
and I got a similar result on my laptop too.

perf report --children --no-children + --call-graph none
------------- ------------- -------------------
current 368.290435503 122.786548856 51.269541556
with index 339.618194440 101.383647394 35.880577271
+ --multi-thread 219.711277265 70.448753814 29.324704738

This result is with 7.7GB data file using libunwind for callchain.

perf report --children --no-children + --call-graph none
------------- ------------- -------------------
current 213.799598463 155.297229724 6.235268506
with index 216.429553998 156.337434110 4.771545122
+ --multi-thread 54.892308166 35.090129366 3.415513290

This result is with same file but using libdw for callchain unwind.

perf report --children --no-children + --call-graph none
------------- ------------- -------------------
current 401.405331379 399.054998021 6.015400857
with index 383.643272700 372.205715392 5.050819167
+ --multi-thread 176.419091057 139.776442715 3.356360850

On my archlinux system, callchain unwind using libdw is much slower
than libunwind. I'm using elfutils version 0.161. Also I don't know
why --children takes less time than --no-children. Anyway we can see
the --multi-thread performance is much better for each case.

This patch is based on acme/perf/core - commit 70923bd26c73 ("perf
tools: Make flex/bison calls honour V=1"). I've just found that it's
updated to apply atomic refcounting to other structs. But as it
requires another round of rebase, fix and testing cycles on my side,
I'd like to send out the current version before doing that.

You can get it from 'perf/threaded-v4' branch on my tree at:

git://git.kernel.org/pub/scm/linux/kernel/git/namhyung/linux-perf.git

Please take a look and play with it. Any comments are welcome! :)

Thanks,
Namhyung


Namhyung Kim (40):
perf tools: Use a software dummy event to track task/mmap events
perf tools: Add rm_rf() utility function
perf tools: Introduce copyfile_offset() function
perf tools: Create separate mmap for dummy tracking event
perf tools: Introduce perf_evlist__mmap_track()
perf tools: Add HEADER_DATA_INDEX feature
perf tools: Handle indexed data file properly
perf record: Add --index option for building index table
perf report: Skip dummy tracking event
perf tools: Introduce thread__comm(_str)_by_time() helpers
perf tools: Add a test case for thread comm handling
perf tools: Use thread__comm_by_time() when adding hist entries
perf tools: Convert dead thread list into rbtree
perf tools: Introduce machine__find*_thread_by_time()
perf tools: Add a test case for timed thread handling
perf tools: Reducing arguments of hist_entry_iter__add()
perf tools: Maintain map groups list in a leader thread
perf tools: Introduce thread__find_addr_location_by_time() and friends
perf callchain: Use thread__find_addr_location_by_time() and friends
perf tools: Add a test case for timed map groups handling
perf tools: Save timestamp of a map creation
perf tools: Introduce map_groups__{insert,find}_by_time()
perf tools: Use map_groups__find_addr_by_time()
perf tools: Add testcase for managing maps with time
perf tools: Protect dso symbol loading using a mutex
perf tools: Protect dso cache tree using dso->lock
perf tools: Protect dso cache fd with a mutex
perf callchain: Maintain libunwind's address space in map_groups
perf tools: Add dso__data_get/put_fd()
perf session: Pass struct events stats to event processing functions
perf hists: Pass hists struct to hist_entry_iter struct
perf tools: Move BUILD_ID_SIZE definition to perf.h
perf session: Separate struct machines from session
perf report: Parallelize perf report using multi-thread
perf record: Synthesize COMM event for a command line workload
perf tools: Fix progress ui to support multi thread
perf report: Add --multi-thread option and config item
perf session: Handle index files generally
perf data: Implement 'index' subcommand
perf tools: Disable thread refcount due to bug

tools/perf/Documentation/perf-data.txt | 25 +-
tools/perf/Documentation/perf-record.txt | 4 +
tools/perf/Documentation/perf-report.txt | 2 +
tools/perf/builtin-annotate.c | 7 +-
tools/perf/builtin-data.c | 351 +++++++++++++++++-
tools/perf/builtin-diff.c | 8 +-
tools/perf/builtin-kmem.c | 10 +-
tools/perf/builtin-kvm.c | 2 +-
tools/perf/builtin-record.c | 202 ++++++++++-
tools/perf/builtin-report.c | 81 ++++-
tools/perf/builtin-top.c | 16 +-
tools/perf/builtin-trace.c | 2 +-
tools/perf/perf.c | 1 +
tools/perf/perf.h | 4 +
tools/perf/tests/Build | 4 +
tools/perf/tests/builtin-test.c | 16 +
tools/perf/tests/dwarf-unwind.c | 12 +-
tools/perf/tests/hists_common.c | 3 +-
tools/perf/tests/hists_cumulate.c | 7 +-
tools/perf/tests/hists_filter.c | 5 +-
tools/perf/tests/hists_link.c | 6 +-
tools/perf/tests/hists_output.c | 7 +-
tools/perf/tests/perf-targz-src-pkg | 21 --
tools/perf/tests/tests.h | 4 +
tools/perf/tests/thread-comm.c | 47 +++
tools/perf/tests/thread-lookup-time.c | 179 ++++++++++
tools/perf/tests/thread-map-time.c | 90 +++++
tools/perf/tests/thread-mg-share.c | 7 +-
tools/perf/tests/thread-mg-time.c | 93 +++++
tools/perf/ui/browsers/hists.c | 30 +-
tools/perf/ui/gtk/hists.c | 3 +
tools/perf/util/build-id.c | 16 +-
tools/perf/util/build-id.h | 2 -
tools/perf/util/dso.c | 174 ++++++---
tools/perf/util/dso.h | 11 +-
tools/perf/util/event.c | 142 +++++++-
tools/perf/util/event.h | 6 +-
tools/perf/util/evlist.c | 168 +++++++--
tools/perf/util/evlist.h | 14 +-
tools/perf/util/evsel.h | 15 +
tools/perf/util/header.c | 64 ++++
tools/perf/util/header.h | 3 +
tools/perf/util/hist.c | 123 ++++---
tools/perf/util/hist.h | 8 +-
tools/perf/util/machine.c | 291 ++++++++++++---
tools/perf/util/machine.h | 14 +-
tools/perf/util/map.c | 72 +++-
tools/perf/util/map.h | 37 +-
tools/perf/util/probe-event.c | 2 +-
.../util/scripting-engines/trace-event-python.c | 4 +-
tools/perf/util/session.c | 396 ++++++++++++++++++---
tools/perf/util/session.h | 7 +-
tools/perf/util/symbol-elf.c | 2 +-
tools/perf/util/symbol.c | 38 +-
tools/perf/util/thread.c | 207 ++++++++++-
tools/perf/util/thread.h | 28 +-
tools/perf/util/tool.h | 14 +
tools/perf/util/unwind-libdw.c | 12 +-
tools/perf/util/unwind-libunwind.c | 93 ++---
tools/perf/util/unwind.h | 15 +-
tools/perf/util/util.c | 81 ++++-
tools/perf/util/util.h | 2 +
62 files changed, 2856 insertions(+), 454 deletions(-)
delete mode 100755 tools/perf/tests/perf-targz-src-pkg
create mode 100644 tools/perf/tests/thread-comm.c
create mode 100644 tools/perf/tests/thread-lookup-time.c
create mode 100644 tools/perf/tests/thread-map-time.c
create mode 100644 tools/perf/tests/thread-mg-time.c

--
2.4.0

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/