perf: Introduce bts sub commands

Hi,

This patch series provides the commands 'perf bts record' and 'perf bts trace' version 2. These commands can record and analyze BTS (Branch Trace Store) log. And, provide the interface to use BTS log for application developers.

BTS is a facility of Intel x86 processors, which can record the address of 'branch to/from' on every branch/jump instruction and interrupt. This facility is very useful for developers to test their software. For example, coverage test, execution path analysis, dynamic step count ...etc. Also, those tools can have a very big advantage that they don't require any changes of the target executable binaries.

But, there are few applications using BTS. Reasons I guess are ...
- Few people know what BTS is.
- Few people know how to use BTS on Linux box.
- It's hard to analyze the BTS log because it includes just a series of addresses.

So, I want to provide a user-friendly interface to BTS for application developers.

About new sub commands
========================
'perf bts record' provides the easy way to record bts log. Usage is 'perf bts record <command>'. This command is just an alias to 'perf record -e branches:u -c 1 <command>'. But, new one is more simple and more intuitive.

'perf bts trace' can parse and analyze recorded bts log and print various information of execution path. This command can show address, pid, command name, function+offset, file path of elf.
You can choose the printed information with option.

Example: 'perf bts trace'
function+offset

irq_return+0x0  => _start+0x0
irq_return+0x0  => _start+0x0
_start+0x3      => _dl_start+0x0
irq_return+0x0  => _dl_start+0x0
irq_return+0x0  => _dl_start+0x26
irq_return+0x0  => _dl_start+0x2d
_dl_start+0x71  => _dl_start+0x93
_dl_start+0x97  => _dl_start+0x78

...

This is the default behavior of 'perf bts trace'. It prints function+offset.

Example2: 'perf bts -cas trace'
command address function+offset

ls      0xffffffff8146fe0e irq_return+0x0  => ls   0x0000003806200b20 _start+0x0
ls      0xffffffff8146fe0e irq_return+0x0  => ls   0x0000003806200b20 _start+0x0
ls      0x0000003806200b23 _start+0x3      => ls   0x0000003806204910 _dl_start+0x0
ls      0xffffffff8146fe0e irq_return+0x0  => ls   0x0000003806204910 _dl_start+0x0
ls      0xffffffff8146fe0e irq_return+0x0  => ls   0x0000003806204936 _dl_start+0x26
ls      0xffffffff8146fe0e irq_return+0x0  => ls   0x000000380620493d _dl_start+0x2d
ls      0x0000003806204981 _dl_start+0x71  => ls   0x00000038062049a3 _dl_start+0x93
ls      0x00000038062049a7 _dl_start+0x97  => ls   0x0000003806204988 _dl_start+0x78

...

In the future, I'd like to make this more informative. For example
- Show source file path
- Show line number
- Show inlined function name
- Draw call graph
- Browse source code and coloring
- Make bts record fast
and more!

Changes in V2:
- Update to the latest -tip tree
- add bts explanation to the subcommand list
- remove the patch already merged (add OPT_CALLBACK_DEFAULT_NOOPT)
- add comments
- add new function to the todo list

Thanks,

---

Akihiro Nagai (6):
perf bts trace: add print all option
perf bts trace: print function+offset
perf bts trace: print file path of the executed elf perf bts trace: print pid and command
perf bts: Introduce new sub command 'perf bts trace'
perf: Introduce perf sub command 'bts record'

 tools/perf/Documentation/perf-bts.txt |   53 ++++++
 tools/perf/Makefile                   |    1 
 tools/perf/builtin-bts.c              |  301 +++++++++++++++++++++++++++++++++
 tools/perf/builtin.h                  |    1 
 tools/perf/command-list.txt           |    1 
 tools/perf/perf.c                     |    1 
 6 files changed, 358 insertions(+), 0 deletions(-)
 create mode 100644 tools/perf/Documentation/perf-bts.txt
 create mode 100644 tools/perf/builtin-bts.c

Akihiro Nagai ([email protected])

Introduce the easy way to record bts log, 'perf bts record'. This command can record the bts log while specified command is executing, and save to the file "perf.data"

Usage:
perf bts record <tracee command>

