perf/core improvements and fixes

Hi Ingo,

Please consider pulling,

- Arnaldo

The following changes since commit 82819ffb42fb45197bacf3223191deca31d3eb91:

perf/x86/msr: Fix the MSR driver build (2015-08-21 08:17:01 +0200)

are available in the git repository at:

git://git.kernel.org/pub/scm/linux/kernel/git/acme/linux.git tags/perf-core-for-mingo

for you to fetch changes up to 1c0bd0e891aaed0219010bfe79b32e1b0b82d662:

perf probe: Try to use symbol table if searching debug info failed (2015-08-21 12:57:20 -0300)

----------------------------------------------------------------
perf/core improvements and fixes:

User visible:

- Fix segfault using 'perf script --show-mmap-events', affects only current perf/core (Adrian Hunter).

- /proc/kcore requires CAP_SYS_RAWIO message too noisy, make it debug only (Adrian Hunter)

- Fix Intel PT timestamp handling (Adrian Hunter)

- Add Intel BTS support, with a call-graph script to show it and PT in use in a GUI using 'perf script' python scripting with postgresql and Qt (Adrian Hunter)

- Add checks for returned EVENT_ERROR type in libtraceevent, fixing a bug that surfaced on arm64 systems (Dean Nelson)

- Fallback to using kallsyms when libdw fails to handle a vmlinux file, that can happen, for instance, when perf is statically linked and then libdw fails to load libebl_{arch}.so (Wang Nan)

Infrastructure:

- Initialize reference counts in map__clone() (Arnaldo Carvalho de Melo)

----------------------------------------------------------------
Adrian Hunter (6):
perf script: Fix segfault using --show-mmap-events perf tools: /proc/kcore requires CAP_SYS_RAWIO message too noisy perf tools: Fix Intel PT timestamp handling
perf tools: Add Intel BTS support
perf tools: Put itrace options into an asciidoc include perf tools: Add example call-graph script

Arnaldo Carvalho de Melo (1):
perf tools: Initialize reference counts in map__clone()

Dean Nelson (1):
tools lib traceevent: Add checks for returned EVENT_ERROR type

Wang Nan (1):
perf probe: Try to use symbol table if searching debug info failed

 tools/lib/traceevent/event-parse.c                 |   9 +
 tools/perf/Documentation/intel-bts.txt             |  86 ++
 tools/perf/Documentation/itrace.txt                |  22 +
 tools/perf/Documentation/perf-inject.txt           |  23 +-
 tools/perf/Documentation/perf-report.txt           |  23 +-
 tools/perf/Documentation/perf-script.txt           |  23 +-
 tools/perf/arch/x86/util/Build                     |   1 +
 tools/perf/arch/x86/util/auxtrace.c                |  49 +-
 tools/perf/arch/x86/util/intel-bts.c               | 458 ++++++++++
 tools/perf/arch/x86/util/pmu.c                     |   3 +
 .../scripts/python/call-graph-from-postgresql.py   | 327 ++++++++
 tools/perf/scripts/python/export-to-postgresql.py  |  47 ++
 tools/perf/util/Build                              |   1 +
 tools/perf/util/annotate.c                         |   1 +
 tools/perf/util/auxtrace.c                         |   3 +
 tools/perf/util/auxtrace.h                         |   1 +
 tools/perf/util/evlist.c                           |   2 +-
 tools/perf/util/intel-bts.c                        | 933 +++++++++++++++++++++
 tools/perf/util/intel-bts.h                        |  43 +
 tools/perf/util/intel-pt.c                         |   2 +-
 tools/perf/util/map.c                              |  13 +-
 tools/perf/util/pmu.c                              |   4 -
 tools/perf/util/probe-event.c                      |   7 +-
 tools/perf/util/symbol.c                           |   4 +-
 24 files changed, 2004 insertions(+), 81 deletions(-)
 create mode 100644 tools/perf/Documentation/intel-bts.txt
 create mode 100644 tools/perf/Documentation/itrace.txt
 create mode 100644 tools/perf/arch/x86/util/intel-bts.c
 create mode 100644 tools/perf/scripts/python/call-graph-from-postgresql.py
 create mode 100644 tools/perf/util/intel-bts.c
 create mode 100644 tools/perf/util/intel-bts.h

From: Adrian Hunter <[email protected]>

Patch "perf script: Don't assume evsel position of tracking events" changed 'perf script' to use 'perf_evlist__id2evsel()'. That results in a segfault if there is more than 1 event and there are synthesized mmap events e.g.

	$ perf record -e cycles,instructions -p$$ sleep 1
	$ perf script --show-mmap-events
	Segmentation fault (core dumped)

That happens because these synthesized events have an 'id' of zero which does not match any 'evsel'.

Currently, these synthesized events use the sample type of the first evsel.

Change 'perf_evlist__id2evsel()' to reflect that which also makes it consistent with 'perf_evlist__event2evsel()'.

---
 tools/perf/util/evlist.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 373f65b02545..e9a5d432902c 100644
