linux_old1/tools/perf/builtin-trace.c

291 lines
5.7 KiB
C
Raw Normal View History

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 22:18:08 +08:00
#include "builtin.h"
#include "util/util.h"
#include "util/cache.h"
#include "util/symbol.h"
#include "util/thread.h"
#include "util/header.h"
#include "util/parse-options.h"
#include "perf.h"
#include "util/debug.h"
#include "util/trace-event.h"
static char const *input_name = "perf.data";
static int input;
static unsigned long page_size;
static unsigned long mmap_window = 32;
static unsigned long total = 0;
static unsigned long total_comm = 0;
static struct rb_root threads;
static struct thread *last_match;
static struct perf_header *header;
static u64 sample_type;
static int
process_comm_event(event_t *event, unsigned long offset, unsigned long head)
{
struct thread *thread;
thread = threads__findnew(event->comm.pid, &threads, &last_match);
dump_printf("%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)) {
dump_printf("problem processing PERF_EVENT_COMM, skipping event.\n");
return -1;
}
total_comm++;
return 0;
}
static int
process_sample_event(event_t *event, unsigned long offset, unsigned long head)
{
char level;
int show = 0;
struct dso *dso = NULL;
struct thread *thread;
u64 ip = event->ip.ip;
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-03 02:20:38 +08:00
u32 cpu = -1;
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 22:18:08 +08:00
u64 period = 1;
void *more_data = event->ip.__more_data;
int cpumode;
thread = threads__findnew(event->ip.pid, &threads, &last_match);
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-03 02:20:38 +08:00
if (sample_type & PERF_SAMPLE_CPU) {
cpu = *(u32 *)more_data;
more_data += sizeof(u32);
more_data += sizeof(u32); /* reserved */
}
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 22:18:08 +08:00
if (sample_type & PERF_SAMPLE_PERIOD) {
period = *(u64 *)more_data;
more_data += sizeof(u64);
}
dump_printf("%p [%p]: PERF_EVENT_SAMPLE (IP, %d): %d/%d: %p period: %Ld\n",
(void *)(offset + head),
(void *)(long)(event->header.size),
event->header.misc,
event->ip.pid, event->ip.tid,
(void *)(long)ip,
(long long)period);
dump_printf(" ... thread: %s:%d\n", thread->comm, thread->pid);
if (thread == NULL) {
eprintf("problem processing %d event, skipping it.\n",
event->header.type);
return -1;
}
cpumode = event->header.misc & PERF_EVENT_MISC_CPUMODE_MASK;
if (cpumode == PERF_EVENT_MISC_KERNEL) {
show = SHOW_KERNEL;
level = 'k';
dso = kernel_dso;
dump_printf(" ...... dso: %s\n", dso->name);
} else if (cpumode == PERF_EVENT_MISC_USER) {
show = SHOW_USER;
level = '.';
} else {
show = SHOW_HV;
level = 'H';
dso = hypervisor_dso;
dump_printf(" ...... dso: [hypervisor]\n");
}
if (sample_type & PERF_SAMPLE_RAW) {
struct {
u32 size;
char data[0];
} *raw = more_data;
/*
* FIXME: better resolve from pid from the struct trace_entry
* field, although it should be the same than this perf
* event pid
*/
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-03 02:20:38 +08:00
print_event(cpu, raw->data, raw->size, 0, thread->comm);
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 22:18:08 +08:00
}
total += period;
return 0;
}
static int
process_event(event_t *event, unsigned long offset, unsigned long head)
{
trace_event(event);
switch (event->header.type) {
case PERF_EVENT_MMAP ... PERF_EVENT_LOST:
return 0;
case PERF_EVENT_COMM:
return process_comm_event(event, offset, head);
case PERF_EVENT_EXIT ... PERF_EVENT_READ:
return 0;
case PERF_EVENT_SAMPLE:
return process_sample_event(event, offset, head);
case PERF_EVENT_MAX:
default:
return -1;
}
return 0;
}
static int __cmd_trace(void)
{
int ret, rc = EXIT_FAILURE;
unsigned long offset = 0;
unsigned long head = 0;
struct stat perf_stat;
event_t *event;
uint32_t size;
char *buf;
trace_report();
register_idle_thread(&threads, &last_match);
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 22:18:08 +08:00
input = open(input_name, O_RDONLY);
if (input < 0) {
perror("failed to open file");
exit(-1);
}
ret = fstat(input, &perf_stat);
if (ret < 0) {
perror("failed to stat file");
exit(-1);
}
if (!perf_stat.st_size) {
fprintf(stderr, "zero-sized file, nothing to do!\n");
exit(0);
}
header = perf_header__read(input);
sample_type = perf_header__sample_type(header);
if (!(sample_type & PERF_SAMPLE_RAW))
die("No trace sample to read. Did you call perf record "
"without -R?");
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 22:18:08 +08:00
if (load_kernel() < 0) {
perror("failed to load kernel symbols");
return EXIT_FAILURE;
}
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 res;
res = munmap(buf, page_size * mmap_window);
assert(res == 0);
offset += shift;
head -= shift;
goto remap;
}
size = event->header.size;
if (!size || process_event(event, offset, head) < 0) {
/*
* 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 < (unsigned long)perf_stat.st_size)
goto more;
rc = EXIT_SUCCESS;
close(input);
return rc;
}
static const char * const annotate_usage[] = {
"perf trace [<options>] <command>",
NULL
};
static const struct option options[] = {
OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
"dump raw trace in ASCII"),
OPT_BOOLEAN('v', "verbose", &verbose,
"be more verbose (show symbol address, etc)"),
OPT_END()
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 22:18:08 +08:00
};
int cmd_trace(int argc, const char **argv, const char *prefix __used)
{
symbol__init();
page_size = getpagesize();
argc = parse_options(argc, argv, options, annotate_usage, 0);
if (argc) {
/*
* Special case: if there's an argument left then assume tha
* it's a symbol filter:
*/
if (argc > 1)
usage_with_options(annotate_usage, options);
}
setup_pager();
return __cmd_trace();
}