Example:

  # perf bts record ls -l
    (ls -l outputs)
  [ perf record: Woken up 1 times to write data ]
  [ perf record: Captured and wrote 0.007 MB perf.data (~320 samples) ]
  # ls
    perf.data

Changes in V2:
- Update to the latest -tip tree
- add bts explanation to the subcommand list

---

 tools/perf/Documentation/perf-bts.txt |   24 +++++++++++++
 tools/perf/Makefile                   |    1 +
 tools/perf/builtin-bts.c              |   62 +++++++++++++++++++++++++++++++++
 tools/perf/builtin.h                  |    1 +
 tools/perf/command-list.txt           |    1 +
 tools/perf/perf.c                     |    1 +
 6 files changed, 90 insertions(+), 0 deletions(-)
 create mode 100644 tools/perf/Documentation/perf-bts.txt
 create mode 100644 tools/perf/builtin-bts.c

new file mode 100644
index 0000000..55a2fe6
@@ -0,0 +1,24 @@
+perf-bts(1)
+==============
+
+NAME
+----
+perf-bts - Record branch-trace-store log
+
+SYNOPSIS
+--------
+[verse]
+'perf bts' record <command>
+
+DESCRIPTION
+-----------
+This command can record branch-trace-store log.
+Branch-trace-store is a facility of processors. It can record
+address of branch to/from on every branch instruction and interrupt.
+
+'perf bts record <command>' records branch-trace-store log while specified
+command is executing. And, save to the file "perf.data".
+
+SEE ALSO
+--------
+linkperf:perf-record[1]

index ac6692c..cd3a8df 100644
@@ -502,6 +502,7 @@ BUILTIN_OBJS += $(OUTPUT)builtin-lock.o
 BUILTIN_OBJS += $(OUTPUT)builtin-kvm.o
 BUILTIN_OBJS += $(OUTPUT)builtin-test.o
 BUILTIN_OBJS += $(OUTPUT)builtin-inject.o
+BUILTIN_OBJS += $(OUTPUT)builtin-bts.o
 
 PERFLIBS = $(LIB_FILE)
 

index c7798c7..11ed837 100644
@@ -35,5 +35,6 @@ extern int cmd_lock(int argc, const char **argv, const char *prefix);
 extern int cmd_kvm(int argc, const char **argv, const char *prefix);
 extern int cmd_test(int argc, const char **argv, const char *prefix);
 extern int cmd_inject(int argc, const char **argv, const char *prefix);
+extern int cmd_bts(int argc, const char **argv, const char *prefix);
 
 #endif

index 16b5088..956acea 100644
@@ -22,3 +22,4 @@ perf-kmem			mainporcelain common
 perf-lock			mainporcelain common
 perf-kvm			mainporcelain common
 perf-test			mainporcelain common
+perf-bts			mainporcelain common

index 595d0f4..4f4a98a 100644
@@ -331,6 +331,7 @@ static void handle_internal_command(int argc, const char **argv)
 		{ "kvm",	cmd_kvm,	0 },
 		{ "test",	cmd_test,	0 },
 		{ "inject",	cmd_inject,	0 },
+		{ "bts",	cmd_bts,	0 },
 	};
 	unsigned int i;
 	static const char ext[] = STRIP_EXTENSION;

Introduce new sub command 'perf bts trace'. This command can parse and print bts log recorded by 'perf bts record'.

Usage:
- First, record the bts log 'perf bts record <command>'
- Second, parse and print bts log 'perf bts trace'

Output:
0xffffffff8146fe0e => 0x0000003806200b20
0x0000003806200b23 => 0x0000003806204910
0xffffffff8146fe0e => 0x0000003806204910
0xffffffff8146fe0e => 0x0000003806204936
0xffffffff8146fe0e => 0x000000380620493d
0x0000003806204981 => 0x00000038062049a3
0x00000038062049a7 => 0x0000003806204988
...

Changes in V2:
- Update to the latest -tip tree

---

 tools/perf/Documentation/perf-bts.txt |   14 ++++++--
 tools/perf/builtin-bts.c              |   56 +++++++++++++++++++++++++++++++--
 2 files changed, 64 insertions(+), 6 deletions(-)

index 55a2fe6..5920dcc 100644
@@ -3,22 +3,30 @@ perf-bts(1)
 
 NAME
 ----