@@ -573,7 +573,7 @@ struct perf_evsel *perf_evlist__id2evsel(struct perf_evlist *evlist, u64 id)
 {
 	struct perf_sample_id *sid;
 
-	if (evlist->nr_entries == 1)
+	if (evlist->nr_entries == 1 || !id)
 		return perf_evlist__first(evlist);
 
 	sid = perf_evlist__id2sid(evlist, id);

2.1.0

From: Adrian Hunter <[email protected]>

The "/proc/kcore requires CAP_SYS_RAWIO" message comes up all the time for 'perf script' if vmlinux is not found and the user isn't root, even when the kernel is not being traced and even though the message is only really relevant for annotation.

Change it to pr_debug and instead put a note in the message displayed if annotation is not possible.

Also, the file being accessed might not be /proc/kcore. Tools can be directed to a different location using the --kallsyms option in which case kcore is expected to be in the same directory. Adjust the message so it is not misleading in that case.

---
 tools/perf/util/annotate.c | 1 +
 tools/perf/util/symbol.c   | 4 ++--
 2 files changed, 3 insertions(+), 2 deletions(-)

index 8a18347709e1..d1eece70b84d 100644
@@ -1126,6 +1126,7 @@ fallback:
 		dso->annotate_warned = 1;
 		pr_err("Can't annotate %s:\n\n"
 		       "No vmlinux file%s\nwas found in the path.\n\n"
+		       "Note that annotation using /proc/kcore requires CAP_SYS_RAWIO capability.\n\n"
 		       "Please use:\n\n"
 		       "  perf buildid-cache -vu vmlinux\n\n"
 		       "or:\n\n"

index 725640fd7cd8..42e98ab5a9bb 100644
@@ -1138,8 +1138,8 @@ static int dso__load_kcore(struct dso *dso, struct map *map,
 
 	fd = open(kcore_filename, O_RDONLY);
 	if (fd < 0) {
-		pr_err("%s requires CAP_SYS_RAWIO capability to access.\n",
-			kcore_filename);
+		pr_debug("Failed to open %s. Note /proc/kcore requires CAP_SYS_RAWIO capability to access.\n",
+			 kcore_filename);
 		return -EINVAL;
 	}
 

2.1.0

From: Adrian Hunter <[email protected]>

Events that don't sample the timestamp have a timestamp value of -1.

Intel PT processing wasn't taking that into account.

This is particularly noticeable with Intel BTS because timestamps are not requested by default.

Then, if the conversion of -1 to TSC results in a small number, the processing is unaffected.

However if the conversion results in a big number, then the data is processed prematurely before relevant sideband data like mmap events, which in turn results in samples with unknown dsos.

Commiter note:

Since BTS wasn't upstream, I split the patch to fold the BTS part with the patch introducing it, to avoid having this bug in the commit history. PT was already upstream, so this patch contains that part.

---
 tools/perf/util/intel-pt.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 2a4a4120473b..a5acd2fe2447 100644
@@ -1450,7 +1450,7 @@ static int intel_pt_process_event(struct perf_session *session,
 		return -EINVAL;
 	}
 
-	if (sample->time)
+	if (sample->time && sample->time != (u64)-1)
 		timestamp = perf_time_to_tsc(sample->time, &pt->tc);
 	else
 		timestamp = 0;

2.1.0

From: Dean Nelson <[email protected]>

Running the following perf-stat command on an arm64 system produces the following result...

[root@aarch64 ~]# perf stat -e kmem:mm_page_alloc -a sleep 1
Warning: [kmem:mm_page_alloc] function sizeof not defined
Warning: Error: expected type 4 but read 0
Segmentation fault
[root@aarch64 ~]#

The second warning was a result of the first warning not stopping processing after it detected the issue.

That is, code that found the issue reported the first problem, but because it did not exit out of the functions smoothly, it caused the other warning to appear and not only that, it later caused the SIGSEGV.

---
 tools/lib/traceevent/event-parse.c | 9 +++++++++
 1 file changed, 9 insertions(+)

index fcd8a9e3d2e1..5c1867a13ef2 100644
@@ -1745,6 +1745,9 @@ process_cond(struct event_format *event, struct print_arg *top, char **tok)
 	type = process_arg(event, left, &token);
 
  again:
+	if (type == EVENT_ERROR)
+		goto out_free;
+
 	/* Handle other operations in the arguments */
 	if (type == EVENT_OP && strcmp(token, ":") != 0) {
 		type = process_op(event, left, &token);

@@ -2004,6 +2007,12 @@ process_op(struct event_format *event, struct print_arg *arg, char **tok)
 			goto out_warn_free;
 
 		type = process_arg_token(event, right, tok, type);
+		if (type == EVENT_ERROR) {
+			free_arg(right);
+			/* token was freed in process_arg_token() via *tok */
+			token = NULL;
+			goto out_free;
+		}
 
 		if (right->type == PRINT_OP &&
 		    get_op_prio(arg->op.op) < get_op_prio(right->op.op)) {

2.1.0

From: Adrian Hunter <[email protected]>

Intel BTS support fits within the new auxtrace infrastructure. Recording is supporting by identifying the Intel BTS PMU, parsing options and setting up events.

Decoding is supported by queuing up trace data by thread and then decoding synchronously delivering synthesized event samples into the session processing for tools to consume.

Committer note:

E.g:

[root@felicio ~]# perf record --per-thread -e intel_bts// ls
anaconda-ks.cfg apctest.output bin kernel-rt-3.10.0-298.rt56.171.el7.x86_64.rpm libexec lock_page.bpf.c perf.data perf.data.old
[ perf record: Woken up 3 times to write data ]
[ perf record: Captured and wrote 4.367 MB perf.data ]
[root@felicio ~]# perf evlist -v
intel_bts//: type: 6, size: 112, { sample_period, sample_freq }: 1, sample_type: IP|TID|IDENTIFIER, read_format: ID, disabled: 1, enable_on_exec: 1, sample_id_all: 1, exclude_guest: 1
dummy:u: type: 1, size: 112, config: 0x9, { sample_period, sample_freq }: 1, sample_type: IP|TID|IDENTIFIER, read_format: ID, disabled: 1, exclude_kernel: 1, exclude_hv: 1, mmap: 1, comm: 1, enable_on_exec: 1, task: 1, sample_id_all: 1, mmap2: 1, comm_exec: 1 [root@felicio ~]# perf script # the navigate in the pager to some interesting place:

    ls 1843 1 branches: ffffffff810a60cb flush_signal_handlers ([kernel.kallsyms]) => ffffffff8121a522 setup_new_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8121a529 setup_new_exec ([kernel.kallsyms]) => ffffffff8122fa30 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fa5d do_close_on_exec ([kernel.kallsyms]) => ffffffff81767ae0 _raw_spin_lock ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff81767af4 _raw_spin_lock ([kernel.kallsyms]) => ffffffff8122fa62 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fa8e do_close_on_exec ([kernel.kallsyms]) => ffffffff8122faf0 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122faf7 do_close_on_exec ([kernel.kallsyms]) => ffffffff8122fa8b do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fa8e do_close_on_exec ([kernel.kallsyms]) => ffffffff8122faf0 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122faf7 do_close_on_exec ([kernel.kallsyms]) => ffffffff8122fa8b do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fa8e do_close_on_exec ([kernel.kallsyms]) => ffffffff8122faf0 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122faf7 do_close_on_exec ([kernel.kallsyms]) => ffffffff8122fa8b do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fa8e do_close_on_exec ([kernel.kallsyms]) => ffffffff8122faf0 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122faf7 do_close_on_exec ([kernel.kallsyms]) => ffffffff8122fa8b do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fa8e do_close_on_exec ([kernel.kallsyms]) => ffffffff8122faf0 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122faf7 do_close_on_exec ([kernel.kallsyms]) => ffffffff8122fa8b do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fa8e do_close_on_exec ([kernel.kallsyms]) => ffffffff8122faf0 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122faf7 do_close_on_exec ([kernel.kallsyms]) => ffffffff8122fa8b do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fac9 do_close_on_exec ([kernel.kallsyms]) => ffffffff8122fad2 do_close_on_exec ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8122fadd do_close_on_exec ([kernel.kallsyms]) => ffffffff8120fc80 filp_close ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8120fcaf filp_close ([kernel.kallsyms]) => ffffffff8120fcb6 filp_close ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8120fcc2 filp_close ([kernel.kallsyms]) => ffffffff812547f0 dnotify_flush ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff81254823 dnotify_flush ([kernel.kallsyms]) => ffffffff8120fcc7 filp_close ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8120fccd filp_close ([kernel.kallsyms]) => ffffffff81261790 locks_remove_posix ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff812617a3 locks_remove_posix ([kernel.kallsyms]) => ffffffff812617b9 locks_remove_posix ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff812617b9 locks_remove_posix ([kernel.kallsyms]) => ffffffff8120fcd2 filp_close ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8120fcd5 filp_close ([kernel.kallsyms]) => ffffffff812142c0 fput ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff812142d6 fput ([kernel.kallsyms]) => ffffffff812142df fput ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff8121430c fput ([kernel.kallsyms]) => ffffffff810b6580 task_work_add ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff810b65ad task_work_add ([kernel.kallsyms]) => ffffffff810b65b1 task_work_add ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff810b65c1 task_work_add ([kernel.kallsyms]) => ffffffff810bc710 kick_process ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff810bc725 kick_process ([kernel.kallsyms]) => ffffffff810bc742 kick_process ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff810bc742 kick_process ([kernel.kallsyms]) => ffffffff810b65c6 task_work_add ([kernel.kallsyms])
    ls 1843 1 branches: ffffffff810b65c9 task_work_add ([kernel.kallsyms]) => ffffffff81214311 fput ([kernel.kallsyms])

---
 tools/perf/Documentation/intel-bts.txt |  86 +++
 tools/perf/arch/x86/util/Build         |   1 +
 tools/perf/arch/x86/util/auxtrace.c    |  49 +-
 tools/perf/arch/x86/util/intel-bts.c   | 458 ++++++++++++++++
 tools/perf/arch/x86/util/pmu.c         |   3 +
 tools/perf/util/Build                  |   1 +
 tools/perf/util/auxtrace.c             |   3 +
 tools/perf/util/auxtrace.h             |   1 +
 tools/perf/util/intel-bts.c            | 933 +++++++++++++++++++++++++++++++++
 tools/perf/util/intel-bts.h            |  43 ++
 tools/perf/util/pmu.c                  |   4 -
 11 files changed, 1576 insertions(+), 6 deletions(-)
 create mode 100644 tools/perf/Documentation/intel-bts.txt
 create mode 100644 tools/perf/arch/x86/util/intel-bts.c
 create mode 100644 tools/perf/util/intel-bts.c
 create mode 100644 tools/perf/util/intel-bts.h

new file mode 100644
index 000000000000..8bdc93bd7fdb
@@ -0,0 +1,86 @@
+Intel Branch Trace Store
+========================
+
+Overview
+========
+
+Intel BTS could be regarded as a predecessor to Intel PT and has some
+similarities because it can also identify every branch a program takes.  A
+notable difference is that Intel BTS has no timing information and as a
+consequence the present implementation is limited to per-thread recording.
+
+While decoding Intel BTS does not require walking the object code, the object
+code is still needed to pair up calls and returns correctly, consequently much
+of the Intel PT documentation applies also to Intel BTS.  Refer to the Intel PT
+documentation and consider that the PMU 'intel_bts' can usually be used in
+place of 'intel_pt' in the examples provided, with the proviso that per-thread
+recording must also be stipulated i.e. the --per-thread option for
+'perf record'.
+
+
+perf record
+===========
+
+new event
+---------
+
+The Intel BTS kernel driver creates a new PMU for Intel BTS.  The perf record
+option is:
+
+	-e intel_bts//
+
+Currently Intel BTS is limited to per-thread tracing so the --per-thread option
+is also needed.
+
+
+snapshot option
+---------------
+
+The snapshot option is the same as Intel PT (refer Intel PT documentation).
+
+
+auxtrace mmap size option
+-----------------------
+
+The mmap size option is the same as Intel PT (refer Intel PT documentation).
+
+
+perf script
+===========
+
+By default, perf script will decode trace data found in the perf.data file.
+This can be further controlled by option --itrace.  The --itrace option is
+the same as Intel PT (refer Intel PT documentation) except that neither
+"instructions" events nor "transactions" events (and consequently call
+chains) are supported.
+
+To disable trace decoding entirely, use the option --no-itrace.
+
+
+dump option
+-----------
+
+perf script has an option (-D) to "dump" the events i.e. display the binary
+data.
+
+When -D is used, Intel BTS packets are displayed.
+
+To disable the display of Intel BTS packets, combine the -D option with
+--no-itrace.
+
+
+perf report
+===========
+
+By default, perf report will decode trace data found in the perf.data file.
+This can be further controlled by new option --itrace exactly the same as
+perf script.
+
+
+perf inject
+===========
+
+perf inject also accepts the --itrace option in which case tracing data is
+removed and replaced with the synthesized events. e.g.
+
+	perf inject --itrace -i perf.data -o perf.data.new

index a8be9f9d0462..2c55e1b336c5 100644
@@ -10,3 +10,4 @@ libperf-$(CONFIG_LIBDW_DWARF_UNWIND) += unwind-libdw.o
 
 libperf-$(CONFIG_AUXTRACE) += auxtrace.o
 libperf-$(CONFIG_AUXTRACE) += intel-pt.o
+libperf-$(CONFIG_AUXTRACE) += intel-bts.o

index fd11cc3ce780..79fe07158d00 100644
@@ -3,6 +3,7 @@
 #include <linux/perf_event.h>
 
 #include "../../util/intel-pt.h"
+#include "../../util/intel-bts.h"
 #include "../../util/pmu.h"
 
 struct perf_event_attr *perf_pmu__get_default_config(struct perf_pmu *pmu __maybe_unused)

@@ -10,6 +11,8 @@ struct perf_event_attr *perf_pmu__get_default_config(struct perf_pmu *pmu __mayb
 #ifdef HAVE_AUXTRACE_SUPPORT
 	if (!strcmp(pmu->name, INTEL_PT_PMU_NAME))
 		return intel_pt_pmu_default_config(pmu);
+	if (!strcmp(pmu->name, INTEL_BTS_PMU_NAME))
+		pmu->selectable = true;
 #endif
 	return NULL;
 }

index c20473d1369e..e912856cc4e5 100644
@@ -80,6 +80,7 @@ libperf-y += thread-stack.o
 libperf-$(CONFIG_AUXTRACE) += auxtrace.o
 libperf-$(CONFIG_AUXTRACE) += intel-pt-decoder/
 libperf-$(CONFIG_AUXTRACE) += intel-pt.o
+libperf-$(CONFIG_AUXTRACE) += intel-bts.o
 libperf-y += parse-branch-options.o
 
 libperf-$(CONFIG_LIBELF) += symbol-elf.o

index 0f0b7e11e2d9..a980e7c50ee0 100644
@@ -48,6 +48,7 @@
 #include "parse-options.h"
 
 #include "intel-pt.h"
+#include "intel-bts.h"
 
 int auxtrace_mmap__mmap(struct auxtrace_mmap *mm,
 			struct auxtrace_mmap_params *mp,

@@ -888,6 +889,8 @@ int perf_event__process_auxtrace_info(struct perf_tool *tool __maybe_unused,
 	switch (type) {
 	case PERF_AUXTRACE_INTEL_PT:
 		return intel_pt_process_auxtrace_info(event, session);
+	case PERF_AUXTRACE_INTEL_BTS:
+		return intel_bts_process_auxtrace_info(event, session);
 	case PERF_AUXTRACE_UNKNOWN:
 	default:
 		return -EINVAL;

index 7d12f33a3a06..bf72b77a588a 100644
@@ -40,6 +40,7 @@ struct events_stats;
 enum auxtrace_type {
 	PERF_AUXTRACE_UNKNOWN,
 	PERF_AUXTRACE_INTEL_PT,
+	PERF_AUXTRACE_INTEL_BTS,
 };
 
 enum itrace_period_type {

index 3c71138e7672..89c91a1a67e7 100644
@@ -462,10 +462,6 @@ static struct perf_pmu *pmu_lookup(const char *name)
 	LIST_HEAD(aliases);
 	__u32 type;
 
-	/* No support for intel_bts so disallow it */
-	if (!strcmp(name, "intel_bts"))
-		return NULL;
-
 	/*
 	 * The pmu data we store & need consists of the pmu
 	 * type value and format definitions. Load both right

2.1.0

From: Adrian Hunter <[email protected]>

perf script, report and inject all have the same itrace options. Put them into an asciidoc include file.

---
 tools/perf/Documentation/itrace.txt      | 22 ++++++++++++++++++++++
 tools/perf/Documentation/perf-inject.txt | 23 +----------------------
 tools/perf/Documentation/perf-report.txt | 23 +----------------------
 tools/perf/Documentation/perf-script.txt | 23 +----------------------
 4 files changed, 25 insertions(+), 66 deletions(-)
 create mode 100644 tools/perf/Documentation/itrace.txt

new file mode 100644
index 000000000000..2ff946677e3b
@@ -0,0 +1,22 @@
+		i	synthesize instructions events
+		b	synthesize branches events
+		c	synthesize branches events (calls only)
+		r	synthesize branches events (returns only)
+		x	synthesize transactions events
+		e	synthesize error events
+		d	create a debug log
+		g	synthesize a call chain (use with i or x)
+
+	The default is all events i.e. the same as --itrace=ibxe
+
+	In addition, the period (default 100000) for instructions events
+	can be specified in units of:
+
+		i	instructions
+		t	ticks
+		ms	milliseconds
+		us	microseconds
+		ns	nanoseconds (default)
+
+	Also the call chain size (default 16, max. 1024) for instructions or
+	transactions events can be specified.

index b876ae312699..0c721c3e37e1 100644
@@ -48,28 +48,7 @@ OPTIONS
 	Decode Instruction Tracing data, replacing it with synthesized events.
 	Options are:
 
-		i	synthesize instructions events
-		b	synthesize branches events
-		c	synthesize branches events (calls only)
-		r	synthesize branches events (returns only)
-		x	synthesize transactions events
-		e	synthesize error events
-		d	create a debug log
-		g	synthesize a call chain (use with i or x)
-
-	The default is all events i.e. the same as --itrace=ibxe
-
-	In addition, the period (default 100000) for instructions events
-	can be specified in units of:
-
-		i	instructions
-		t	ticks
-		ms	milliseconds
-		us	microseconds
-		ns	nanoseconds (default)
-
-	Also the call chain size (default 16, max. 1024) for instructions or
-	transactions events can be specified.
+include::itrace.txt[]
 
 SEE ALSO
 --------

index a18ba757a0ed..9c7981bfddad 100644
@@ -331,28 +331,7 @@ OPTIONS
 --itrace::
 	Options for decoding instruction tracing data. The options are:
 
-		i	synthesize instructions events
-		b	synthesize branches events
-		c	synthesize branches events (calls only)
-		r	synthesize branches events (returns only)
-		x	synthesize transactions events
-		e	synthesize error events
-		d	create a debug log
-		g	synthesize a call chain (use with i or x)
-
-	The default is all events i.e. the same as --itrace=ibxe
-
-	In addition, the period (default 100000) for instructions events
-	can be specified in units of:
-
-		i	instructions
-		t	ticks
-		ms	milliseconds
-		us	microseconds
-		ns	nanoseconds (default)
-
-	Also the call chain size (default 16, max. 1024) for instructions or
-	transactions events can be specified.
+include::itrace.txt[]
 
 	To disable decoding entirely, use --no-itrace.
 

index 8e9be1f9c1dd..c0d24791a7f3 100644
@@ -235,28 +235,7 @@ OPTIONS
 --itrace::
 	Options for decoding instruction tracing data. The options are:
 
-		i	synthesize instructions events
-		b	synthesize branches events
-		c	synthesize branches events (calls only)
-		r	synthesize branches events (returns only)
-		x	synthesize transactions events
-		e	synthesize error events
-		d	create a debug log
-		g	synthesize a call chain (use with i or x)
-
-	The default is all events i.e. the same as --itrace=ibxe
-
-	In addition, the period (default 100000) for instructions events
-	can be specified in units of:
-
-		i	instructions
-		t	ticks
-		ms	milliseconds
-		us	microseconds
-		ns	nanoseconds (default)
-
-	Also the call chain size (default 16, max. 1024) for instructions or
-	transactions events can be specified.
+include::itrace.txt[]
 
 	To disable decoding entirely, use --no-itrace.
 

2.1.0

From: Adrian Hunter <[email protected]>

Add a script to produce a call-graph from data exported to a postgresql database and derived from a processor trace event like intel_pt or intel_bts.

Refer to comments in the scripts call-graph-from-postgresql.py and export-to-postgresql.py for more details on how to set up the environment, install the required packages, etc.

Committer note:

An example of using this script with Intel PT:

  $ perf record -e intel_pt//u ls
  $ perf script -s ~/libexec/perf-core/scripts/python/export-to-postgresql.py pt_example branches calls
  2015-05-29 12:49:23.464364 Creating database...
  2015-05-29 12:49:26.281717 Writing to intermediate files...
  2015-05-29 12:49:27.190383 Copying to database...
  2015-05-29 12:49:28.140451 Removing intermediate files...
  2015-05-29 12:49:28.147451 Adding primary keys
  2015-05-29 12:49:28.655683 Adding foreign keys
  2015-05-29 12:49:29.365350 Done
  $ python tools/perf/scripts/python/call-graph-from-postgresql.py pt_example
  # The result is a GUI window with a tree representing a context-sensitive
  # call-graph.  Expanding a couple of levels of the tree and adjusting column
  # widths to suit will display something like:

Call Graph: pt_example
Call Path |Object |Count|Time(ns)|Time(%)|Branch Count|Branch Count(%)
v- ls

     v- 2638:2638
         v- _start                  ld-2.19.so    1   10074071  100.0        211135          100.0
           |- unknown               unknown       1      13198    0.1             1            0.0
           >- _dl_start             ld-2.19.so    1    1400980   13.9         19637            9.3
           >- _d_linit_internal     ld-2.19.so    1     448152    4.4         11094            5.3
           v-__libc_start_main@plt  ls            1    8211741   81.5        180397           85.4
              >- _dl_fixup          ld-2.19.so    1       7607    0.1           108            0.1
              >- __cxa_atexit       libc-2.19.so  1      11737    0.1            10            0.0
              >- __libc_csu_init    ls            1      10354    0.1            10            0.0
              |- _setjmp            libc-2.19.so  1          0    0.0             4            0.0
              v- main               ls            1    8182043   99.6        180254           99.9

---
 .../scripts/python/call-graph-from-postgresql.py   | 327 +++++++++++++++++++++
 tools/perf/scripts/python/export-to-postgresql.py  |  47 +++
 2 files changed, 374 insertions(+)
 create mode 100644 tools/perf/scripts/python/call-graph-from-postgresql.py

new file mode 100644
index 000000000000..e78fdc2a5a9d
@@ -0,0 +1,327 @@
+#!/usr/bin/python2
+# call-graph-from-postgresql.py: create call-graph from postgresql database
+# Copyright (c) 2014, Intel Corporation.
+#
+# This program is free software; you can redistribute it and/or modify it
+# under the terms and conditions of the GNU General Public License,
+# version 2, as published by the Free Software Foundation.
+#
+# This program is distributed in the hope it will be useful, but WITHOUT
+# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+# FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
+# more details.
+
+# To use this script you will need to have exported data using the
+# export-to-postgresql.py script.  Refer to that script for details.
+#
+# Following on from the example in the export-to-postgresql.py script, a
+# call-graph can be displayed for the pt_example database like this:
+#
+#	python tools/perf/scripts/python/call-graph-from-postgresql.py pt_example
+#
+# Note this script supports connecting to remote databases by setting hostname,
+# port, username, password, and dbname e.g.
+#
+#	python tools/perf/scripts/python/call-graph-from-postgresql.py "hostname=myhost username=myuser password=mypassword dbname=pt_example"
+#
+# The result is a GUI window with a tree representing a context-sensitive
+# call-graph.  Expanding a couple of levels of the tree and adjusting column
+# widths to suit will display something like:
+#
+#                                         Call Graph: pt_example
+# Call Path                          Object      Count   Time(ns)  Time(%)  Branch Count   Branch Count(%)
+# v- ls
+#     v- 2638:2638
+#         v- _start                  ld-2.19.so    1     10074071   100.0         211135            100.0
+#           |- unknown               unknown       1        13198     0.1              1              0.0
+#           >- _dl_start             ld-2.19.so    1      1400980    13.9          19637              9.3
+#           >- _d_linit_internal     ld-2.19.so    1       448152     4.4          11094              5.3
+#           v-__libc_start_main@plt  ls            1      8211741    81.5         180397             85.4
+#              >- _dl_fixup          ld-2.19.so    1         7607     0.1            108              0.1
+#              >- __cxa_atexit       libc-2.19.so  1        11737     0.1             10              0.0
+#              >- __libc_csu_init    ls            1        10354     0.1             10              0.0
+#              |- _setjmp            libc-2.19.so  1            0     0.0              4              0.0
+#              v- main               ls            1      8182043    99.6         180254             99.9
+#
+# Points to note:
+#	The top level is a command name (comm)
+#	The next level is a thread (pid:tid)
+#	Subsequent levels are functions
+#	'Count' is the number of calls
+#	'Time' is the elapsed time until the function returns
+#	Percentages are relative to the level above
+#	'Branch Count' is the total number of branches for that function and all
+#       functions that it calls
+
+import sys
+from PySide.QtCore import *
+from PySide.QtGui import *
+from PySide.QtSql import *
+from decimal import *
+
+class TreeItem():
+
+	def __init__(self, db, row, parent_item):
+		self.db = db
+		self.row = row
+		self.parent_item = parent_item
+		self.query_done = False;
+		self.child_count = 0
+		self.child_items = []
+		self.data = ["", "", "", "", "", "", ""]
+		self.comm_id = 0
+		self.thread_id = 0
+		self.call_path_id = 1
+		self.branch_count = 0
+		self.time = 0
+		if not parent_item:
+			self.setUpRoot()
+
+	def setUpRoot(self):
+		self.query_done = True
+		query = QSqlQuery(self.db)
+		ret = query.exec_('SELECT id, comm FROM comms')
+		if not ret:
+			raise Exception("Query failed: " + query.lastError().text())
+		while query.next():
+			if not query.value(0):
+				continue
+			child_item = TreeItem(self.db, self.child_count, self)
+			self.child_items.append(child_item)
+			self.child_count += 1
+			child_item.setUpLevel1(query.value(0), query.value(1))
+
+	def setUpLevel1(self, comm_id, comm):
+		self.query_done = True;
+		self.comm_id = comm_id
+		self.data[0] = comm
+		self.child_items = []
+		self.child_count = 0
+		query = QSqlQuery(self.db)
+		ret = query.exec_('SELECT thread_id, ( SELECT pid FROM threads WHERE id = thread_id ), ( SELECT tid FROM threads WHERE id = thread_id ) FROM comm_threads WHERE comm_id = ' + str(comm_id))
+		if not ret:
+			raise Exception("Query failed: " + query.lastError().text())
+		while query.next():
+			child_item = TreeItem(self.db, self.child_count, self)
+			self.child_items.append(child_item)
+			self.child_count += 1
+			child_item.setUpLevel2(comm_id, query.value(0), query.value(1), query.value(2))
+
+	def setUpLevel2(self, comm_id, thread_id, pid, tid):
+		self.comm_id = comm_id
+		self.thread_id = thread_id
+		self.data[0] = str(pid) + ":" + str(tid)
+
+	def getChildItem(self, row):
+		return self.child_items[row]
+
+	def getParentItem(self):
+		return self.parent_item
+
+	def getRow(self):
+		return self.row
+
+	def timePercent(self, b):
+		if not self.time:
+			return "0.0"
+		x = (b * Decimal(100)) / self.time
+		return str(x.quantize(Decimal('.1'), rounding=ROUND_HALF_UP))
+
+	def branchPercent(self, b):
+		if not self.branch_count:
+			return "0.0"
+		x = (b * Decimal(100)) / self.branch_count
+		return str(x.quantize(Decimal('.1'), rounding=ROUND_HALF_UP))
+
+	def addChild(self, call_path_id, name, dso, count, time, branch_count):
+		child_item = TreeItem(self.db, self.child_count, self)
+		child_item.comm_id = self.comm_id
+		child_item.thread_id = self.thread_id
+		child_item.call_path_id = call_path_id
+		child_item.branch_count = branch_count
+		child_item.time = time
+		child_item.data[0] = name
+		if dso == "[kernel.kallsyms]":
+			dso = "[kernel]"
+		child_item.data[1] = dso
+		child_item.data[2] = str(count)
+		child_item.data[3] = str(time)
+		child_item.data[4] = self.timePercent(time)
+		child_item.data[5] = str(branch_count)
+		child_item.data[6] = self.branchPercent(branch_count)
+		self.child_items.append(child_item)
+		self.child_count += 1
+
+	def selectCalls(self):
+		self.query_done = True;
+		query = QSqlQuery(self.db)
+		ret = query.exec_('SELECT id, call_path_id, branch_count, call_time, return_time, '
+				  '( SELECT name FROM symbols WHERE id = ( SELECT symbol_id FROM call_paths WHERE id = call_path_id ) ), '
+				  '( SELECT short_name FROM dsos WHERE id = ( SELECT dso_id FROM symbols WHERE id = ( SELECT symbol_id FROM call_paths WHERE id = call_path_id ) ) ), '
+				  '( SELECT ip FROM call_paths where id = call_path_id ) '
+				  'FROM calls WHERE parent_call_path_id = ' + str(self.call_path_id) + ' AND comm_id = ' + str(self.comm_id) + ' AND thread_id = ' + str(self.thread_id) +
+				  'ORDER BY call_path_id')
+		if not ret:
+			raise Exception("Query failed: " + query.lastError().text())
+		last_call_path_id = 0
+		name = ""
+		dso = ""
+		count = 0
+		branch_count = 0
+		total_branch_count = 0
+		time = 0
+		total_time = 0
+		while query.next():
+			if query.value(1) == last_call_path_id:
+				count += 1
+				branch_count += query.value(2)
+				time += query.value(4) - query.value(3)
+			else:
+				if count:
+					self.addChild(last_call_path_id, name, dso, count, time, branch_count)
+				last_call_path_id = query.value(1)
+				name = query.value(5)
+				dso = query.value(6)
+				count = 1
+				total_branch_count += branch_count
+				total_time += time
+				branch_count = query.value(2)
+				time = query.value(4) - query.value(3)
+		if count:
+			self.addChild(last_call_path_id, name, dso, count, time, branch_count)
+		total_branch_count += branch_count
+		total_time += time
+		# Top level does not have time or branch count, so fix that here
+		if total_branch_count > self.branch_count:
+			self.branch_count = total_branch_count
+			if self.branch_count:
+				for child_item in self.child_items:
+					child_item.data[6] = self.branchPercent(child_item.branch_count)
+		if total_time > self.time:
+			self.time = total_time
+			if self.time:
+				for child_item in self.child_items:
+					child_item.data[4] = self.timePercent(child_item.time)
+
+	def childCount(self):
+		if not self.query_done:
+			self.selectCalls()
+		return self.child_count
+
+	def columnCount(self):
+		return 7
+
+	def columnHeader(self, column):
+		headers = ["Call Path", "Object", "Count ", "Time (ns) ", "Time (%) ", "Branch Count ", "Branch Count (%) "]
+		return headers[column]
+
+	def getData(self, column):
+		return self.data[column]
+
+class TreeModel(QAbstractItemModel):
+
+	def __init__(self, db, parent=None):
+		super(TreeModel, self).__init__(parent)
+		self.db = db
+		self.root = TreeItem(db, 0, None)
+
+	def columnCount(self, parent):
+		return self.root.columnCount()
+
+	def rowCount(self, parent):
+		if parent.isValid():
+			parent_item = parent.internalPointer()
+		else:
+			parent_item = self.root
+		return parent_item.childCount()
+
+	def headerData(self, section, orientation, role):
+		if role == Qt.TextAlignmentRole:
+			if section > 1:
+				return Qt.AlignRight
+		if role != Qt.DisplayRole:
+			return None
+		if orientation != Qt.Horizontal:
+			return None
+		return self.root.columnHeader(section)
+
+	def parent(self, child):
+		child_item = child.internalPointer()
+		if child_item is self.root:
+			return QModelIndex()
+		parent_item = child_item.getParentItem()
+		return self.createIndex(parent_item.getRow(), 0, parent_item)
+
+	def index(self, row, column, parent):
+		if parent.isValid():
+			parent_item = parent.internalPointer()
+		else:
+			parent_item = self.root
+		child_item = parent_item.getChildItem(row)
+		return self.createIndex(row, column, child_item)
+
+	def data(self, index, role):
+		if role == Qt.TextAlignmentRole:
+			if index.column() > 1:
+				return Qt.AlignRight
+		if role != Qt.DisplayRole:
+			return None
+		index_item = index.internalPointer()
+		return index_item.getData(index.column())
+
+class MainWindow(QMainWindow):
+
+	def __init__(self, db, dbname, parent=None):
+		super(MainWindow, self).__init__(parent)
+
+		self.setObjectName("MainWindow")
+		self.setWindowTitle("Call Graph: " + dbname)
+		self.move(100, 100)
+		self.resize(800, 600)
+		style = self.style()
+		icon = style.standardIcon(QStyle.SP_MessageBoxInformation)
+		self.setWindowIcon(icon);
+
+		self.model = TreeModel(db)
+
+		self.view = QTreeView()
+		self.view.setModel(self.model)
+
+		self.setCentralWidget(self.view)
+
+if __name__ == '__main__':
+	if (len(sys.argv) < 2):
+		print >> sys.stderr, "Usage is: call-graph-from-postgresql.py <database name>"
+		raise Exception("Too few arguments")
+
+	dbname = sys.argv[1]
+
+	db = QSqlDatabase.addDatabase('QPSQL')
+
+	opts = dbname.split()
+	for opt in opts:
+		if '=' in opt:
+			opt = opt.split('=')
+			if opt[0] == 'hostname':
+				db.setHostName(opt[1])
+			elif opt[0] == 'port':
+				db.setPort(int(opt[1]))
+			elif opt[0] == 'username':
+				db.setUserName(opt[1])
+			elif opt[0] == 'password':
+				db.setPassword(opt[1])
+			elif opt[0] == 'dbname':
+				dbname = opt[1]
+		else:
+			dbname = opt
+
+	db.setDatabaseName(dbname)
+	if not db.open():
+		raise Exception("Failed to open database " + dbname + " error: " + db.lastError().text())
+
+	app = QApplication(sys.argv)
+	window = MainWindow(db, dbname)
+	window.show()
+	err = app.exec_()
+	db.close()
+	sys.exit(err)

2.1.0

From: Arnaldo Carvalho de Melo <[email protected]>

Map clone was written before we introduced reference counts for maps and dsos, so all that was needed was just a copy and then we would insert it into the new map_groups instance.

Fix it by, after copying, initializing the map->refcnt, grabbing a struct dso refcount and resetting pointers that may be used to determine if a map, when deleted, is in a rb_tree.

---
 tools/perf/util/map.c | 13 +++++++++++--
 1 file changed, 11 insertions(+), 2 deletions(-)

index ce37e95bc513..b1c475d9b240 100644
@@ -348,9 +348,18 @@ struct symbol *map__find_symbol_by_name(struct map *map, const char *name,
 	return dso__find_symbol_by_name(map->dso, map->type, name);
 }
 
-struct map *map__clone(struct map *map)
+struct map *map__clone(struct map *from)
 {
-	return memdup(map, sizeof(*map));
+	struct map *map = memdup(from, sizeof(*map));
+
+	if (map != NULL) {
+		atomic_set(&map->refcnt, 1);
+		RB_CLEAR_NODE(&map->rb_node);
+		dso__get(map->dso);
+		map->groups = NULL;
+	}
+
+	return map;
 }
 
 int map__overlap(struct map *l, struct map *r)

2.1.0

From: Wang Nan <[email protected]>

A problem can occur in a statically linked perf when vmlinux can be found:

 # perf probe --add sys_epoll_pwait
 probe-definition(0): sys_epoll_pwait
 symbol:sys_epoll_pwait file:(null) line:0 offset:0 return:0 lazy:(null)
 0 arguments
 Looking at the vmlinux_path (7 entries long)
 Using /lib/modules/4.2.0-rc1+/build/vmlinux for symbols
 Open Debuginfo file: /lib/modules/4.2.0-rc1+/build/vmlinux
 Try to find probe point from debuginfo.
 Symbol sys_epoll_pwait address found : ffffffff8122bd40
 Matched function: SyS_epoll_pwait
 Failed to get call frame on 0xffffffff8122bd40
 An error occurred in debuginfo analysis (-2).
   Error: Failed to add events. Reason: No such file or directory (Code: -2)

The reason is caused by libdw that, if libdw is statically linked, it can't load libebl_{arch}.so reliable.

In this case it is still possible to get the address from /proc/kalksyms. However, perf tries that only when libdw returns -EBADF.

This patch gives it another chance to utilize symbol table, even if libdw returns an error code other than -EBADF.

After applying this patch:

 # perf probe -nv --add sys_epoll_pwait
 probe-definition(0): sys_epoll_pwait
 symbol:sys_epoll_pwait file:(null) line:0 offset:0 return:0 lazy:(null)
 0 arguments
 Looking at the vmlinux_path (7 entries long)
 Using /lib/modules/4.2.0-rc1+/build/vmlinux for symbols
 Open Debuginfo file: /lib/modules/4.2.0-rc1+/build/vmlinux
 Try to find probe point from debuginfo.
 Symbol sys_epoll_pwait address found : ffffffff8122bd40
 Matched function: SyS_epoll_pwait
 Failed to get call frame on 0xffffffff8122bd40
 An error occurred in debuginfo analysis (-2).
 Trying to use symbols.
 Opening /sys/kernel/debug/tracing/kprobe_events write=1
 Added new event:
 Writing event: p:probe/sys_epoll_pwait _text+2276672
   probe:sys_epoll_pwait (on sys_epoll_pwait)

You can now use it in all perf tools, such as:

perf record -e probe:sys_epoll_pwait -aR sleep 1

Although libdw returns an error (Failed to get call frame), perf tries symbol table and finally gets correct address.

---
 tools/perf/util/probe-event.c | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

index fe4941a94a25..f07374bc9c5a 100644
@@ -705,9 +705,10 @@ static int try_to_find_probe_trace_events(struct perf_probe_event *pev,
 	}
 	/* Error path : ntevs < 0 */
 	pr_debug("An error occurred in debuginfo analysis (%d).\n", ntevs);
-	if (ntevs == -EBADF) {
-		pr_warning("Warning: No dwarf info found in the vmlinux - "
-			"please rebuild kernel with CONFIG_DEBUG_INFO=y.\n");
+	if (ntevs < 0) {
+		if (ntevs == -EBADF)
+			pr_warning("Warning: No dwarf info found in the vmlinux - "
+				"please rebuild kernel with CONFIG_DEBUG_INFO=y.\n");
 		if (!need_dwarf) {
 			pr_debug("Trying to use symbols.\n");
 			return 0;

2.1.0

Pulled, thanks a lot Arnaldo!

Ingo