linux_dsm_epyc7002/tools/perf/builtin-report.c

1396 lines
27 KiB
C
Raw Normal View History

/*
* builtin-report.c
*
* Builtin report command: Analyze the perf.data input file,
* look up and read DSOs and symbol information and display
* a histogram of results, along various sorting keys.
*/
#include "builtin.h"
#include "util/util.h"
#include "util/color.h"
#include "util/list.h"
#include "util/cache.h"
#include "util/rbtree.h"
#include "util/symbol.h"
#include "util/string.h"
#include "perf.h"
#include "util/parse-options.h"
#include "util/parse-events.h"
#define SHOW_KERNEL 1
#define SHOW_USER 2
#define SHOW_HV 4
static char const *input_name = "perf.data";
static char *vmlinux = NULL;
static char default_sort_order[] = "comm,dso";
static char *sort_order = default_sort_order;
static int input;
static int show_mask = SHOW_KERNEL | SHOW_USER | SHOW_HV;
static int dump_trace = 0;
#define dprintf(x...) do { if (dump_trace) printf(x); } while (0)
#define cdprintf(x...) do { if (dump_trace) color_fprintf(stdout, color, x); } while (0)
static int verbose;
static int full_paths;
perf report: Add per system call overhead histogram Take advantage of call-graph percounter sampling/recording to display a non-trivial histogram: the true, collapsed/summarized cost measurement, on a per system call total overhead basis: aldebaran:~/linux/linux/tools/perf> ./perf record -g -a -f ~/hackbench 10 aldebaran:~/linux/linux/tools/perf> ./perf report -s symbol --syscalls | head -10 # # (3536 samples) # # Overhead Symbol # ........ ...... # 40.75% [k] sys_write 40.21% [k] sys_read 4.44% [k] do_nmi ... This is done by accounting each (reliable) call-chain that chains back to a given system call to that system call function. [ So in the above example we can see that hackbench spends about 40% of its total time somewhere in sys_write() and 40% somewhere in sys_read(), the rest of the time is spent in user-space. The time is not spent in sys_write() _itself_ but in one of its many child functions. ] Or, a recording of a (source files are already in the page-cache) kernel build: $ perf record -g -m 512 -f -- make -j32 kernel $ perf report -s s --syscalls | grep '\[k\]' | grep -v nmi 4.14% [k] do_page_fault 1.20% [k] sys_write 1.10% [k] sys_open 0.63% [k] sys_exit_group 0.48% [k] smp_apic_timer_interrupt 0.37% [k] sys_read 0.37% [k] sys_execve 0.20% [k] sys_mmap 0.18% [k] sys_close 0.14% [k] sys_munmap 0.13% [k] sys_poll 0.09% [k] sys_newstat 0.07% [k] sys_clone 0.06% [k] sys_newfstat 0.05% [k] sys_access 0.05% [k] schedule Shows the true total cost of each syscall variant that gets used during a kernel build. This profile reveals it that pagefaults are the costliest, followed by read()/write(). An interesting detail: timer interrupts cost 0.5% - or 0.5 seconds per 100 seconds of kernel build-time. (this was done with HZ=1000) The summary is done in 'perf report', i.e. in the post-processing stage - so once we have a good call-graph recording, this type of non-trivial high-level analysis becomes possible. 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: Linus Torvalds <torvalds@linux-foundation.org> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Pekka Enberg <penberg@cs.helsinki.fi> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-06-15 16:24:38 +07:00
static int collapse_syscalls;
static unsigned long page_size;
static unsigned long mmap_window = 32;
struct ip_chain_event {
__u16 nr;
__u16 hv;
__u16 kernel;
__u16 user;
__u64 ips[];
};
struct ip_event {
struct perf_event_header header;
__u64 ip;
__u32 pid, tid;
unsigned char __more_data[];
};
struct mmap_event {
struct perf_event_header header;
__u32 pid, tid;
__u64 start;
__u64 len;
__u64 pgoff;
char filename[PATH_MAX];
};
struct comm_event {
struct perf_event_header header;
__u32 pid, tid;
char comm[16];
};
struct fork_event {
struct perf_event_header header;
__u32 pid, ppid;
};
struct period_event {
struct perf_event_header header;
__u64 time;
__u64 id;
__u64 sample_period;
};
typedef union event_union {
struct perf_event_header header;
struct ip_event ip;
struct mmap_event mmap;
struct comm_event comm;
struct fork_event fork;
struct period_event period;
} event_t;
static LIST_HEAD(dsos);
static struct dso *kernel_dso;
static struct dso *vdso;
static void dsos__add(struct dso *dso)
{
list_add_tail(&dso->node, &dsos);
}
static struct dso *dsos__find(const char *name)
{
struct dso *pos;
list_for_each_entry(pos, &dsos, node)
if (strcmp(pos->name, name) == 0)
return pos;
return NULL;
}
static struct dso *dsos__findnew(const char *name)
{
struct dso *dso = dsos__find(name);
int nr;
if (dso)
return dso;
dso = dso__new(name, 0);
if (!dso)
goto out_delete_dso;
nr = dso__load(dso, NULL, verbose);
if (nr < 0) {
if (verbose)
fprintf(stderr, "Failed to open: %s\n", name);
goto out_delete_dso;
}
if (!nr && verbose) {
fprintf(stderr,
"No symbols found in: %s, maybe install a debug package?\n",
name);
}
dsos__add(dso);
return dso;
out_delete_dso:
dso__delete(dso);
return NULL;
}
static void dsos__fprintf(FILE *fp)
{
struct dso *pos;
list_for_each_entry(pos, &dsos, node)
dso__fprintf(pos, fp);
}
static struct symbol *vdso__find_symbol(struct dso *dso, __u64 ip)
{
return dso__find_symbol(kernel_dso, ip);
}
static int load_kernel(void)
{
int err;
kernel_dso = dso__new("[kernel]", 0);
if (!kernel_dso)
return -1;
err = dso__load_kernel(kernel_dso, vmlinux, NULL, verbose);
if (err) {
dso__delete(kernel_dso);
kernel_dso = NULL;
} else
dsos__add(kernel_dso);
vdso = dso__new("[vdso]", 0);
if (!vdso)
return -1;
vdso->find_symbol = vdso__find_symbol;
dsos__add(vdso);
return err;
}
static char __cwd[PATH_MAX];
static char *cwd = __cwd;
static int cwdlen;
static int strcommon(const char *pathname)
{
int n = 0;
while (pathname[n] == cwd[n] && n < cwdlen)
++n;
return n;
}
struct map {
struct list_head node;
__u64 start;
__u64 end;
__u64 pgoff;
__u64 (*map_ip)(struct map *, __u64);
struct dso *dso;
};
static __u64 map__map_ip(struct map *map, __u64 ip)
{
return ip - map->start + map->pgoff;
}
static __u64 vdso__map_ip(struct map *map, __u64 ip)
{
return ip;
}
static inline int is_anon_memory(const char *filename)
{
return strcmp(filename, "//anon") == 0;
}
static struct map *map__new(struct mmap_event *event)
{
struct map *self = malloc(sizeof(*self));
if (self != NULL) {
const char *filename = event->filename;
char newfilename[PATH_MAX];
int anon;
if (cwd) {
int n = strcommon(filename);
if (n == cwdlen) {
snprintf(newfilename, sizeof(newfilename),
".%s", filename + n);
filename = newfilename;
}
}
anon = is_anon_memory(filename);
if (anon) {
snprintf(newfilename, sizeof(newfilename), "/tmp/perf-%d.map", event->pid);
filename = newfilename;
}
self->start = event->start;
self->end = event->start + event->len;
self->pgoff = event->pgoff;
self->dso = dsos__findnew(filename);
if (self->dso == NULL)
goto out_delete;
if (self->dso == vdso || anon)
self->map_ip = vdso__map_ip;
else
self->map_ip = map__map_ip;
}
return self;
out_delete:
free(self);
return NULL;
}
static struct map *map__clone(struct map *self)
{
struct map *map = malloc(sizeof(*self));
if (!map)
return NULL;
memcpy(map, self, sizeof(*self));
return map;
}
static int map__overlap(struct map *l, struct map *r)
{
if (l->start > r->start) {
struct map *t = l;
l = r;
r = t;
}
if (l->end > r->start)
return 1;
return 0;
}
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
static size_t map__fprintf(struct map *self, FILE *fp)
{
return fprintf(fp, " %Lx-%Lx %Lx %s\n",
self->start, self->end, self->pgoff, self->dso->name);
}
struct thread {
struct rb_node rb_node;
struct list_head maps;
pid_t pid;
char *comm;
};
static struct thread *thread__new(pid_t pid)
{
struct thread *self = malloc(sizeof(*self));
if (self != NULL) {
self->pid = pid;
self->comm = malloc(32);
if (self->comm)
snprintf(self->comm, 32, ":%d", self->pid);
INIT_LIST_HEAD(&self->maps);
}
return self;
}
static int thread__set_comm(struct thread *self, const char *comm)
{
if (self->comm)
free(self->comm);
self->comm = strdup(comm);
return self->comm ? 0 : -ENOMEM;
}
static size_t thread__fprintf(struct thread *self, FILE *fp)
{
struct map *pos;
size_t ret = fprintf(fp, "Thread %d %s\n", self->pid, self->comm);
list_for_each_entry(pos, &self->maps, node)
ret += map__fprintf(pos, fp);
return ret;
}
static struct rb_root threads;
static struct thread *last_match;
static struct thread *threads__findnew(pid_t pid)
{
struct rb_node **p = &threads.rb_node;
struct rb_node *parent = NULL;
struct thread *th;
/*
* Font-end cache - PID lookups come in blocks,
* so most of the time we dont have to look up
* the full rbtree:
*/
if (last_match && last_match->pid == pid)
return last_match;
while (*p != NULL) {
parent = *p;
th = rb_entry(parent, struct thread, rb_node);
if (th->pid == pid) {
last_match = th;
return th;
}
if (pid < th->pid)
p = &(*p)->rb_left;
else
p = &(*p)->rb_right;
}
th = thread__new(pid);
if (th != NULL) {
rb_link_node(&th->rb_node, parent, p);
rb_insert_color(&th->rb_node, &threads);
last_match = th;
}
return th;
}
static void thread__insert_map(struct thread *self, struct map *map)
{
struct map *pos, *tmp;
list_for_each_entry_safe(pos, tmp, &self->maps, node) {
if (map__overlap(pos, map)) {
list_del_init(&pos->node);
/* XXX leaks dsos */
free(pos);
}
}
list_add_tail(&map->node, &self->maps);
}
static int thread__fork(struct thread *self, struct thread *parent)
{
struct map *map;
if (self->comm)
free(self->comm);
self->comm = strdup(parent->comm);
if (!self->comm)
return -ENOMEM;
list_for_each_entry(map, &parent->maps, node) {
struct map *new = map__clone(map);
if (!new)
return -ENOMEM;
thread__insert_map(self, new);
}
return 0;
}
static struct map *thread__find_map(struct thread *self, __u64 ip)
{
struct map *pos;
if (self == NULL)
return NULL;
list_for_each_entry(pos, &self->maps, node)
if (ip >= pos->start && ip <= pos->end)
return pos;
return NULL;
}
static size_t threads__fprintf(FILE *fp)
{
size_t ret = 0;
struct rb_node *nd;
for (nd = rb_first(&threads); nd; nd = rb_next(nd)) {
struct thread *pos = rb_entry(nd, struct thread, rb_node);
ret += thread__fprintf(pos, fp);
}
return ret;
}
/*
* histogram, sorted on item, collects counts
*/
static struct rb_root hist;
struct hist_entry {
struct rb_node rb_node;
struct thread *thread;
struct map *map;
struct dso *dso;
struct symbol *sym;
__u64 ip;
char level;
__u64 count;
};
/*
* configurable sorting bits
*/
struct sort_entry {
struct list_head list;
char *header;
int64_t (*cmp)(struct hist_entry *, struct hist_entry *);
int64_t (*collapse)(struct hist_entry *, struct hist_entry *);
size_t (*print)(FILE *fp, struct hist_entry *);
};
/* --sort pid */
static int64_t
sort__thread_cmp(struct hist_entry *left, struct hist_entry *right)
{
return right->thread->pid - left->thread->pid;
}
static size_t
sort__thread_print(FILE *fp, struct hist_entry *self)
{
return fprintf(fp, "%16s:%5d", self->thread->comm ?: "", self->thread->pid);
}
static struct sort_entry sort_thread = {
.header = " Command: Pid",
.cmp = sort__thread_cmp,
.print = sort__thread_print,
};
/* --sort comm */
static int64_t
sort__comm_cmp(struct hist_entry *left, struct hist_entry *right)
{
return right->thread->pid - left->thread->pid;
}
static int64_t
sort__comm_collapse(struct hist_entry *left, struct hist_entry *right)
{
char *comm_l = left->thread->comm;
char *comm_r = right->thread->comm;
if (!comm_l || !comm_r) {
if (!comm_l && !comm_r)
return 0;
else if (!comm_l)
return -1;
else
return 1;
}
return strcmp(comm_l, comm_r);
}
static size_t
sort__comm_print(FILE *fp, struct hist_entry *self)
{
return fprintf(fp, "%16s", self->thread->comm);
}
static struct sort_entry sort_comm = {
.header = " Command",
.cmp = sort__comm_cmp,
.collapse = sort__comm_collapse,
.print = sort__comm_print,
};
/* --sort dso */
static int64_t
sort__dso_cmp(struct hist_entry *left, struct hist_entry *right)
{
struct dso *dso_l = left->dso;
struct dso *dso_r = right->dso;
if (!dso_l || !dso_r) {
if (!dso_l && !dso_r)
return 0;
else if (!dso_l)
return -1;
else
return 1;
}
return strcmp(dso_l->name, dso_r->name);
}
static size_t
sort__dso_print(FILE *fp, struct hist_entry *self)
{
if (self->dso)
return fprintf(fp, "%-25s", self->dso->name);
return fprintf(fp, "%016llx ", (__u64)self->ip);
}
static struct sort_entry sort_dso = {
.header = "Shared Object ",
.cmp = sort__dso_cmp,
.print = sort__dso_print,
};
/* --sort symbol */
static int64_t
sort__sym_cmp(struct hist_entry *left, struct hist_entry *right)
{
__u64 ip_l, ip_r;
if (left->sym == right->sym)
return 0;
ip_l = left->sym ? left->sym->start : left->ip;
ip_r = right->sym ? right->sym->start : right->ip;
return (int64_t)(ip_r - ip_l);
}
static size_t
sort__sym_print(FILE *fp, struct hist_entry *self)
{
size_t ret = 0;
if (verbose)
ret += fprintf(fp, "%#018llx ", (__u64)self->ip);
if (self->sym) {
ret += fprintf(fp, "[%c] %s",
self->dso == kernel_dso ? 'k' : '.', self->sym->name);
} else {
ret += fprintf(fp, "%#016llx", (__u64)self->ip);
}
return ret;
}
static struct sort_entry sort_sym = {
.header = "Symbol",
.cmp = sort__sym_cmp,
.print = sort__sym_print,
};
static int sort__need_collapse = 0;
struct sort_dimension {
char *name;
struct sort_entry *entry;
int taken;
};
static struct sort_dimension sort_dimensions[] = {
{ .name = "pid", .entry = &sort_thread, },
{ .name = "comm", .entry = &sort_comm, },
{ .name = "dso", .entry = &sort_dso, },
{ .name = "symbol", .entry = &sort_sym, },
};
static LIST_HEAD(hist_entry__sort_list);
static int sort_dimension__add(char *tok)
{
int i;
for (i = 0; i < ARRAY_SIZE(sort_dimensions); i++) {
struct sort_dimension *sd = &sort_dimensions[i];
if (sd->taken)
continue;
if (strncasecmp(tok, sd->name, strlen(tok)))
continue;
if (sd->entry->collapse)
sort__need_collapse = 1;
list_add_tail(&sd->entry->list, &hist_entry__sort_list);
sd->taken = 1;
return 0;
}
return -ESRCH;
}
static int64_t
hist_entry__cmp(struct hist_entry *left, struct hist_entry *right)
{
struct sort_entry *se;
int64_t cmp = 0;
list_for_each_entry(se, &hist_entry__sort_list, list) {
cmp = se->cmp(left, right);
if (cmp)
break;
}
return cmp;
}
static int64_t
hist_entry__collapse(struct hist_entry *left, struct hist_entry *right)
{
struct sort_entry *se;
int64_t cmp = 0;
list_for_each_entry(se, &hist_entry__sort_list, list) {
int64_t (*f)(struct hist_entry *, struct hist_entry *);
f = se->collapse ?: se->cmp;
cmp = f(left, right);
if (cmp)
break;
}
return cmp;
}
static size_t
hist_entry__fprintf(FILE *fp, struct hist_entry *self, __u64 total_samples)
{
struct sort_entry *se;
size_t ret;
if (total_samples) {
double percent = self->count * 100.0 / total_samples;
char *color = PERF_COLOR_NORMAL;
/*
* We color high-overhead entries in red, mid-overhead
* entries in green - and keep the low overhead places
* normal:
*/
if (percent >= 5.0) {
color = PERF_COLOR_RED;
} else {
if (percent >= 0.5)
color = PERF_COLOR_GREEN;
}
ret = color_fprintf(fp, color, " %6.2f%%",
(self->count * 100.0) / total_samples);
} else
ret = fprintf(fp, "%12Ld ", self->count);
list_for_each_entry(se, &hist_entry__sort_list, list) {
fprintf(fp, " ");
ret += se->print(fp, self);
}
ret += fprintf(fp, "\n");
return ret;
}
/*
* collect histogram counts
*/
static int
hist_entry__add(struct thread *thread, struct map *map, struct dso *dso,
struct symbol *sym, __u64 ip, char level, __u64 count)
{
struct rb_node **p = &hist.rb_node;
struct rb_node *parent = NULL;
struct hist_entry *he;
struct hist_entry entry = {
.thread = thread,
.map = map,
.dso = dso,
.sym = sym,
.ip = ip,
.level = level,
.count = count,
};
int cmp;
while (*p != NULL) {
parent = *p;
he = rb_entry(parent, struct hist_entry, rb_node);
cmp = hist_entry__cmp(&entry, he);
if (!cmp) {
he->count += count;
return 0;
}
if (cmp < 0)
p = &(*p)->rb_left;
else
p = &(*p)->rb_right;
}
he = malloc(sizeof(*he));
if (!he)
return -ENOMEM;
*he = entry;
rb_link_node(&he->rb_node, parent, p);
rb_insert_color(&he->rb_node, &hist);
return 0;
}
static void hist_entry__free(struct hist_entry *he)
{
free(he);
}
/*
* collapse the histogram
*/
static struct rb_root collapse_hists;
static void collapse__insert_entry(struct hist_entry *he)
{
struct rb_node **p = &collapse_hists.rb_node;
struct rb_node *parent = NULL;
struct hist_entry *iter;
int64_t cmp;
while (*p != NULL) {
parent = *p;
iter = rb_entry(parent, struct hist_entry, rb_node);
cmp = hist_entry__collapse(iter, he);
if (!cmp) {
iter->count += he->count;
hist_entry__free(he);
return;
}
if (cmp < 0)
p = &(*p)->rb_left;
else
p = &(*p)->rb_right;
}
rb_link_node(&he->rb_node, parent, p);
rb_insert_color(&he->rb_node, &collapse_hists);
}
static void collapse__resort(void)
{
struct rb_node *next;
struct hist_entry *n;
if (!sort__need_collapse)
return;
next = rb_first(&hist);
while (next) {
n = rb_entry(next, struct hist_entry, rb_node);
next = rb_next(&n->rb_node);
rb_erase(&n->rb_node, &hist);
collapse__insert_entry(n);
}
}
/*
* reverse the map, sort on count.
*/
static struct rb_root output_hists;
static void output__insert_entry(struct hist_entry *he)
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
{
struct rb_node **p = &output_hists.rb_node;
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
struct rb_node *parent = NULL;
struct hist_entry *iter;
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
while (*p != NULL) {
parent = *p;
iter = rb_entry(parent, struct hist_entry, rb_node);
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
if (he->count > iter->count)
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
p = &(*p)->rb_left;
else
p = &(*p)->rb_right;
}
rb_link_node(&he->rb_node, parent, p);
rb_insert_color(&he->rb_node, &output_hists);
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
}
static void output__resort(void)
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
{
struct rb_node *next;
struct hist_entry *n;
struct rb_root *tree = &hist;
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
if (sort__need_collapse)
tree = &collapse_hists;
next = rb_first(tree);
while (next) {
n = rb_entry(next, struct hist_entry, rb_node);
next = rb_next(&n->rb_node);
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
rb_erase(&n->rb_node, tree);
output__insert_entry(n);
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
}
}
static size_t output__fprintf(FILE *fp, __u64 total_samples)
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
{
struct hist_entry *pos;
struct sort_entry *se;
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
struct rb_node *nd;
size_t ret = 0;
fprintf(fp, "\n");
fprintf(fp, "#\n");
fprintf(fp, "# (%Ld samples)\n", (__u64)total_samples);
fprintf(fp, "#\n");
fprintf(fp, "# Overhead");
list_for_each_entry(se, &hist_entry__sort_list, list)
fprintf(fp, " %s", se->header);
fprintf(fp, "\n");
fprintf(fp, "# ........");
list_for_each_entry(se, &hist_entry__sort_list, list) {
int i;
fprintf(fp, " ");
for (i = 0; i < strlen(se->header); i++)
fprintf(fp, ".");
}
fprintf(fp, "\n");
fprintf(fp, "#\n");
for (nd = rb_first(&output_hists); nd; nd = rb_next(nd)) {
pos = rb_entry(nd, struct hist_entry, rb_node);
ret += hist_entry__fprintf(fp, pos, total_samples);
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
}
if (!strcmp(sort_order, default_sort_order)) {
fprintf(fp, "#\n");
fprintf(fp, "# (For more details, try: perf report --sort comm,dso,symbol)\n");
fprintf(fp, "#\n");
}
fprintf(fp, "\n");
perf report: Sort output by symbol usage [acme@emilia ~]$ perf record find / > /dev/null 2>&1 [acme@emilia ~]$ perf stat perf report | head -20 4.95 find [k] 0xffffffff81393d65 _spin_lock 3.89 find [.] 0x000000000000af89 /usr/bin/find: <unknown> 2.19 find [k] 0xffffffffa00518e0 ext3fs_dirhash 1.87 find [k] 0xffffffff810a6cea __rcu_read_lock 1.86 find [k] 0xffffffff811c7312 _atomic_dec_and_lock 1.86 find [.] 0x00000000000782ab /lib64/libc-2.5.so: __GI_strlen 1.85 find [k] 0xffffffff810fedfb __kmalloc 1.62 find [.] 0x00000000000430ff /lib64/libc-2.5.so: vfprintf 1.59 find [k] 0xffffffff810a6d6d __rcu_read_unlock 1.55 find [k] 0xffffffff81119395 __d_lookup 1.39 find [.] 0x0000000000071b40 /lib64/libc-2.5.so: _int_malloc 1.30 find [k] 0xffffffffa031c4fc nfs_do_filldir 1.21 find [k] 0xffffffff811876a5 avc_has_perm_noaudit 1.15 find [k] 0xffffffff810fef62 kmem_cache_alloc 1.07 find [k] 0xffffffff811d03fb copy_user_generic_string 1.03 find [k] 0xffffffffa0043882 ext3_htree_store_dirent 0.99 find [k] 0xffffffff81393ebb _spin_lock_bh 0.98 find [k] 0xffffffffa03319a2 nfs3_decode_dirent 0.97 find [k] 0xffffffff8100bf20 system_call 0.92 find [k] 0xffffffff8139437e _spin_unlock Performance counter stats for 'perf': 244.278972 task clock ticks (msecs) 8 context switches (events) 9 CPU migrations (events) 2104 pagefaults (events) 35329669 CPU cycles (events) (scaled from 75.40%) 13740366 instructions (events) (scaled from 75.49%) 59073 cache references (events) (scaled from 24.60%) 196 cache misses (events) (scaled from 24.51%) Wall-clock time elapsed: 246.060717 msecs [acme@emilia ~]$ [acme@emilia ~]$ grep "model name" /proc/cpuinfo | head -1 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz [acme@emilia ~]$ grep "model name" /proc/cpuinfo | wc -l 8 [acme@emilia ~]$ Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com> Cc: Paul Mackerras <paulus@samba.org> Cc: Mike Galbraith <efault@gmx.de> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Peter Zijlstra <a.p.zijlstra@chello.nl> LKML-Reference: <20090526191904.GH4424@ghostprotocols.net> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-05-27 02:19:04 +07:00
return ret;
}
static void register_idle_thread(void)
{
struct thread *thread = threads__findnew(0);
if (thread == NULL ||
thread__set_comm(thread, "[idle]")) {
fprintf(stderr, "problem inserting idle task.\n");
exit(-1);
}
}
static unsigned long total = 0,
total_mmap = 0,
total_comm = 0,
total_fork = 0,
total_unknown = 0;
static int
process_overflow_event(event_t *event, unsigned long offset, unsigned long head)
{
char level;
int show = 0;
struct dso *dso = NULL;
struct thread *thread = threads__findnew(event->ip.pid);
__u64 ip = event->ip.ip;
__u64 period = 1;
struct map *map = NULL;
void *more_data = event->ip.__more_data;
struct ip_chain_event *chain;
if (event->header.type & PERF_SAMPLE_PERIOD) {
period = *(__u64 *)more_data;
more_data += sizeof(__u64);
}
dprintf("%p [%p]: PERF_EVENT (IP, %d): %d: %p period: %Ld\n",
(void *)(offset + head),
(void *)(long)(event->header.size),
event->header.misc,
event->ip.pid,
(void *)(long)ip,
(long long)period);
if (event->header.type & PERF_SAMPLE_CALLCHAIN) {
int i;
chain = (void *)more_data;
if (dump_trace) {
dprintf("... chain: u:%d, k:%d, nr:%d\n",
chain->user,
chain->kernel,
chain->nr);
for (i = 0; i < chain->nr; i++)
dprintf("..... %2d: %016Lx\n", i, chain->ips[i]);
}
perf report: Add per system call overhead histogram Take advantage of call-graph percounter sampling/recording to display a non-trivial histogram: the true, collapsed/summarized cost measurement, on a per system call total overhead basis: aldebaran:~/linux/linux/tools/perf> ./perf record -g -a -f ~/hackbench 10 aldebaran:~/linux/linux/tools/perf> ./perf report -s symbol --syscalls | head -10 # # (3536 samples) # # Overhead Symbol # ........ ...... # 40.75% [k] sys_write 40.21% [k] sys_read 4.44% [k] do_nmi ... This is done by accounting each (reliable) call-chain that chains back to a given system call to that system call function. [ So in the above example we can see that hackbench spends about 40% of its total time somewhere in sys_write() and 40% somewhere in sys_read(), the rest of the time is spent in user-space. The time is not spent in sys_write() _itself_ but in one of its many child functions. ] Or, a recording of a (source files are already in the page-cache) kernel build: $ perf record -g -m 512 -f -- make -j32 kernel $ perf report -s s --syscalls | grep '\[k\]' | grep -v nmi 4.14% [k] do_page_fault 1.20% [k] sys_write 1.10% [k] sys_open 0.63% [k] sys_exit_group 0.48% [k] smp_apic_timer_interrupt 0.37% [k] sys_read 0.37% [k] sys_execve 0.20% [k] sys_mmap 0.18% [k] sys_close 0.14% [k] sys_munmap 0.13% [k] sys_poll 0.09% [k] sys_newstat 0.07% [k] sys_clone 0.06% [k] sys_newfstat 0.05% [k] sys_access 0.05% [k] schedule Shows the true total cost of each syscall variant that gets used during a kernel build. This profile reveals it that pagefaults are the costliest, followed by read()/write(). An interesting detail: timer interrupts cost 0.5% - or 0.5 seconds per 100 seconds of kernel build-time. (this was done with HZ=1000) The summary is done in 'perf report', i.e. in the post-processing stage - so once we have a good call-graph recording, this type of non-trivial high-level analysis becomes possible. 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: Linus Torvalds <torvalds@linux-foundation.org> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Pekka Enberg <penberg@cs.helsinki.fi> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-06-15 16:24:38 +07:00
if (collapse_syscalls) {
/*
* Find the all-but-last kernel entry
* amongst the call-chains - to get
* to the level of system calls:
*/
if (chain->kernel >= 2)
ip = chain->ips[chain->kernel-2];
}
}
dprintf(" ... thread: %s:%d\n", thread->comm, thread->pid);
if (thread == NULL) {
fprintf(stderr, "problem processing %d event, skipping it.\n",
event->header.type);
return -1;
}
if (event->header.misc & PERF_EVENT_MISC_KERNEL) {
show = SHOW_KERNEL;
level = 'k';
dso = kernel_dso;
dprintf(" ...... dso: %s\n", dso->name);
} else if (event->header.misc & PERF_EVENT_MISC_USER) {
show = SHOW_USER;
level = '.';
map = thread__find_map(thread, ip);
if (map != NULL) {
ip = map->map_ip(map, ip);
dso = map->dso;
} else {
/*
* If this is outside of all known maps,
* and is a negative address, try to look it
* up in the kernel dso, as it might be a
* vsyscall (which executes in user-mode):
*/
if ((long long)ip < 0)
dso = kernel_dso;
}
dprintf(" ...... dso: %s\n", dso ? dso->name : "<not found>");
} else {
show = SHOW_HV;
level = 'H';
dprintf(" ...... dso: [hypervisor]\n");
}
if (show & show_mask) {
struct symbol *sym = NULL;
if (dso)
sym = dso->find_symbol(dso, ip);
if (hist_entry__add(thread, map, dso, sym, ip, level, period)) {
fprintf(stderr,
"problem incrementing symbol count, skipping event\n");
return -1;
}
}
total += period;
return 0;
}
static int
process_mmap_event(event_t *event, unsigned long offset, unsigned long head)
{
struct thread *thread = threads__findnew(event->mmap.pid);
struct map *map = map__new(&event->mmap);
dprintf("%p [%p]: PERF_EVENT_MMAP %d: [%p(%p) @ %p]: %s\n",
(void *)(offset + head),
(void *)(long)(event->header.size),
event->mmap.pid,
(void *)(long)event->mmap.start,
(void *)(long)event->mmap.len,
(void *)(long)event->mmap.pgoff,
event->mmap.filename);
if (thread == NULL || map == NULL) {
dprintf("problem processing PERF_EVENT_MMAP, skipping event.\n");
return 0;
}
thread__insert_map(thread, map);
total_mmap++;
return 0;
}
static int
process_comm_event(event_t *event, unsigned long offset, unsigned long head)
{
struct thread *thread = threads__findnew(event->comm.pid);
dprintf("%p [%p]: PERF_EVENT_COMM: %s:%d\n",
(void *)(offset + head),
(void *)(long)(event->header.size),
event->comm.comm, event->comm.pid);
if (thread == NULL ||
thread__set_comm(thread, event->comm.comm)) {
dprintf("problem processing PERF_EVENT_COMM, skipping event.\n");
return -1;
}
total_comm++;
return 0;
}
static int
process_fork_event(event_t *event, unsigned long offset, unsigned long head)
{
struct thread *thread = threads__findnew(event->fork.pid);
struct thread *parent = threads__findnew(event->fork.ppid);
dprintf("%p [%p]: PERF_EVENT_FORK: %d:%d\n",
(void *)(offset + head),
(void *)(long)(event->header.size),
event->fork.pid, event->fork.ppid);
if (!thread || !parent || thread__fork(thread, parent)) {
dprintf("problem processing PERF_EVENT_FORK, skipping event.\n");
return -1;
}
total_fork++;
return 0;
}
static int
process_period_event(event_t *event, unsigned long offset, unsigned long head)
{
dprintf("%p [%p]: PERF_EVENT_PERIOD: time:%Ld, id:%Ld: period:%Ld\n",
(void *)(offset + head),
(void *)(long)(event->header.size),
event->period.time,
event->period.id,
event->period.sample_period);
return 0;
}
static void trace_event(event_t *event)
{
unsigned char *raw_event = (void *)event;
char *color = PERF_COLOR_BLUE;
int i, j;
if (!dump_trace)
return;
dprintf(".");
cdprintf("\n. ... raw event: size %d bytes\n", event->header.size);
for (i = 0; i < event->header.size; i++) {
if ((i & 15) == 0) {
dprintf(".");
cdprintf(" %04x: ", i);
}
cdprintf(" %02x", raw_event[i]);
if (((i & 15) == 15) || i == event->header.size-1) {
cdprintf(" ");
for (j = 0; j < 15-(i & 15); j++)
cdprintf(" ");
for (j = 0; j < (i & 15); j++) {
if (isprint(raw_event[i-15+j]))
cdprintf("%c", raw_event[i-15+j]);
else
cdprintf(".");
}
cdprintf("\n");
}
}
dprintf(".\n");
}
static int
process_event(event_t *event, unsigned long offset, unsigned long head)
{
trace_event(event);
if (event->header.misc & PERF_EVENT_MISC_OVERFLOW)
return process_overflow_event(event, offset, head);
switch (event->header.type) {
case PERF_EVENT_MMAP:
return process_mmap_event(event, offset, head);
case PERF_EVENT_COMM:
return process_comm_event(event, offset, head);
case PERF_EVENT_FORK:
return process_fork_event(event, offset, head);
case PERF_EVENT_PERIOD:
return process_period_event(event, offset, head);
/*
* We dont process them right now but they are fine:
*/
case PERF_EVENT_THROTTLE:
case PERF_EVENT_UNTHROTTLE:
return 0;
default:
return -1;
}
return 0;
}
static int __cmd_report(void)
{
int ret, rc = EXIT_FAILURE;
unsigned long offset = 0;
unsigned long head = 0;
struct stat stat;
event_t *event;
uint32_t size;
char *buf;
register_idle_thread();
input = open(input_name, O_RDONLY);
if (input < 0) {
fprintf(stderr, " failed to open file: %s", input_name);
if (!strcmp(input_name, "perf.data"))
fprintf(stderr, " (try 'perf record' first)");
fprintf(stderr, "\n");
exit(-1);
}
ret = fstat(input, &stat);
if (ret < 0) {
perror("failed to stat file");
exit(-1);
}
if (!stat.st_size) {
fprintf(stderr, "zero-sized file, nothing to do!\n");
exit(0);
}
if (load_kernel() < 0) {
perror("failed to load kernel symbols");
return EXIT_FAILURE;
}
if (!full_paths) {
if (getcwd(__cwd, sizeof(__cwd)) == NULL) {
perror("failed to get the current directory");
return EXIT_FAILURE;
}
cwdlen = strlen(cwd);
} else {
cwd = NULL;
cwdlen = 0;
}
remap:
buf = (char *)mmap(NULL, page_size * mmap_window, PROT_READ,
MAP_SHARED, input, offset);
if (buf == MAP_FAILED) {
perror("failed to mmap file");
exit(-1);
}
more:
event = (event_t *)(buf + head);
size = event->header.size;
if (!size)
size = 8;
if (head + event->header.size >= page_size * mmap_window) {
unsigned long shift = page_size * (head / page_size);
int ret;
ret = munmap(buf, page_size * mmap_window);
assert(ret == 0);
offset += shift;
head -= shift;
goto remap;
}
size = event->header.size;
dprintf("\n%p [%p]: event: %d\n",
(void *)(offset + head),
(void *)(long)event->header.size,
event->header.type);
if (!size || process_event(event, offset, head) < 0) {
dprintf("%p [%p]: skipping unknown header type: %d\n",
(void *)(offset + head),
(void *)(long)(event->header.size),
event->header.type);
total_unknown++;
/*
* assume we lost track of the stream, check alignment, and
* increment a single u64 in the hope to catch on again 'soon'.
*/
if (unlikely(head & 7))
head &= ~7ULL;
size = 8;
}
head += size;
if (offset + head < stat.st_size)
goto more;
rc = EXIT_SUCCESS;
close(input);
dprintf(" IP events: %10ld\n", total);
dprintf(" mmap events: %10ld\n", total_mmap);
dprintf(" comm events: %10ld\n", total_comm);
dprintf(" fork events: %10ld\n", total_fork);
dprintf(" unknown events: %10ld\n", total_unknown);
if (dump_trace)
return 0;
if (verbose >= 3)
threads__fprintf(stdout);
if (verbose >= 2)
dsos__fprintf(stdout);
collapse__resort();
output__resort();
output__fprintf(stdout, total);
return rc;
}
static const char * const report_usage[] = {
"perf report [<options>] <command>",
NULL
};
static const struct option options[] = {
OPT_STRING('i', "input", &input_name, "file",
"input file name"),
OPT_BOOLEAN('v', "verbose", &verbose,
"be more verbose (show symbol address, etc)"),
OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
"dump raw trace in ASCII"),
OPT_STRING('k', "vmlinux", &vmlinux, "file", "vmlinux pathname"),
OPT_STRING('s', "sort", &sort_order, "key[,key2...]",
"sort by key(s): pid, comm, dso, symbol. Default: pid,symbol"),
OPT_BOOLEAN('P', "full-paths", &full_paths,
"Don't shorten the pathnames taking into account the cwd"),
perf report: Add per system call overhead histogram Take advantage of call-graph percounter sampling/recording to display a non-trivial histogram: the true, collapsed/summarized cost measurement, on a per system call total overhead basis: aldebaran:~/linux/linux/tools/perf> ./perf record -g -a -f ~/hackbench 10 aldebaran:~/linux/linux/tools/perf> ./perf report -s symbol --syscalls | head -10 # # (3536 samples) # # Overhead Symbol # ........ ...... # 40.75% [k] sys_write 40.21% [k] sys_read 4.44% [k] do_nmi ... This is done by accounting each (reliable) call-chain that chains back to a given system call to that system call function. [ So in the above example we can see that hackbench spends about 40% of its total time somewhere in sys_write() and 40% somewhere in sys_read(), the rest of the time is spent in user-space. The time is not spent in sys_write() _itself_ but in one of its many child functions. ] Or, a recording of a (source files are already in the page-cache) kernel build: $ perf record -g -m 512 -f -- make -j32 kernel $ perf report -s s --syscalls | grep '\[k\]' | grep -v nmi 4.14% [k] do_page_fault 1.20% [k] sys_write 1.10% [k] sys_open 0.63% [k] sys_exit_group 0.48% [k] smp_apic_timer_interrupt 0.37% [k] sys_read 0.37% [k] sys_execve 0.20% [k] sys_mmap 0.18% [k] sys_close 0.14% [k] sys_munmap 0.13% [k] sys_poll 0.09% [k] sys_newstat 0.07% [k] sys_clone 0.06% [k] sys_newfstat 0.05% [k] sys_access 0.05% [k] schedule Shows the true total cost of each syscall variant that gets used during a kernel build. This profile reveals it that pagefaults are the costliest, followed by read()/write(). An interesting detail: timer interrupts cost 0.5% - or 0.5 seconds per 100 seconds of kernel build-time. (this was done with HZ=1000) The summary is done in 'perf report', i.e. in the post-processing stage - so once we have a good call-graph recording, this type of non-trivial high-level analysis becomes possible. 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: Linus Torvalds <torvalds@linux-foundation.org> Cc: Frederic Weisbecker <fweisbec@gmail.com> Cc: Pekka Enberg <penberg@cs.helsinki.fi> LKML-Reference: <new-submission> Signed-off-by: Ingo Molnar <mingo@elte.hu>
2009-06-15 16:24:38 +07:00
OPT_BOOLEAN('S', "syscalls", &collapse_syscalls,
"show per syscall summary overhead, using call graph"),
OPT_END()
};
static void setup_sorting(void)
{
char *tmp, *tok, *str = strdup(sort_order);
for (tok = strtok_r(str, ", ", &tmp);
tok; tok = strtok_r(NULL, ", ", &tmp)) {
if (sort_dimension__add(tok) < 0) {
error("Unknown --sort key: `%s'", tok);
usage_with_options(report_usage, options);
}
}
free(str);
}
int cmd_report(int argc, const char **argv, const char *prefix)
{
symbol__init();
page_size = getpagesize();
argc = parse_options(argc, argv, options, report_usage, 0);
setup_sorting();
/*
* Any (unrecognized) arguments left?
*/
if (argc)
usage_with_options(report_usage, options);
setup_pager();
return __cmd_report();
}