-perf-bts - Record branch-trace-store log
+perf-bts - Record and print branch-trace-store log
 
 SYNOPSIS
 --------
 [verse]
-'perf bts' record <command>
+'perf bts' [<options>] {record|trace}
 
 DESCRIPTION
 -----------
-This command can record branch-trace-store log.
+This command can record and print branch-trace-store log.
 Branch-trace-store is a facility of processors. It can record
 address of branch to/from on every branch instruction and interrupt.
 
 'perf bts record <command>' records branch-trace-store log while specified
 command is executing. And, save to the file "perf.data".
 
+'perf bts trace' parses recorded branch-trace-store log and prints it.
+
+OPTIONS
+-------
+-i::
+--input=::
+        Specify input file name to analyze.
+
 SEE ALSO
 --------
 linkperf:perf-record[1]

That would grow the data size for little gain, as long as you only record BTS data into the buffer the current bits should work fine.

Indeed.

In the longer term though, I think we need a specific branch set record.

Currently for every branch pair we create a new event with all the headers, so the pid, time, etc... are all repeated for every entries.

We rather need a single record everytime we flush the bts buffer to the perf buffer.

We also don't want arch specific data interfaces, so we need to iterate the bts buffer and copy the stuff anyway, and if you don't want the time and pid bits don't set those PERF_SAMPLE bits.

But we may actually want the time and pid bits.

This could be a PERF_SAMPLE_RAW may be?

Well clearly not ;-)

But maybe we can do something like: PERF_RECORD_SAMPLES (note the plural):

struct {
	struct perf_event_header		header;

	u64					nr;
	u32					common_type;
	u32					data_type;

	struct perf_sample			common;
	struct perf_sample			data[nr];
}

Where struct perf_sample is PERF_RECORD_SAMPLE without the perf_event_header bit.

Where we can split the many samples into a piece that is the same for all perf_samples::common, where the content specified by the PERF_SAMPLE_ bits from ::common_type, and the the rest lives in data[] specified by the PERF_SAMPLE_ bits from ::data_type.

Well, yeah but that involves some new corner cases in both the kernel and userspace.

What about a generic branch record like:

struct branch {
	u64 nr;
	struct {
		u64 from;
		u64 to;
	}[nr]
}

This is going to be useful also when one day we'll support the function tracer, lbr and so...

Hardly.

No, since that suffers the exact same problem you currently have, no TIME,TID,etc.. Nor is it quite usable for LBR since there is no clear means of associating it with a previous PERF_RECORD_SAMPLE.

(LBR really is quite different from BTS)

(2010/12/22 3:31), Frederic Weisbecker wrote:
[...]

Exactly.
I'll add a check code of PERF_SAMPLE_ID there.

And, I found the problem that perf cannot handle the data including multiple event types. I executed following command to make perf.data includes two event types: hardware and software event.

 # perf record -e branches:u -c 1 -d -e raw_syscalls:sys_enter ls
 (... ls outputs)
[ perf record: Woken up 18 times to write data ]
[ perf record: Captured and wrote 4.468 MB perf.data (~195216 samples) ]

 # perf bts trace
  Fatal: non matching sample_type

It results in error. Other perf subcommands also failed on this recorded data. For example, perf annotate, perf script, perf report.

In the future, I would like to analyze BTS log and other type events at the same time.

Agreed.

Thank you for your advise!

------------------------------------
Akihiro Nagai
Email: [email protected]

Provide the function of printing pid and command name to 'perf bts trace'. Users can select items to print with options. For example,
'perf bts -p trace' prints only pid,
'perf bts -ac trace' prints address and comamnd name. 'perf bts trace' prints only address (default)

This is output sample (perf bts -ac trace):

command      address
ls           0xffffffff8146fe0e => ls           0x0000003806200b20
ls           0xffffffff8146fe0e => ls           0x0000003806200b20
ls           0x0000003806200b23 => ls           0x0000003806204910
ls           0xffffffff8146fe0e => ls           0x0000003806204910
ls           0xffffffff8146fe0e => ls           0x0000003806204936
ls           0xffffffff8146fe0e => ls           0x000000380620493d
ls           0x0000003806204981 => ls           0x00000038062049a3
ls           0x00000038062049a7 => ls           0x0000003806204988

