linux/tools/perf/builtin-record.c

726 lines
16 KiB
C
Raw Normal View History

/*
* builtin-record.c
*
* Builtin record command: Record the profile of a workload
* (or a CPU, or a PID) into the perf.data output file - for
* later analysis via perf report.
*/
#include "builtin.h"
#include "perf.h"
#include "util/util.h"
#include "util/parse-options.h"
#include "util/parse-events.h"
#include "util/string.h"
#include "util/header.h"
#include "util/event.h"
#include "util/debug.h"
perf tools: Add perf trace This adds perf trace into the set of perf tools. It is written to fetch the tracepoint samples from perf events and display them, according to the events information given by the debugfs files through the util/trace* tools. It is a rough first shot and doesn't yet handle the cpu, timestamps fields and some other things. Example: perf record -f -e workqueue:workqueue_execution:record -F 1 -a perf trace kblockd/0-236 [000] 0.000000: workqueue_execution: thread=:236 func=cfq_kick_queue+0x0 kondemand/0-360 [000] 0.000000: workqueue_execution: thread=:360 func=do_dbs_timer+0x0 kondemand/0-360 [000] 0.000000: workqueue_execution: thread=:360 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 kondemand/1-361 [000] 0.000000: workqueue_execution: thread=:361 func=do_dbs_timer+0x0 Todo: - A lot of things! Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Mike Galbraith <efault@gmx.de> Cc: "Luis Claudio R. Goncalves" <lclaudio@uudg.org> Cc: Clark Williams <williams@redhat.com> Cc: Jon Masters <jonathan@jonmasters.org> Cc: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca> Cc: Christoph Hellwig <hch@infradead.org> Cc: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com> Cc: Zhaolei <zhaolei@cn.fujitsu.com> Cc: Li Zefan <lizf@cn.fujitsu.com> Cc: Lai Jiangshan <laijs@cn.fujitsu.com> Cc: Masami Hiramatsu <mhiramat@redhat.com> Cc: Tom Zanussi <tzanussi@gmail.com> Cc: "Frank Ch. Eigler" <fche@redhat.com> Cc: Roland McGrath <roland@redhat.com> Cc: Jason Baron <jbaron@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Jiaying Zhang <jiayingz@google.com> Cc: Anton Blanchard <anton@samba.org> LKML-Reference: <1250518688-7207-4-git-send-email-fweisbec@gmail.com> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-08-17 14:18:08 +00:00
#include "util/trace-event.h"
#include <unistd.h>
#include <sched.h>
#define ALIGN(x, a) __ALIGN_MASK(x, (typeof(x))(a)-1)
#define __ALIGN_MASK(x, mask) (((x)+(mask))&~(mask))
static int fd[MAX_NR_CPUS][MAX_COUNTERS];
static long default_interval = 100000;
static int nr_cpus = 0;
static unsigned int page_size;
static unsigned int mmap_pages = 128;
static int freq = 0;
static int output;
static const char *output_name = "perf.data";
static int group = 0;
static unsigned int realtime_prio = 0;
static int raw_samples = 0;
static int system_wide = 0;
static int profile_cpu = -1;
static pid_t target_pid = -1;
static int inherit = 1;
static int force = 0;
static int append_file = 0;
static int call_graph = 0;
static int inherit_stat = 0;
static int no_samples = 0;
static int sample_address = 0;
static int multiplex = 0;
perf tools: Implement counter output multiplexing Finish the -M/--multiplex option implementation: - separate it out from group_fd - correctly set it via the ioctl and dont mmap counters that are multiplexed - modify the perf record event loop to deal with buffer-less counters. - remove the -g option from perf sched record - account for unordered events in perf sched latency - (add -f to perf sched record to ease measurements) - skip idle threads (pid==0) in latency output The result is better latency output by 'perf sched latency': ----------------------------------------------------------------------------------- Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | ----------------------------------------------------------------------------------- ksoftirqd/8 | 0.071 ms | 2 | avg: 0.458 ms | max: 0.913 ms | at-spi-registry | 0.609 ms | 19 | avg: 0.013 ms | max: 0.023 ms | perf | 3.316 ms | 16 | avg: 0.013 ms | max: 0.054 ms | Xorg | 0.392 ms | 19 | avg: 0.011 ms | max: 0.018 ms | sleep | 0.537 ms | 2 | avg: 0.009 ms | max: 0.009 ms | ----------------------------------------------------------------------------------- TOTAL: | 4.925 ms | 58 | --------------------------------------------- Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Mike Galbraith <efault@gmx.de> Cc: Paul Mackerras <paulus@samba.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 16:15:54 +00:00
static int multiplex_fd = -1;
static long samples;
static struct timeval last_read;
static struct timeval this_read;
static u64 bytes_written;
static struct pollfd event_array[MAX_NR_CPUS * MAX_COUNTERS];
static int nr_poll;
static int nr_cpu;
static int file_new = 1;
struct perf_header *header;
struct mmap_data {
int counter;
void *base;
unsigned int mask;
unsigned int prev;
};
static struct mmap_data mmap_array[MAX_NR_CPUS][MAX_COUNTERS];
static unsigned long mmap_read_head(struct mmap_data *md)
{
struct perf_counter_mmap_page *pc = md->base;
long head;
head = pc->data_head;
rmb();
return head;
}
static void mmap_write_tail(struct mmap_data *md, unsigned long tail)
{
struct perf_counter_mmap_page *pc = md->base;
/*
* ensure all reads are done before we write the tail out.
*/
/* mb(); */
pc->data_tail = tail;
}
static void write_output(void *buf, size_t size)
{
while (size) {
int ret = write(output, buf, size);
if (ret < 0)
die("failed to write");
size -= ret;
buf += ret;
bytes_written += ret;
}
}
static void mmap_read(struct mmap_data *md)
{
unsigned int head = mmap_read_head(md);
unsigned int old = md->prev;
unsigned char *data = md->base + page_size;
unsigned long size;
void *buf;
int diff;
gettimeofday(&this_read, NULL);
/*
* If we're further behind than half the buffer, there's a chance
* the writer will bite our tail and mess up the samples under us.
*
* If we somehow ended up ahead of the head, we got messed up.
*
* In either case, truncate and restart at head.
*/
diff = head - old;
if (diff < 0) {
struct timeval iv;
unsigned long msecs;
timersub(&this_read, &last_read, &iv);
msecs = iv.tv_sec*1000 + iv.tv_usec/1000;
fprintf(stderr, "WARNING: failed to keep up with mmap data."
" Last read %lu msecs ago.\n", msecs);
/*
* head points to a known good entry, start there.
*/
old = head;
}
last_read = this_read;
if (old != head)
samples++;
size = head - old;
if ((old & md->mask) + size != (head & md->mask)) {
buf = &data[old & md->mask];
size = md->mask + 1 - (old & md->mask);
old += size;
write_output(buf, size);
}
buf = &data[old & md->mask];
size = head - old;
old += size;
write_output(buf, size);
md->prev = old;
mmap_write_tail(md, old);
}
static volatile int done = 0;
static volatile int signr = -1;
static void sig_handler(int sig)
{
done = 1;
signr = sig;
}
static void sig_atexit(void)
{
if (signr == -1)
return;
signal(signr, SIG_DFL);
kill(getpid(), signr);
}
static pid_t pid_synthesize_comm_event(pid_t pid, int full)
{
struct comm_event comm_ev;
char filename[PATH_MAX];
char bf[BUFSIZ];
FILE *fp;
size_t size = 0;
DIR *tasks;
struct dirent dirent, *next;
pid_t tgid = 0;
snprintf(filename, sizeof(filename), "/proc/%d/status", pid);
fp = fopen(filename, "r");
if (fp == NULL) {
/*
* We raced with a task exiting - just return:
*/
if (verbose)
fprintf(stderr, "couldn't open %s\n", filename);
return 0;
}
memset(&comm_ev, 0, sizeof(comm_ev));
while (!comm_ev.comm[0] || !comm_ev.pid) {
if (fgets(bf, sizeof(bf), fp) == NULL)
goto out_failure;
if (memcmp(bf, "Name:", 5) == 0) {
char *name = bf + 5;
while (*name && isspace(*name))
++name;
size = strlen(name) - 1;
memcpy(comm_ev.comm, name, size++);
} else if (memcmp(bf, "Tgid:", 5) == 0) {
char *tgids = bf + 5;
while (*tgids && isspace(*tgids))
++tgids;
tgid = comm_ev.pid = atoi(tgids);
}
}
comm_ev.header.type = PERF_EVENT_COMM;
size = ALIGN(size, sizeof(u64));
comm_ev.header.size = sizeof(comm_ev) - (sizeof(comm_ev.comm) - size);
if (!full) {
comm_ev.tid = pid;
write_output(&comm_ev, comm_ev.header.size);
goto out_fclose;
}
snprintf(filename, sizeof(filename), "/proc/%d/task", pid);
tasks = opendir(filename);
while (!readdir_r(tasks, &dirent, &next) && next) {
char *end;
pid = strtol(dirent.d_name, &end, 10);
if (*end)
continue;
comm_ev.tid = pid;
write_output(&comm_ev, comm_ev.header.size);
}
closedir(tasks);
out_fclose:
fclose(fp);
return tgid;
out_failure:
fprintf(stderr, "couldn't get COMM and pgid, malformed %s\n",
filename);
exit(EXIT_FAILURE);
}
static void pid_synthesize_mmap_samples(pid_t pid, pid_t tgid)
{
char filename[PATH_MAX];
FILE *fp;
snprintf(filename, sizeof(filename), "/proc/%d/maps", pid);
fp = fopen(filename, "r");
if (fp == NULL) {
/*
* We raced with a task exiting - just return:
*/
if (verbose)
fprintf(stderr, "couldn't open %s\n", filename);
return;
}
while (1) {
char bf[BUFSIZ], *pbf = bf;
struct mmap_event mmap_ev = {
.header = { .type = PERF_EVENT_MMAP },
};
int n;
size_t size;
if (fgets(bf, sizeof(bf), fp) == NULL)
break;
/* 00400000-0040c000 r-xp 00000000 fd:01 41038 /bin/cat */
n = hex2u64(pbf, &mmap_ev.start);
if (n < 0)
continue;
pbf += n + 1;
n = hex2u64(pbf, &mmap_ev.len);
if (n < 0)
continue;
pbf += n + 3;
if (*pbf == 'x') { /* vm_exec */
char *execname = strchr(bf, '/');
/* Catch VDSO */
if (execname == NULL)
execname = strstr(bf, "[vdso]");
if (execname == NULL)
continue;
size = strlen(execname);
execname[size - 1] = '\0'; /* Remove \n */
memcpy(mmap_ev.filename, execname, size);
size = ALIGN(size, sizeof(u64));
mmap_ev.len -= mmap_ev.start;
mmap_ev.header.size = (sizeof(mmap_ev) -
(sizeof(mmap_ev.filename) - size));
mmap_ev.pid = tgid;
mmap_ev.tid = pid;
write_output(&mmap_ev, mmap_ev.header.size);
}
}
fclose(fp);
}
static void synthesize_all(void)
{
DIR *proc;
struct dirent dirent, *next;
proc = opendir("/proc");
while (!readdir_r(proc, &dirent, &next) && next) {
char *end;
pid_t pid, tgid;
pid = strtol(dirent.d_name, &end, 10);
if (*end) /* only interested in proper numerical dirents */
continue;
tgid = pid_synthesize_comm_event(pid, 1);
pid_synthesize_mmap_samples(pid, tgid);
}
closedir(proc);
}
static int group_fd;
static struct perf_header_attr *get_header_attr(struct perf_counter_attr *a, int nr)
{
struct perf_header_attr *h_attr;
if (nr < header->attrs) {
h_attr = header->attr[nr];
} else {
h_attr = perf_header_attr__new(a);
perf_header__add_attr(header, h_attr);
}
return h_attr;
}
static void create_counter(int counter, int cpu, pid_t pid)
{
struct perf_counter_attr *attr = attrs + counter;
struct perf_header_attr *h_attr;
int track = !counter; /* only the first counter needs these */
struct {
u64 count;
u64 time_enabled;
u64 time_running;
u64 id;
} read_data;
attr->read_format = PERF_FORMAT_TOTAL_TIME_ENABLED |
PERF_FORMAT_TOTAL_TIME_RUNNING |
PERF_FORMAT_ID;
attr->sample_type |= PERF_SAMPLE_IP | PERF_SAMPLE_TID;
if (freq) {
attr->sample_type |= PERF_SAMPLE_PERIOD;
attr->freq = 1;
attr->sample_freq = freq;
}
if (no_samples)
attr->sample_freq = 0;
if (inherit_stat)
attr->inherit_stat = 1;
if (sample_address)
attr->sample_type |= PERF_SAMPLE_ADDR;
if (call_graph)
attr->sample_type |= PERF_SAMPLE_CALLCHAIN;
perf trace: Sample the CPU too Sample, record, parse and print the CPU field - it had all zeroes before. Before (watch the second column, the CPU values): perf-32685 [000] 0.000000: sched_wakeup_new: task perf:32686 [120] success=1 [011] perf-32685 [000] 0.000000: sched_migrate_task: task perf:32685 [120] from: 1 to: 11 perf-32685 [000] 0.000000: sched_process_fork: parent perf:32685 child perf:32686 true-32686 [000] 0.000000: sched_wakeup: task migration/11:25 [0] success=1 [011] true-32686 [000] 0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015] true-32686 [000] 0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015] perf-32685 [000] 0.000000: sched_switch: task perf:32685 [120] (S) ==> swapper:0 [140] true-32686 [000] 0.000000: sched_switch: task perf:32686 [120] (R) ==> migration/11:25 [0] true-32686 [000] 0.000000: sched_switch: task perf:32686 [120] (R) ==> distccd:12793 [125] true-32686 [000] 0.000000: sched_switch: task true:32686 [120] (R) ==> distccd:12793 [125] true-32686 [000] 0.000000: sched_process_exit: task true:32686 [120] true-32686 [000] 0.000000: sched_stat_wait: task: distccd:12793 wait: 6767985949080 [ns] true-32686 [000] 0.000000: sched_stat_wait: task: distccd:12793 wait: 6767986139446 [ns] true-32686 [000] 0.000000: sched_stat_sleep: task: distccd:12793 sleep: 132844 [ns] true-32686 [000] 0.000000: sched_stat_sleep: task: distccd:12793 sleep: 131724 [ns] After: perf-32685 [001] 0.000000: sched_wakeup_new: task perf:32686 [120] success=1 [011] perf-32685 [001] 0.000000: sched_migrate_task: task perf:32685 [120] from: 1 to: 11 perf-32685 [001] 0.000000: sched_process_fork: parent perf:32685 child perf:32686 true-32686 [011] 0.000000: sched_wakeup: task migration/11:25 [0] success=1 [011] true-32686 [015] 0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015] true-32686 [015] 0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015] perf-32685 [001] 0.000000: sched_switch: task perf:32685 [120] (S) ==> swapper:0 [140] true-32686 [011] 0.000000: sched_switch: task perf:32686 [120] (R) ==> migration/11:25 [0] true-32686 [015] 0.000000: sched_switch: task perf:32686 [120] (R) ==> distccd:12793 [125] true-32686 [015] 0.000000: sched_switch: task true:32686 [120] (R) ==> distccd:12793 [125] true-32686 [015] 0.000000: sched_process_exit: task true:32686 [120] true-32686 [015] 0.000000: sched_stat_wait: task: distccd:12793 wait: 6767985949080 [ns] true-32686 [015] 0.000000: sched_stat_wait: task: distccd:12793 wait: 6767986139446 [ns] true-32686 [015] 0.000000: sched_stat_sleep: task: distccd:12793 sleep: 132844 [ns] true-32686 [015] 0.000000: sched_stat_sleep: task: distccd:12793 sleep: 131724 [ns] So we can now see how this workload migrated between CPUs. Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Paul Mackerras <paulus@samba.org> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Li Zefan <lizf@cn.fujitsu.com> Cc: Mike Galbraith <efault@gmx.de> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-02 18:20:38 +00:00
if (raw_samples) {
perf trace: Sample timestamps as well Before: perf-21082 [013] 0.000000: sched_wakeup_new: task perf:21083 [120] success=1 [015] perf-21082 [013] 0.000000: sched_migrate_task: task perf:21082 [120] from: 13 to: 15 perf-21082 [013] 0.000000: sched_process_fork: parent perf:21082 child perf:21083 true-21083 [015] 0.000000: sched_wakeup: task migration/15:33 [0] success=1 [015] perf-21082 [013] 0.000000: sched_switch: task perf:21082 [120] (S) ==> swapper:0 [140] true-21083 [015] 0.000000: sched_switch: task perf:21083 [120] (R) ==> migration/15:33 [0] true-21083 [011] 0.000000: sched_process_exit: task true:21083 [120] After: perf-21082 [013] 14674.797613: sched_wakeup_new: task perf:21083 [120] success=1 [015] perf-21082 [013] 14674.797506: sched_migrate_task: task perf:21082 [120] from: 13 to: 15 perf-21082 [013] 14674.797610: sched_process_fork: parent perf:21082 child perf:21083 true-21083 [015] 14674.797725: sched_wakeup: task migration/15:33 [0] success=1 [015] perf-21082 [013] 14674.797722: sched_switch: task perf:21082 [120] (S) ==> swapper:0 [140] true-21083 [015] 14674.797729: sched_switch: task perf:21083 [120] (R) ==> migration/15:33 [0] true-21083 [011] 14674.798159: sched_process_exit: task true:21083 [120] Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Mike Galbraith <efault@gmx.de> Cc: Paul Mackerras <paulus@samba.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-03 10:00:22 +00:00
attr->sample_type |= PERF_SAMPLE_TIME;
attr->sample_type |= PERF_SAMPLE_RAW;
perf trace: Sample the CPU too Sample, record, parse and print the CPU field - it had all zeroes before. Before (watch the second column, the CPU values): perf-32685 [000] 0.000000: sched_wakeup_new: task perf:32686 [120] success=1 [011] perf-32685 [000] 0.000000: sched_migrate_task: task perf:32685 [120] from: 1 to: 11 perf-32685 [000] 0.000000: sched_process_fork: parent perf:32685 child perf:32686 true-32686 [000] 0.000000: sched_wakeup: task migration/11:25 [0] success=1 [011] true-32686 [000] 0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015] true-32686 [000] 0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015] perf-32685 [000] 0.000000: sched_switch: task perf:32685 [120] (S) ==> swapper:0 [140] true-32686 [000] 0.000000: sched_switch: task perf:32686 [120] (R) ==> migration/11:25 [0] true-32686 [000] 0.000000: sched_switch: task perf:32686 [120] (R) ==> distccd:12793 [125] true-32686 [000] 0.000000: sched_switch: task true:32686 [120] (R) ==> distccd:12793 [125] true-32686 [000] 0.000000: sched_process_exit: task true:32686 [120] true-32686 [000] 0.000000: sched_stat_wait: task: distccd:12793 wait: 6767985949080 [ns] true-32686 [000] 0.000000: sched_stat_wait: task: distccd:12793 wait: 6767986139446 [ns] true-32686 [000] 0.000000: sched_stat_sleep: task: distccd:12793 sleep: 132844 [ns] true-32686 [000] 0.000000: sched_stat_sleep: task: distccd:12793 sleep: 131724 [ns] After: perf-32685 [001] 0.000000: sched_wakeup_new: task perf:32686 [120] success=1 [011] perf-32685 [001] 0.000000: sched_migrate_task: task perf:32685 [120] from: 1 to: 11 perf-32685 [001] 0.000000: sched_process_fork: parent perf:32685 child perf:32686 true-32686 [011] 0.000000: sched_wakeup: task migration/11:25 [0] success=1 [011] true-32686 [015] 0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015] true-32686 [015] 0.000000: sched_wakeup: task distccd:12793 [125] success=1 [015] perf-32685 [001] 0.000000: sched_switch: task perf:32685 [120] (S) ==> swapper:0 [140] true-32686 [011] 0.000000: sched_switch: task perf:32686 [120] (R) ==> migration/11:25 [0] true-32686 [015] 0.000000: sched_switch: task perf:32686 [120] (R) ==> distccd:12793 [125] true-32686 [015] 0.000000: sched_switch: task true:32686 [120] (R) ==> distccd:12793 [125] true-32686 [015] 0.000000: sched_process_exit: task true:32686 [120] true-32686 [015] 0.000000: sched_stat_wait: task: distccd:12793 wait: 6767985949080 [ns] true-32686 [015] 0.000000: sched_stat_wait: task: distccd:12793 wait: 6767986139446 [ns] true-32686 [015] 0.000000: sched_stat_sleep: task: distccd:12793 sleep: 132844 [ns] true-32686 [015] 0.000000: sched_stat_sleep: task: distccd:12793 sleep: 131724 [ns] So we can now see how this workload migrated between CPUs. Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Paul Mackerras <paulus@samba.org> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Li Zefan <lizf@cn.fujitsu.com> Cc: Mike Galbraith <efault@gmx.de> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-02 18:20:38 +00:00
attr->sample_type |= PERF_SAMPLE_CPU;
}
perf_counter: Fix/complete ftrace event records sampling This patch implements the kernel side support for ftrace event record sampling. A new counter sampling attribute is added: PERF_SAMPLE_TP_RECORD which requests ftrace events record sampling. In this case if a PERF_TYPE_TRACEPOINT counter is active and a tracepoint fires, we emit the tracepoint binary record to the perfcounter event buffer, as a sample. Result, after setting PERF_SAMPLE_TP_RECORD attribute from perf record: perf record -f -F 1 -a -e workqueue:workqueue_execution perf report -D 0x21e18 [0x48]: event: 9 . . ... raw event: size 72 bytes . 0000: 09 00 00 00 01 00 48 00 d0 c7 00 81 ff ff ff ff ......H........ . 0010: 0a 00 00 00 0a 00 00 00 21 00 00 00 00 00 00 00 ........!...... . 0020: 2b 00 01 02 0a 00 00 00 0a 00 00 00 65 76 65 6e +...........eve . 0030: 74 73 2f 31 00 00 00 00 00 00 00 00 0a 00 00 00 ts/1........... . 0040: e0 b1 31 81 ff ff ff ff ....... . 0x21e18 [0x48]: PERF_EVENT_SAMPLE (IP, 1): 10: 0xffffffff8100c7d0 period: 33 The raw ftrace binary record starts at offset 0020. Translation: struct trace_entry { type = 0x2b = 43; flags = 1; preempt_count = 2; pid = 0xa = 10; tgid = 0xa = 10; } thread_comm = "events/1" thread_pid = 0xa = 10; func = 0xffffffff8131b1e0 = flush_to_ldisc() What will come next? - Userspace support ('perf trace'), 'flight data recorder' mode for perf trace, etc. - The unconditional copy from the profiling callback brings some costs however if someone wants no such sampling to occur, and needs to be fixed in the future. For that we need to have an instant access to the perf counter attribute. This is a matter of a flag to add in the struct ftrace_event. - Take care of the events recursivity! Don't ever try to record a lock event for example, it seems some locking is used in the profiling fast path and lead to a tracing recursivity. That will be fixed using raw spinlock or recursivity protection. - [...] - Profit! :-) Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com> Cc: Li Zefan <lizf@cn.fujitsu.com> Cc: Tom Zanussi <tzanussi@gmail.com> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Paul Mackerras <paulus@samba.org> Cc: Pekka Enberg <penberg@cs.helsinki.fi> Cc: Gabriel Munteanu <eduard.munteanu@linux360.ro> Cc: Lai Jiangshan <laijs@cn.fujitsu.com> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-08-06 23:25:54 +00:00
attr->mmap = track;
attr->comm = track;
attr->inherit = (cpu < 0) && inherit;
attr->disabled = 1;
try_again:
fd[nr_cpu][counter] = sys_perf_counter_open(attr, pid, cpu, group_fd, 0);
if (fd[nr_cpu][counter] < 0) {
int err = errno;
if (err == EPERM)
die("Permission error - are you root?\n");
else if (err == ENODEV && profile_cpu != -1)
die("No such device - did you specify an out-of-range profile CPU?\n");
/*
* If it's cycles then fall back to hrtimer
* based cpu-clock-tick sw counter, which
* is always available even if no PMU support:
*/
if (attr->type == PERF_TYPE_HARDWARE
&& attr->config == PERF_COUNT_HW_CPU_CYCLES) {
if (verbose)
warning(" ... trying to fall back to cpu-clock-ticks\n");
attr->type = PERF_TYPE_SOFTWARE;
attr->config = PERF_COUNT_SW_CPU_CLOCK;
goto try_again;
}
printf("\n");
error("perfcounter syscall returned with %d (%s)\n",
fd[nr_cpu][counter], strerror(err));
die("No CONFIG_PERF_COUNTERS=y kernel support configured?\n");
exit(-1);
}
h_attr = get_header_attr(attr, counter);
if (!file_new) {
if (memcmp(&h_attr->attr, attr, sizeof(*attr))) {
fprintf(stderr, "incompatible append\n");
exit(-1);
}
}
if (read(fd[nr_cpu][counter], &read_data, sizeof(read_data)) == -1) {
perror("Unable to read perf file descriptor\n");
exit(-1);
}
perf_header_attr__add_id(h_attr, read_data.id);
assert(fd[nr_cpu][counter] >= 0);
fcntl(fd[nr_cpu][counter], F_SETFL, O_NONBLOCK);
/*
* First counter acts as the group leader:
*/
if (group && group_fd == -1)
group_fd = fd[nr_cpu][counter];
perf tools: Implement counter output multiplexing Finish the -M/--multiplex option implementation: - separate it out from group_fd - correctly set it via the ioctl and dont mmap counters that are multiplexed - modify the perf record event loop to deal with buffer-less counters. - remove the -g option from perf sched record - account for unordered events in perf sched latency - (add -f to perf sched record to ease measurements) - skip idle threads (pid==0) in latency output The result is better latency output by 'perf sched latency': ----------------------------------------------------------------------------------- Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | ----------------------------------------------------------------------------------- ksoftirqd/8 | 0.071 ms | 2 | avg: 0.458 ms | max: 0.913 ms | at-spi-registry | 0.609 ms | 19 | avg: 0.013 ms | max: 0.023 ms | perf | 3.316 ms | 16 | avg: 0.013 ms | max: 0.054 ms | Xorg | 0.392 ms | 19 | avg: 0.011 ms | max: 0.018 ms | sleep | 0.537 ms | 2 | avg: 0.009 ms | max: 0.009 ms | ----------------------------------------------------------------------------------- TOTAL: | 4.925 ms | 58 | --------------------------------------------- Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Mike Galbraith <efault@gmx.de> Cc: Paul Mackerras <paulus@samba.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 16:15:54 +00:00
if (multiplex && multiplex_fd == -1)
multiplex_fd = fd[nr_cpu][counter];
perf tools: Implement counter output multiplexing Finish the -M/--multiplex option implementation: - separate it out from group_fd - correctly set it via the ioctl and dont mmap counters that are multiplexed - modify the perf record event loop to deal with buffer-less counters. - remove the -g option from perf sched record - account for unordered events in perf sched latency - (add -f to perf sched record to ease measurements) - skip idle threads (pid==0) in latency output The result is better latency output by 'perf sched latency': ----------------------------------------------------------------------------------- Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | ----------------------------------------------------------------------------------- ksoftirqd/8 | 0.071 ms | 2 | avg: 0.458 ms | max: 0.913 ms | at-spi-registry | 0.609 ms | 19 | avg: 0.013 ms | max: 0.023 ms | perf | 3.316 ms | 16 | avg: 0.013 ms | max: 0.054 ms | Xorg | 0.392 ms | 19 | avg: 0.011 ms | max: 0.018 ms | sleep | 0.537 ms | 2 | avg: 0.009 ms | max: 0.009 ms | ----------------------------------------------------------------------------------- TOTAL: | 4.925 ms | 58 | --------------------------------------------- Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Mike Galbraith <efault@gmx.de> Cc: Paul Mackerras <paulus@samba.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 16:15:54 +00:00
if (multiplex && fd[nr_cpu][counter] != multiplex_fd) {
int ret;
perf tools: Implement counter output multiplexing Finish the -M/--multiplex option implementation: - separate it out from group_fd - correctly set it via the ioctl and dont mmap counters that are multiplexed - modify the perf record event loop to deal with buffer-less counters. - remove the -g option from perf sched record - account for unordered events in perf sched latency - (add -f to perf sched record to ease measurements) - skip idle threads (pid==0) in latency output The result is better latency output by 'perf sched latency': ----------------------------------------------------------------------------------- Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | ----------------------------------------------------------------------------------- ksoftirqd/8 | 0.071 ms | 2 | avg: 0.458 ms | max: 0.913 ms | at-spi-registry | 0.609 ms | 19 | avg: 0.013 ms | max: 0.023 ms | perf | 3.316 ms | 16 | avg: 0.013 ms | max: 0.054 ms | Xorg | 0.392 ms | 19 | avg: 0.011 ms | max: 0.018 ms | sleep | 0.537 ms | 2 | avg: 0.009 ms | max: 0.009 ms | ----------------------------------------------------------------------------------- TOTAL: | 4.925 ms | 58 | --------------------------------------------- Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Mike Galbraith <efault@gmx.de> Cc: Paul Mackerras <paulus@samba.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 16:15:54 +00:00
ret = ioctl(fd[nr_cpu][counter], PERF_COUNTER_IOC_SET_OUTPUT, multiplex_fd);
assert(ret != -1);
} else {
event_array[nr_poll].fd = fd[nr_cpu][counter];
event_array[nr_poll].events = POLLIN;
nr_poll++;
mmap_array[nr_cpu][counter].counter = counter;
mmap_array[nr_cpu][counter].prev = 0;
mmap_array[nr_cpu][counter].mask = mmap_pages*page_size - 1;
mmap_array[nr_cpu][counter].base = mmap(NULL, (mmap_pages+1)*page_size,
PROT_READ|PROT_WRITE, MAP_SHARED, fd[nr_cpu][counter], 0);
if (mmap_array[nr_cpu][counter].base == MAP_FAILED) {
error("failed to mmap with %d (%s)\n", errno, strerror(errno));
exit(-1);
}
}
ioctl(fd[nr_cpu][counter], PERF_COUNTER_IOC_ENABLE);
}
static void open_counters(int cpu, pid_t pid)
{
int counter;
group_fd = -1;
for (counter = 0; counter < nr_counters; counter++)
create_counter(counter, cpu, pid);
nr_cpu++;
}
static void atexit_header(void)
{
header->data_size += bytes_written;
perf_header__write(header, output);
}
static int __cmd_record(int argc, const char **argv)
{
int i, counter;
struct stat st;
pid_t pid = 0;
int flags;
int ret;
page_size = sysconf(_SC_PAGE_SIZE);
nr_cpus = sysconf(_SC_NPROCESSORS_ONLN);
assert(nr_cpus <= MAX_NR_CPUS);
assert(nr_cpus >= 0);
atexit(sig_atexit);
signal(SIGCHLD, sig_handler);
signal(SIGINT, sig_handler);
if (!stat(output_name, &st) && st.st_size) {
if (!force && !append_file) {
fprintf(stderr, "Error, output file %s exists, use -A to append or -f to overwrite.\n",
output_name);
exit(-1);
}
} else {
append_file = 0;
}
flags = O_CREAT|O_RDWR;
if (append_file)
file_new = 0;
else
flags |= O_TRUNC;
output = open(output_name, flags, S_IRUSR|S_IWUSR);
if (output < 0) {
perror("failed to create output file");
exit(-1);
}
if (!file_new)
header = perf_header__read(output);
else
header = perf_header__new();
if (raw_samples) {
read_tracing_data(attrs, nr_counters);
} else {
for (i = 0; i < nr_counters; i++) {
if (attrs[i].sample_type & PERF_SAMPLE_RAW) {
read_tracing_data(attrs, nr_counters);
break;
}
}
}
atexit(atexit_header);
if (!system_wide) {
pid = target_pid;
if (pid == -1)
pid = getpid();
open_counters(profile_cpu, pid);
} else {
if (profile_cpu != -1) {
open_counters(profile_cpu, target_pid);
} else {
for (i = 0; i < nr_cpus; i++)
open_counters(i, target_pid);
}
}
if (file_new)
perf_header__write(header, output);
if (!system_wide) {
pid_t tgid = pid_synthesize_comm_event(pid, 0);
pid_synthesize_mmap_samples(pid, tgid);
} else
synthesize_all();
if (target_pid == -1 && argc) {
pid = fork();
if (pid < 0)
perror("failed to fork");
if (!pid) {
if (execvp(argv[0], (char **)argv)) {
perror(argv[0]);
exit(-1);
}
}
}
if (realtime_prio) {
struct sched_param param;
param.sched_priority = realtime_prio;
if (sched_setscheduler(0, SCHED_FIFO, &param)) {
printf("Could not set realtime priority.\n");
exit(-1);
}
}
for (;;) {
int hits = samples;
for (i = 0; i < nr_cpu; i++) {
perf tools: Implement counter output multiplexing Finish the -M/--multiplex option implementation: - separate it out from group_fd - correctly set it via the ioctl and dont mmap counters that are multiplexed - modify the perf record event loop to deal with buffer-less counters. - remove the -g option from perf sched record - account for unordered events in perf sched latency - (add -f to perf sched record to ease measurements) - skip idle threads (pid==0) in latency output The result is better latency output by 'perf sched latency': ----------------------------------------------------------------------------------- Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | ----------------------------------------------------------------------------------- ksoftirqd/8 | 0.071 ms | 2 | avg: 0.458 ms | max: 0.913 ms | at-spi-registry | 0.609 ms | 19 | avg: 0.013 ms | max: 0.023 ms | perf | 3.316 ms | 16 | avg: 0.013 ms | max: 0.054 ms | Xorg | 0.392 ms | 19 | avg: 0.011 ms | max: 0.018 ms | sleep | 0.537 ms | 2 | avg: 0.009 ms | max: 0.009 ms | ----------------------------------------------------------------------------------- TOTAL: | 4.925 ms | 58 | --------------------------------------------- Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> Cc: Mike Galbraith <efault@gmx.de> Cc: Paul Mackerras <paulus@samba.org> Cc: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Frederic Weisbecker <fweisbec@gmail.com> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-09-13 16:15:54 +00:00
for (counter = 0; counter < nr_counters; counter++) {
if (mmap_array[i][counter].base)
mmap_read(&mmap_array[i][counter]);
}
}
if (hits == samples) {
if (done)
break;
ret = poll(event_array, nr_poll, 100);
}
}
/*
* Approximate RIP event size: 24 bytes.
*/
fprintf(stderr,
"[ perf record: Captured and wrote %.3f MB %s (~%lld samples) ]\n",
(double)bytes_written / 1024.0 / 1024.0,
output_name,
bytes_written / 24);
return 0;
}
static const char * const record_usage[] = {
"perf record [<options>] [<command>]",
"perf record [<options>] -- <command> [<options>]",
NULL
};
static const struct option options[] = {
OPT_CALLBACK('e', "event", NULL, "event",
"event selector. use 'perf list' to list available events",
parse_events),
OPT_INTEGER('p', "pid", &target_pid,
"record events on existing pid"),
OPT_INTEGER('r', "realtime", &realtime_prio,
"collect data with this RT SCHED_FIFO priority"),
OPT_BOOLEAN('R', "raw-samples", &raw_samples,
"collect raw sample records from all opened counters"),
OPT_BOOLEAN('a', "all-cpus", &system_wide,
"system-wide collection from all CPUs"),
OPT_BOOLEAN('A', "append", &append_file,
"append to the output file to do incremental profiling"),
OPT_INTEGER('C', "profile_cpu", &profile_cpu,
"CPU to profile on"),
OPT_BOOLEAN('f', "force", &force,
"overwrite existing data file"),
OPT_LONG('c', "count", &default_interval,
"event period to sample"),
OPT_STRING('o', "output", &output_name, "file",
"output file name"),
OPT_BOOLEAN('i', "inherit", &inherit,
"child tasks inherit counters"),
OPT_INTEGER('F', "freq", &freq,
"profile at this frequency"),
OPT_INTEGER('m', "mmap-pages", &mmap_pages,
"number of mmap data pages"),
OPT_BOOLEAN('g', "call-graph", &call_graph,
"do call-graph (stack chain/backtrace) recording"),
OPT_BOOLEAN('v', "verbose", &verbose,
"be more verbose (show counter open errors, etc)"),
OPT_BOOLEAN('s', "stat", &inherit_stat,
"per thread counts"),
OPT_BOOLEAN('d', "data", &sample_address,
"Sample addresses"),
OPT_BOOLEAN('n', "no-samples", &no_samples,
"don't sample"),
OPT_BOOLEAN('M', "multiplex", &multiplex,
"multiplex counter output in a single channel"),
OPT_END()
};
int cmd_record(int argc, const char **argv, const char *prefix __used)
{
int counter;
argc = parse_options(argc, argv, options, record_usage,
PARSE_OPT_STOP_AT_NON_OPTION);
if (!argc && target_pid == -1 && !system_wide)
usage_with_options(record_usage, options);
if (!nr_counters) {
nr_counters = 1;
attrs[0].type = PERF_TYPE_HARDWARE;
attrs[0].config = PERF_COUNT_HW_CPU_CYCLES;
}
for (counter = 0; counter < nr_counters; counter++) {
if (attrs[counter].sample_period)
continue;
attrs[counter].sample_period = default_interval;
}
return __cmd_record(argc, argv);
}