---

 tools/perf/Documentation/perf-bts.txt |   18 ++++-
 tools/perf/builtin-bts.c              |  128 +++++++++++++++++++++++++++++++--
 2 files changed, 137 insertions(+), 9 deletions(-)

index 5920dcc..56ddaa4 100644
@@ -3,7 +3,7 @@ perf-bts(1)
 
 NAME
 ----
-perf-bts - Record and print branch-trace-store log
+perf-bts - Record and analyze branch-trace-store log
 
 SYNOPSIS
 --------

@@ -12,20 +12,32 @@ SYNOPSIS
 
 DESCRIPTION
 -----------
-This command can record and print branch-trace-store log.
+This command can record and analyze branch-trace-store log.
 Branch-trace-store is a facility of processors. It can record
 address of branch to/from on every branch instruction and interrupt.
 
 'perf bts record <command>' records branch-trace-store log while specified
 command is executing. And, save to the file "perf.data".
 
-'perf bts trace' parses recorded branch-trace-store log and prints it.
+'perf bts trace' analyzes recorded branch-trace-store log and prints it.
+The command can select the item to print. For example,
+  'perf bts -a trace'	: prints only address
+  'perf bts -acp trace'	: prints address, command name and pid
 
 OPTIONS
 -------
 -i::
 --input=::
         Specify input file name to analyze.
+-a::
+--addr::
+	Print address. (default)
+-c::
+--comm::
+	Print command name.
+-p::
+--pid::
+	Print pid.
 
 SEE ALSO
 --------

Provide the function to print file path to the executed elf. Users can enable it with option '-e' or '--elfpath'. For example,
'perf bts -ae trace'
This command prints address and file path of elf. And, output is:

address elf_filepath
0xffffffff8145814e /lib/modules/2.6.37-rc6-tip+/build/vmlinux => 0x0000003806200b20 /lib64/ld-2.12.90.so 0xffffffff8145814e /lib/modules/2.6.37-rc6-tip+/build/vmlinux => 0x0000003806200b20 /lib64/ld-2.12.90.so
0x0000003806200b23 /lib64/ld-2.12.90.so => 0x0000003806204910 /lib64/ld-2.12.90.so
0xffffffff8145814e /lib/modules/2.6.37-rc6-tip+/build/vmlinux => 0x0000003806204910 /lib64/ld-2.12.90.so 0xffffffff8145814e /lib/modules/2.6.37-rc6-tip+/build/vmlinux => 0x0000003806204936 /lib64/ld-2.12.90.so 0xffffffff8145814e /lib/modules/2.6.37-rc6-tip+/build/vmlinux => 0x000000380620493d /lib64/ld-2.12.90.so
0x0000003806204981 /lib64/ld-2.12.90.so => 0x00000038062049a3 /lib64/ld-2.12.90.so
0x00000038062049a7 /lib64/ld-2.12.90.so => 0x0000003806204988 /lib64/ld-2.12.90.so
...

Changes in V2:
- add comment

---

 tools/perf/Documentation/perf-bts.txt |    3 +++
 tools/perf/builtin-bts.c              |   32 ++++++++++++++++++++++++++++++++
 2 files changed, 35 insertions(+), 0 deletions(-)

index 56ddaa4..acabffc 100644
@@ -38,6 +38,9 @@ OPTIONS
 -p::
 --pid::
 	Print pid.
+-e::
+--elfpath::
+	Print file path of executed elf.
 
 SEE ALSO
 --------

index 525bcd3..1e82c89 100644
@@ -20,6 +20,7 @@ struct exec_info {
 	u64		addr;		/* recorded address by bts */
 	pid_t		pid;		/* tracee process pid */
 	const char	*comm;		/* command name */
+	const char	*elfpath;	/* file path to elf */
 };
 
 #define EI_PID_UNSET	-1

@@ -28,6 +29,7 @@ struct exec_info {
 #define EI_FLAG_PRINT_ADDR		(1 << 0)
 #define EI_FLAG_PRINT_PID		(1 << 1)
 #define EI_FLAG_PRINT_COMM		(1 << 2)
+#define EI_FLAG_PRINT_ELFPATH		(1 << 3)
 
 /* it's used when no print item specified */
 #define EI_FLAG_PRINT_DEFAULT		EI_FLAG_PRINT_ADDR

@@ -77,6 +79,9 @@ static const struct option bts_options[] = {
 	OPT_CALLBACK_DEFAULT_NOOPT('c', "comm", NULL, NULL,
 				   "print command name", set_print_flags,
 				   (void *)EI_FLAG_PRINT_COMM),
+	OPT_CALLBACK_DEFAULT_NOOPT('e', "elfpath", NULL, NULL,
+				   "print file path to elf", set_print_flags,
+				   (void *)EI_FLAG_PRINT_ELFPATH),
 	OPT_END()
 };
 

@@ -91,6 +96,7 @@ static void fill_exec_info(struct exec_info *ei, struct perf_session *session,
 						event_t *event, u64 addr)
 {
 	struct thread *thread;
+	struct addr_location al;
 
 	ei->addr = addr;
 	ei->pid = event->ip.pid;

@@ -99,12 +105,26 @@ static void fill_exec_info(struct exec_info *ei, struct perf_session *session,
 	if (!thread)
 		return;
 	ei->comm = thread->comm;
+
+	/* get file path to elf */
+	memset(&al, 0, sizeof(al));
+	thread__find_addr_map(thread, session, PERF_RECORD_MISC_USER,
+			      MAP__FUNCTION, event->ip.pid, addr, &al);
+	if (!al.map)
+		thread__find_addr_map(thread, session, PERF_RECORD_MISC_KERNEL,
+				      MAP__FUNCTION, event->ip.pid, addr, &al);
+	if (!al.map)
+		return;
+	/* resolve vmlinux path */
+	map__load(al.map, NULL);
+	ei->elfpath = al.map->dso->long_name;
 }
 
 static void __print_exec_info(struct exec_info *ei)
 {
 	char pid[16];
 	const char *comm;
+	const char *elfpath;
 
 	if (print_flags & EI_FLAG_PRINT_PID) {
 		if (ei->pid == EI_PID_UNSET)

@@ -119,6 +139,10 @@ static void __print_exec_info(struct exec_info *ei)
 	}
 	if (print_flags & EI_FLAG_PRINT_ADDR)
 		printf(FMT_ADDR " ", ei->addr);
+	if (print_flags & EI_FLAG_PRINT_ELFPATH) {
+		elfpath = ei->elfpath ? : EI_UNKNOWN_TEXT;
+		printf("%-32s ", elfpath);
+	}
 }
 
 static void print_exec_info(struct exec_info *ei_from, struct exec_info *ei_to)

@@ -137,6 +161,8 @@ static void print_exec_info_header(void)
 		printf("%-12s ", "command");
 	if (print_flags & EI_FLAG_PRINT_ADDR)
 		printf("%-" FMT_ADDR_WIDTH "s ", "address");
+	if (print_flags & EI_FLAG_PRINT_ELFPATH)
+		printf("%-32s ", "elf_filepath");
 	printf("\n");
 }
 

@@ -160,6 +186,7 @@ static int process_sample_event(event_t *event, struct sample_data *sample,
 static struct perf_event_ops event_ops = {
 	.sample			= process_sample_event,
 	.comm			= event__process_comm,
+	.mmap			= event__process_mmap,
 	.ordered_samples	= false,
 };
 

@@ -177,6 +204,11 @@ static int __cmd_trace(void)
 	if (is_flags_unset(print_flags))
 		print_flags = EI_FLAG_PRINT_DEFAULT;
 
+	/* setup kernel maps to resolve vmlinux file path */
+	perf_session__create_kernel_maps(session);
+	if (symbol__init() < 0)
+		fprintf(stderr, "failed to initialize symbol.\n");
+
 	setup_pager();
 	print_exec_info_header();
 	perf_session__process_events(session, &event_ops);

Provide the function to print function+offset.
And, set it as the default behavior of 'perf bts trace'.
To use this function, users can also specify the option '-s' or '--symbol'.

Example: 'perf bts -as trace'
This command prints address and function+offset.

Output sample:
address function+offset
0xffffffff8146fe0e irq_return+0x0 => 0x00007fd4038e3b20 _start+0x0
...
0x000000380661ee79 __libc_start_main+0xf9 => 0x00000000004035c3 main+0x0

0xffffffff8146ef4e irq_return+0x0         => 0x00000000004035c3 main+0x0
0x00000000004035e8 main+0x25              => 0x000000000040bca0 set_program_name+0x0
0xffffffff8146ef4e irq_return+0x0         => 0x000000000040bca0 set_program_name+0x0
0x000000000040bcae set_program_name+0xe   => 0x00000000004023d0 strrchr@plt+0x0
0x00000000004023d0 strrchr@plt+0x0        => 0x00000000004023d6 strrchr@plt+0x6
...
0x0000000000403e0c main+0x849             => 0x00000000004021f0 exit@plt+0x0
0x00000000004021f0 exit@plt+0x0           => 0x00000000004021f6 exit@plt+0x6
0x00000000004021fb exit@plt+0xb           => 0x00000000004020d0 _init+0x18
0x00000000004020d6 _init+0x1e             => 0x00000038062149d0 _dl_runtime_resolve+0x0

...

---

 tools/perf/Documentation/perf-bts.txt |    5 +++-
 tools/perf/builtin-bts.c              |   45 +++++++++++++++++++++++++++++----
 2 files changed, 44 insertions(+), 6 deletions(-)

index acabffc..13ee862 100644
@@ -31,7 +31,7 @@ OPTIONS
         Specify input file name to analyze.
 -a::
 --addr::
-	Print address. (default)
+	Print address.
 -c::
 --comm::
 	Print command name.

@@ -41,6 +41,9 @@ OPTIONS
 -e::
 --elfpath::
 	Print file path of executed elf.
+-s::
+--symbol::
+	Print function name and offset. (default)
 
 SEE ALSO
 --------

For ease of use, add option printing all information '-A' or '--all'. This option can print following information.
- pid
- command name
- address
- function+offset
- elf file path

---

 tools/perf/Documentation/perf-bts.txt |    3 +++
 tools/perf/builtin-bts.c              |    6 ++++++
 2 files changed, 9 insertions(+), 0 deletions(-)

index 13ee862..c598dd2 100644
@@ -44,6 +44,9 @@ OPTIONS
 -s::
 --symbol::
 	Print function name and offset. (default)
+-A::
+--all::
+	Print all information.
 
 SEE ALSO
 --------

index be57571..bac4e83 100644
@@ -34,6 +34,9 @@ struct exec_info {
 #define EI_FLAG_PRINT_ELFPATH		(1 << 3)
 #define EI_FLAG_PRINT_SYMBOL		(1 << 4)
 
+/* all print flags are enabled */
+#define	 EI_FLAG_PRINT_ALL		-1UL
+
 /* it's used when no print item specified */
 #define EI_FLAG_PRINT_DEFAULT		EI_FLAG_PRINT_SYMBOL
 

@@ -92,6 +95,9 @@ static const struct option bts_options[] = {
 				   "print function+offset (default)",
 				   set_print_flags,
 				   (void *)EI_FLAG_PRINT_SYMBOL),
+	OPT_CALLBACK_DEFAULT_NOOPT('A', "all", NULL, NULL,
+				   "print all items", set_print_flags,
+				   (void *)EI_FLAG_PRINT_ALL),
 	OPT_END()
 };
 

And I would add:

- It has a big overhead, probably because the CPU spends some time to record the branches, but also because it generates a huge amount of traces to save periodically.

- It seems it's only available on intel CPUs (and some of them)

- It can't do branch type filtering like LBR does on some intel CPUs. Like recording only call and ret branches and ignore jmp, je, etc... which would make lower overhead if our goal is to trace only the function graph for example.

OTOH it has a great potential.

I would suggest to call it perf branch. Bts beeing only an underlying backend feature that makes it working. An implementation detail. For example, the function graph traces may join in the future to provide some branch details of the kernel, only in the function level of course.

That's a good start!

I suspect in the future, the default should be a function graph layout and only dive into in-proc branch details if requested by means of options.

But may be I'm biaised and in practice we need to output the branches right away. That said I suspect a function graph should give the first desired overview.

This can probably be done incrementally though, this output is already a nice feature.

Cool!

Very nice plans.

Thanks!