2010-04-24 02:05:38

by Frederic Weisbecker

[permalink] [raw]
Subject: [GIT PULL] perf tools updates

Ingo,

Please pull the perf/core branch that can be found at:

git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git
perf/core

Thanks,
Frederic
---

Frederic Weisbecker (6):
perf: Generalize perf lock's sample event reordering to the session layer
perf: Use generic sample reordering in perf sched
perf: Use generic sample reordering in perf kmem
perf: Use generic sample reordering in perf trace
perf: Use generic sample reordering in perf timechart
perf: Add a perf trace option to check samples ordering reliability

Hitoshi Mitake (1):
perf lock: Fix state machine to recognize lock sequence

Stephane Eranian (1):
perf: Fix initialization bug in parse_single_tracepoint_event()

William Cohen (1):
perf: Some perf-kvm documentation edits


tools/perf/Documentation/perf-kvm.txt | 9 +-
tools/perf/builtin-kmem.c | 6 +-
tools/perf/builtin-lock.c | 595 ++++++++++++++++++++-------------
tools/perf/builtin-sched.c | 8 +-
tools/perf/builtin-timechart.c | 112 +------
tools/perf/builtin-trace.c | 13 +
tools/perf/util/parse-events.c | 13 +-
tools/perf/util/session.c | 179 ++++++++++-
tools/perf/util/session.h | 10 +
9 files changed, 583 insertions(+), 362 deletions(-)


2010-04-24 02:05:48

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 2/9] perf: Fix initialization bug in parse_single_tracepoint_event()

From: Stephane Eranian <[email protected]>

The parse_single_tracepoint_event() was setting some attributes
before it validated the event was indeed a tracepoint event. This
caused problems with other initialization routines like in the
builtin-top.c module whereby sample_period is not set if not 0.

Signed-off-by: Stephane Eranian <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Ingo Molnar <[email protected]>
LKML-Reference: <[email protected]>
Signed-off-by: Frederic Weisbecker <[email protected]>
---
tools/perf/util/parse-events.c | 13 +++++++------
1 files changed, 7 insertions(+), 6 deletions(-)

diff --git a/tools/perf/util/parse-events.c b/tools/perf/util/parse-events.c
index 3b4ec67..600d327 100644
--- a/tools/perf/util/parse-events.c
+++ b/tools/perf/util/parse-events.c
@@ -418,12 +418,6 @@ parse_single_tracepoint_event(char *sys_name,
u64 id;
int fd;

- attr->sample_type |= PERF_SAMPLE_RAW;
- attr->sample_type |= PERF_SAMPLE_TIME;
- attr->sample_type |= PERF_SAMPLE_CPU;
-
- attr->sample_period = 1;
-
snprintf(evt_path, MAXPATHLEN, "%s/%s/%s/id", debugfs_path,
sys_name, evt_name);

@@ -442,6 +436,13 @@ parse_single_tracepoint_event(char *sys_name,
attr->type = PERF_TYPE_TRACEPOINT;
*strp = evt_name + evt_length;

+ attr->sample_type |= PERF_SAMPLE_RAW;
+ attr->sample_type |= PERF_SAMPLE_TIME;
+ attr->sample_type |= PERF_SAMPLE_CPU;
+
+ attr->sample_period = 1;
+
+
return EVT_HANDLED;
}

--
1.6.2.3

2010-04-24 02:06:13

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 4/9] perf: Use generic sample reordering in perf sched

Use the new generic sample events reordering from perf sched,
this drops the need of multiplexing the buffers on record time,
improving the scalability of perf sched.

Signed-off-by: Frederic Weisbecker <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Hitoshi Mitake <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Masami Hiramatsu <[email protected]>
Cc: Tom Zanussi <[email protected]>
---
tools/perf/builtin-sched.c | 8 ++++----
1 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/tools/perf/builtin-sched.c b/tools/perf/builtin-sched.c
index 09ddc8e..94453f1 100644
--- a/tools/perf/builtin-sched.c
+++ b/tools/perf/builtin-sched.c
@@ -1651,9 +1651,10 @@ static int process_lost_event(event_t *event __used,
}

static struct perf_event_ops event_ops = {
- .sample = process_sample_event,
- .comm = event__process_comm,
- .lost = process_lost_event,
+ .sample = process_sample_event,
+ .comm = event__process_comm,
+ .lost = process_lost_event,
+ .ordered_samples = true,
};

static int read_events(void)
@@ -1850,7 +1851,6 @@ static const char *record_args[] = {
"record",
"-a",
"-R",
- "-M",
"-f",
"-m", "1024",
"-c", "1",
--
1.6.2.3

2010-04-24 02:06:29

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 6/9] perf: Use generic sample reordering in perf trace

Use the new generic sample events reordering from perf trace.
Before that, the displayed traces were ordered as they were
in the input as recorded by perf record (not time ordered).

This makes eventually perf trace displaying the events as beeing
time ordered.

Signed-off-by: Frederic Weisbecker <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Hitoshi Mitake <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Masami Hiramatsu <[email protected]>
Cc: Tom Zanussi <[email protected]>
---
tools/perf/builtin-trace.c | 1 +
1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 2eefb33..1d034f6 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -108,6 +108,7 @@ static struct perf_event_ops event_ops = {
.event_type = event__process_event_type,
.tracing_data = event__process_tracing_data,
.build_id = event__process_build_id,
+ .ordered_samples = true,
};

extern volatile int session_done;
--
1.6.2.3

2010-04-24 02:06:33

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 7/9] perf: Use generic sample reordering in perf timechart

Use the new generic sample events reordering from perf timechart,
this drops the ad hoc sample reordering it was using before.

Signed-off-by: Frederic Weisbecker <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Hitoshi Mitake <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Masami Hiramatsu <[email protected]>
Cc: Tom Zanussi <[email protected]>
Cc: Arjan van de Ven <[email protected]>
---
tools/perf/builtin-timechart.c | 112 ++--------------------------------------
1 files changed, 5 insertions(+), 107 deletions(-)

diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c
index 96f4a09..c35aa44 100644
--- a/tools/perf/builtin-timechart.c
+++ b/tools/perf/builtin-timechart.c
@@ -143,9 +143,6 @@ struct wake_event {
static struct power_event *power_events;
static struct wake_event *wake_events;

-struct sample_wrapper *all_samples;
-
-
struct process_filter;
struct process_filter {
char *name;
@@ -566,88 +563,6 @@ static void end_sample_processing(void)
}
}

-static u64 sample_time(event_t *event, const struct perf_session *session)
-{
- int cursor;
-
- cursor = 0;
- if (session->sample_type & PERF_SAMPLE_IP)
- cursor++;
- if (session->sample_type & PERF_SAMPLE_TID)
- cursor++;
- if (session->sample_type & PERF_SAMPLE_TIME)
- return event->sample.array[cursor];
- return 0;
-}
-
-
-/*
- * We first queue all events, sorted backwards by insertion.
- * The order will get flipped later.
- */
-static int queue_sample_event(event_t *event, struct perf_session *session)
-{
- struct sample_wrapper *copy, *prev;
- int size;
-
- size = event->sample.header.size + sizeof(struct sample_wrapper) + 8;
-
- copy = malloc(size);
- if (!copy)
- return 1;
-
- memset(copy, 0, size);
-
- copy->next = NULL;
- copy->timestamp = sample_time(event, session);
-
- memcpy(&copy->data, event, event->sample.header.size);
-
- /* insert in the right place in the list */
-
- if (!all_samples) {
- /* first sample ever */
- all_samples = copy;
- return 0;
- }
-
- if (all_samples->timestamp < copy->timestamp) {
- /* insert at the head of the list */
- copy->next = all_samples;
- all_samples = copy;
- return 0;
- }
-
- prev = all_samples;
- while (prev->next) {
- if (prev->next->timestamp < copy->timestamp) {
- copy->next = prev->next;
- prev->next = copy;
- return 0;
- }
- prev = prev->next;
- }
- /* insert at the end of the list */
- prev->next = copy;
-
- return 0;
-}
-
-static void sort_queued_samples(void)
-{
- struct sample_wrapper *cursor, *next;
-
- cursor = all_samples;
- all_samples = NULL;
-
- while (cursor) {
- next = cursor->next;
- cursor->next = all_samples;
- all_samples = cursor;
- cursor = next;
- }
-}
-
/*
* Sort the pid datastructure
*/
@@ -1011,26 +926,12 @@ static void write_svg_file(const char *filename)
svg_close();
}

-static void process_samples(struct perf_session *session)
-{
- struct sample_wrapper *cursor;
- event_t *event;
-
- sort_queued_samples();
-
- cursor = all_samples;
- while (cursor) {
- event = (void *)&cursor->data;
- cursor = cursor->next;
- process_sample_event(event, session);
- }
-}
-
static struct perf_event_ops event_ops = {
- .comm = process_comm_event,
- .fork = process_fork_event,
- .exit = process_exit_event,
- .sample = queue_sample_event,
+ .comm = process_comm_event,
+ .fork = process_fork_event,
+ .exit = process_exit_event,
+ .sample = process_sample_event,
+ .ordered_samples = true,
};

static int __cmd_timechart(void)
@@ -1048,8 +949,6 @@ static int __cmd_timechart(void)
if (ret)
goto out_delete;

- process_samples(session);
-
end_sample_processing();

sort_pids();
@@ -1072,7 +971,6 @@ static const char *record_args[] = {
"record",
"-a",
"-R",
- "-M",
"-f",
"-c", "1",
"-e", "power:power_start",
--
1.6.2.3

2010-04-24 02:06:38

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 9/9] perf: Some perf-kvm documentation edits

From: William Cohen <[email protected]>

asciidoc does not allow the "===" to be longer than the line
above it.
Also fix a couple types and formatting errors.

Signed-off-by: William Cohen <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Ingo Molnar <[email protected]>
LKML-Reference: <[email protected]>
Signed-off-by: Frederic Weisbecker <[email protected]>
---
tools/perf/Documentation/perf-kvm.txt | 9 +++++----
1 files changed, 5 insertions(+), 4 deletions(-)

diff --git a/tools/perf/Documentation/perf-kvm.txt b/tools/perf/Documentation/perf-kvm.txt
index 93400a0..d004e19 100644
--- a/tools/perf/Documentation/perf-kvm.txt
+++ b/tools/perf/Documentation/perf-kvm.txt
@@ -1,5 +1,5 @@
perf-kvm(1)
-==============
+===========

NAME
----
@@ -41,9 +41,9 @@ There are a couple of variants of perf kvm:
OPTIONS
-------
--host=::
- Collect host side perforamnce profile.
+ Collect host side performance profile.
--guest=::
- Collect guest side perforamnce profile.
+ Collect guest side performance profile.
--guestmount=<path>::
Guest os root file system mount directory. Users mounts guest os
root directories under <path> by a specific filesystem access method,
@@ -64,4 +64,5 @@ OPTIONS

SEE ALSO
--------
-linkperf:perf-top[1] perf-record[1] perf-report[1] perf-diff[1] perf-buildid-list[1]
+linkperf:perf-top[1], linkperf:perf-record[1], linkperf:perf-report[1],
+linkperf:perf-diff[1], linkperf:perf-buildid-list[1]
--
1.6.2.3

2010-04-24 02:06:42

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 8/9] perf: Add a perf trace option to check samples ordering reliability

To ensure sample events time reordering is reliable, add a -d option
to perf trace to check that automatically.

Signed-off-by: Frederic Weisbecker <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Hitoshi Mitake <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Masami Hiramatsu <[email protected]>
Cc: Tom Zanussi <[email protected]>
---
tools/perf/builtin-trace.c | 12 ++++++++++++
1 files changed, 12 insertions(+), 0 deletions(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 1d034f6..77f556f 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -11,6 +11,8 @@

static char const *script_name;
static char const *generate_script_lang;
+static bool debug_ordering;
+static u64 last_timestamp;

static int default_start_script(const char *script __unused,
int argc __unused,
@@ -87,6 +89,14 @@ static int process_sample_event(event_t *event, struct perf_session *session)
}

if (session->sample_type & PERF_SAMPLE_RAW) {
+ if (debug_ordering) {
+ if (data.time < last_timestamp) {
+ pr_err("Samples misordered, previous: %llu "
+ "this: %llu\n", last_timestamp,
+ data.time);
+ }
+ last_timestamp = data.time;
+ }
/*
* FIXME: better resolve from pid from the struct trace_entry
* field, although it should be the same than this perf
@@ -532,6 +542,8 @@ static const struct option options[] = {
"generate perf-trace.xx script in specified language"),
OPT_STRING('i', "input", &input_name, "file",
"input file name"),
+ OPT_BOOLEAN('d', "debug-ordering", &debug_ordering,
+ "check that samples time ordering is monotonic"),

OPT_END()
};
--
1.6.2.3

2010-04-24 02:06:10

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 1/9] perf lock: Fix state machine to recognize lock sequence

From: Hitoshi Mitake <[email protected]>

Previous state machine of perf lock was really broken.
This patch improves it a little.

This patch prepares the list of state machine that represents
lock sequences for each threads.

These state machines can be one of these sequences:

1) acquire -> acquired -> release
2) acquire -> contended -> acquired -> release
3) acquire (w/ try) -> release
4) acquire (w/ read) -> release

The case of 4) is a little special.
Double acquire of read lock is allowed, so the state machine
counts read lock number, and permits double acquire and release.

But, things are not so simple. Something in my model is still wrong.
I counted the number of lock instances with bad sequence,
and ratio is like this (case of tracing whoami): bad:233, total:2279

version 2:
* threads are now identified with tid, not pid
* prepared SEQ_STATE_READ_ACQUIRED for read lock.
* bunch of struct lock_seq_stat is now linked list
* debug information enhanced (this have to be removed someday)
e.g.
| === output for debug===
|
| bad:233, total:2279
| bad rate:0.000000
| histogram of events caused bad sequence
| acquire: 165
| acquired: 0
| contended: 0
| release: 68

Signed-off-by: Hitoshi Mitake <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Jens Axboe <[email protected]>
Cc: Jason Baron <[email protected]>
Cc: Xiao Guangrong <[email protected]>
Cc: Ingo Molnar <[email protected]>
LKML-Reference: <[email protected]>
[rename SEQ_STATE_UNINITED to SEQ_STATE_UNINITIALIZED]
Signed-off-by: Frederic Weisbecker <[email protected]>
---
tools/perf/builtin-lock.c | 410 +++++++++++++++++++++++++++++++++++++--------
1 files changed, 342 insertions(+), 68 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 6c38e4f..716d8c5 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -23,6 +23,8 @@
#include <linux/list.h>
#include <linux/hash.h>

+static struct perf_session *session;
+
/* based on kernel/lockdep.c */
#define LOCKHASH_BITS 12
#define LOCKHASH_SIZE (1UL << LOCKHASH_BITS)
@@ -32,9 +34,6 @@ static struct list_head lockhash_table[LOCKHASH_SIZE];
#define __lockhashfn(key) hash_long((unsigned long)key, LOCKHASH_BITS)
#define lockhashentry(key) (lockhash_table + __lockhashfn((key)))

-#define LOCK_STATE_UNLOCKED 0 /* initial state */
-#define LOCK_STATE_LOCKED 1
-
struct lock_stat {
struct list_head hash_entry;
struct rb_node rb; /* used for sorting */
@@ -47,20 +46,151 @@ struct lock_stat {
void *addr; /* address of lockdep_map, used as ID */
char *name; /* for strcpy(), we cannot use const */

- int state;
- u64 prev_event_time; /* timestamp of previous event */
-
- unsigned int nr_acquired;
unsigned int nr_acquire;
+ unsigned int nr_acquired;
unsigned int nr_contended;
unsigned int nr_release;

+ unsigned int nr_readlock;
+ unsigned int nr_trylock;
/* these times are in nano sec. */
u64 wait_time_total;
u64 wait_time_min;
u64 wait_time_max;
+
+ int discard; /* flag of blacklist */
+};
+
+/*
+ * States of lock_seq_stat
+ *
+ * UNINITIALIZED is required for detecting first event of acquire.
+ * As the nature of lock events, there is no guarantee
+ * that the first event for the locks are acquire,
+ * it can be acquired, contended or release.
+ */
+#define SEQ_STATE_UNINITIALIZED 0 /* initial state */
+#define SEQ_STATE_RELEASED 1
+#define SEQ_STATE_ACQUIRING 2
+#define SEQ_STATE_ACQUIRED 3
+#define SEQ_STATE_READ_ACQUIRED 4
+#define SEQ_STATE_CONTENDED 5
+
+/*
+ * MAX_LOCK_DEPTH
+ * Imported from include/linux/sched.h.
+ * Should this be synchronized?
+ */
+#define MAX_LOCK_DEPTH 48
+
+/*
+ * struct lock_seq_stat:
+ * Place to put on state of one lock sequence
+ * 1) acquire -> acquired -> release
+ * 2) acquire -> contended -> acquired -> release
+ * 3) acquire (with read or try) -> release
+ * 4) Are there other patterns?
+ */
+struct lock_seq_stat {
+ struct list_head list;
+ int state;
+ u64 prev_event_time;
+ void *addr;
+
+ int read_count;
};

+struct thread_stat {
+ struct rb_node rb;
+
+ u32 tid;
+ struct list_head seq_list;
+};
+
+static struct rb_root thread_stats;
+
+static struct thread_stat *thread_stat_find(u32 tid)
+{
+ struct rb_node *node;
+ struct thread_stat *st;
+
+ node = thread_stats.rb_node;
+ while (node) {
+ st = container_of(node, struct thread_stat, rb);
+ if (st->tid == tid)
+ return st;
+ else if (tid < st->tid)
+ node = node->rb_left;
+ else
+ node = node->rb_right;
+ }
+
+ return NULL;
+}
+
+static void thread_stat_insert(struct thread_stat *new)
+{
+ struct rb_node **rb = &thread_stats.rb_node;
+ struct rb_node *parent = NULL;
+ struct thread_stat *p;
+
+ while (*rb) {
+ p = container_of(*rb, struct thread_stat, rb);
+ parent = *rb;
+
+ if (new->tid < p->tid)
+ rb = &(*rb)->rb_left;
+ else if (new->tid > p->tid)
+ rb = &(*rb)->rb_right;
+ else
+ BUG_ON("inserting invalid thread_stat\n");
+ }
+
+ rb_link_node(&new->rb, parent, rb);
+ rb_insert_color(&new->rb, &thread_stats);
+}
+
+static struct thread_stat *thread_stat_findnew_after_first(u32 tid)
+{
+ struct thread_stat *st;
+
+ st = thread_stat_find(tid);
+ if (st)
+ return st;
+
+ st = zalloc(sizeof(struct thread_stat));
+ if (!st)
+ die("memory allocation failed\n");
+
+ st->tid = tid;
+ INIT_LIST_HEAD(&st->seq_list);
+
+ thread_stat_insert(st);
+
+ return st;
+}
+
+static struct thread_stat *thread_stat_findnew_first(u32 tid);
+static struct thread_stat *(*thread_stat_findnew)(u32 tid) =
+ thread_stat_findnew_first;
+
+static struct thread_stat *thread_stat_findnew_first(u32 tid)
+{
+ struct thread_stat *st;
+
+ st = zalloc(sizeof(struct thread_stat));
+ if (!st)
+ die("memory allocation failed\n");
+ st->tid = tid;
+ INIT_LIST_HEAD(&st->seq_list);
+
+ rb_link_node(&st->rb, NULL, &thread_stats.rb_node);
+ rb_insert_color(&st->rb, &thread_stats);
+
+ thread_stat_findnew = thread_stat_findnew_after_first;
+ return st;
+}
+
/* build simple key function one is bigger than two */
#define SINGLE_KEY(member) \
static int lock_stat_key_ ## member(struct lock_stat *one, \
@@ -175,8 +305,6 @@ static struct lock_stat *lock_stat_findnew(void *addr, const char *name)
goto alloc_failed;
strcpy(new->name, name);

- /* LOCK_STATE_UNLOCKED == 0 isn't guaranteed forever */
- new->state = LOCK_STATE_UNLOCKED;
new->wait_time_min = ULLONG_MAX;

list_add(&new->hash_entry, entry);
@@ -198,6 +326,7 @@ struct raw_event_sample {
struct trace_acquire_event {
void *addr;
const char *name;
+ int flag;
};

struct trace_acquired_event {
@@ -241,120 +370,246 @@ struct trace_lock_handler {
struct thread *thread);
};

+static struct lock_seq_stat *get_seq(struct thread_stat *ts, void *addr)
+{
+ struct lock_seq_stat *seq;
+
+ list_for_each_entry(seq, &ts->seq_list, list) {
+ if (seq->addr == addr)
+ return seq;
+ }
+
+ seq = zalloc(sizeof(struct lock_seq_stat));
+ if (!seq)
+ die("Not enough memory\n");
+ seq->state = SEQ_STATE_UNINITIALIZED;
+ seq->addr = addr;
+
+ list_add(&seq->list, &ts->seq_list);
+ return seq;
+}
+
+static int bad_hist[4];
+
static void
report_lock_acquire_event(struct trace_acquire_event *acquire_event,
struct event *__event __used,
int cpu __used,
- u64 timestamp,
+ u64 timestamp __used,
struct thread *thread __used)
{
- struct lock_stat *st;
+ struct lock_stat *ls;
+ struct thread_stat *ts;
+ struct lock_seq_stat *seq;
+
+ ls = lock_stat_findnew(acquire_event->addr, acquire_event->name);
+ if (ls->discard)
+ return;

- st = lock_stat_findnew(acquire_event->addr, acquire_event->name);
+ ts = thread_stat_findnew(thread->pid);
+ seq = get_seq(ts, acquire_event->addr);

- switch (st->state) {
- case LOCK_STATE_UNLOCKED:
+ switch (seq->state) {
+ case SEQ_STATE_UNINITIALIZED:
+ case SEQ_STATE_RELEASED:
+ if (!acquire_event->flag) {
+ seq->state = SEQ_STATE_ACQUIRING;
+ } else {
+ if (acquire_event->flag & 1)
+ ls->nr_trylock++;
+ if (acquire_event->flag & 2)
+ ls->nr_readlock++;
+ seq->state = SEQ_STATE_READ_ACQUIRED;
+ seq->read_count = 1;
+ ls->nr_acquired++;
+ }
+ break;
+ case SEQ_STATE_READ_ACQUIRED:
+ if (acquire_event->flag & 2) {
+ seq->read_count++;
+ ls->nr_acquired++;
+ goto end;
+ } else {
+ goto broken;
+ }
break;
- case LOCK_STATE_LOCKED:
+ case SEQ_STATE_ACQUIRED:
+ case SEQ_STATE_ACQUIRING:
+ case SEQ_STATE_CONTENDED:
+broken:
+ /* broken lock sequence, discard it */
+ ls->discard = 1;
+ bad_hist[0]++;
+ list_del(&seq->list);
+ free(seq);
+ goto end;
break;
default:
- BUG_ON(1);
+ BUG_ON("Unknown state of lock sequence found!\n");
break;
}

- st->prev_event_time = timestamp;
+ ls->nr_acquire++;
+ seq->prev_event_time = timestamp;
+end:
+ return;
}

static void
report_lock_acquired_event(struct trace_acquired_event *acquired_event,
struct event *__event __used,
int cpu __used,
- u64 timestamp,
+ u64 timestamp __used,
struct thread *thread __used)
{
- struct lock_stat *st;
+ struct lock_stat *ls;
+ struct thread_stat *ts;
+ struct lock_seq_stat *seq;
+ u64 contended_term;

- st = lock_stat_findnew(acquired_event->addr, acquired_event->name);
+ ls = lock_stat_findnew(acquired_event->addr, acquired_event->name);
+ if (ls->discard)
+ return;
+
+ ts = thread_stat_findnew(thread->pid);
+ seq = get_seq(ts, acquired_event->addr);

- switch (st->state) {
- case LOCK_STATE_UNLOCKED:
- st->state = LOCK_STATE_LOCKED;
- st->nr_acquired++;
+ switch (seq->state) {
+ case SEQ_STATE_UNINITIALIZED:
+ /* orphan event, do nothing */
+ return;
+ case SEQ_STATE_ACQUIRING:
break;
- case LOCK_STATE_LOCKED:
+ case SEQ_STATE_CONTENDED:
+ contended_term = timestamp - seq->prev_event_time;
+ ls->wait_time_total += contended_term;
+
+ if (contended_term < ls->wait_time_min)
+ ls->wait_time_min = contended_term;
+ else if (ls->wait_time_max < contended_term)
+ ls->wait_time_max = contended_term;
break;
+ case SEQ_STATE_RELEASED:
+ case SEQ_STATE_ACQUIRED:
+ case SEQ_STATE_READ_ACQUIRED:
+ /* broken lock sequence, discard it */
+ ls->discard = 1;
+ bad_hist[1]++;
+ list_del(&seq->list);
+ free(seq);
+ goto end;
+ break;
+
default:
- BUG_ON(1);
+ BUG_ON("Unknown state of lock sequence found!\n");
break;
}

- st->prev_event_time = timestamp;
+ seq->state = SEQ_STATE_ACQUIRED;
+ ls->nr_acquired++;
+ seq->prev_event_time = timestamp;
+end:
+ return;
}

static void
report_lock_contended_event(struct trace_contended_event *contended_event,
struct event *__event __used,
int cpu __used,
- u64 timestamp,
+ u64 timestamp __used,
struct thread *thread __used)
{
- struct lock_stat *st;
+ struct lock_stat *ls;
+ struct thread_stat *ts;
+ struct lock_seq_stat *seq;
+
+ ls = lock_stat_findnew(contended_event->addr, contended_event->name);
+ if (ls->discard)
+ return;

- st = lock_stat_findnew(contended_event->addr, contended_event->name);
+ ts = thread_stat_findnew(thread->pid);
+ seq = get_seq(ts, contended_event->addr);

- switch (st->state) {
- case LOCK_STATE_UNLOCKED:
+ switch (seq->state) {
+ case SEQ_STATE_UNINITIALIZED:
+ /* orphan event, do nothing */
+ return;
+ case SEQ_STATE_ACQUIRING:
break;
- case LOCK_STATE_LOCKED:
- st->nr_contended++;
+ case SEQ_STATE_RELEASED:
+ case SEQ_STATE_ACQUIRED:
+ case SEQ_STATE_READ_ACQUIRED:
+ case SEQ_STATE_CONTENDED:
+ /* broken lock sequence, discard it */
+ ls->discard = 1;
+ bad_hist[2]++;
+ list_del(&seq->list);
+ free(seq);
+ goto end;
break;
default:
- BUG_ON(1);
+ BUG_ON("Unknown state of lock sequence found!\n");
break;
}

- st->prev_event_time = timestamp;
+ seq->state = SEQ_STATE_CONTENDED;
+ ls->nr_contended++;
+ seq->prev_event_time = timestamp;
+end:
+ return;
}

static void
report_lock_release_event(struct trace_release_event *release_event,
struct event *__event __used,
int cpu __used,
- u64 timestamp,
+ u64 timestamp __used,
struct thread *thread __used)
{
- struct lock_stat *st;
- u64 hold_time;
+ struct lock_stat *ls;
+ struct thread_stat *ts;
+ struct lock_seq_stat *seq;

- st = lock_stat_findnew(release_event->addr, release_event->name);
+ ls = lock_stat_findnew(release_event->addr, release_event->name);
+ if (ls->discard)
+ return;

- switch (st->state) {
- case LOCK_STATE_UNLOCKED:
- break;
- case LOCK_STATE_LOCKED:
- st->state = LOCK_STATE_UNLOCKED;
- hold_time = timestamp - st->prev_event_time;
+ ts = thread_stat_findnew(thread->pid);
+ seq = get_seq(ts, release_event->addr);

- if (timestamp < st->prev_event_time) {
- /* terribly, this can happen... */
+ switch (seq->state) {
+ case SEQ_STATE_UNINITIALIZED:
+ goto end;
+ break;
+ case SEQ_STATE_ACQUIRED:
+ break;
+ case SEQ_STATE_READ_ACQUIRED:
+ seq->read_count--;
+ BUG_ON(seq->read_count < 0);
+ if (!seq->read_count) {
+ ls->nr_release++;
goto end;
}
-
- if (st->wait_time_min > hold_time)
- st->wait_time_min = hold_time;
- if (st->wait_time_max < hold_time)
- st->wait_time_max = hold_time;
- st->wait_time_total += hold_time;
-
- st->nr_release++;
+ break;
+ case SEQ_STATE_ACQUIRING:
+ case SEQ_STATE_CONTENDED:
+ case SEQ_STATE_RELEASED:
+ /* broken lock sequence, discard it */
+ ls->discard = 1;
+ bad_hist[3]++;
+ goto free_seq;
break;
default:
- BUG_ON(1);
+ BUG_ON("Unknown state of lock sequence found!\n");
break;
}

+ ls->nr_release++;
+free_seq:
+ list_del(&seq->list);
+ free(seq);
end:
- st->prev_event_time = timestamp;
+ return;
}

/* lock oriented handlers */
@@ -381,6 +636,7 @@ process_lock_acquire_event(void *data,
tmp = raw_field_value(event, "lockdep_addr", data);
memcpy(&acquire_event.addr, &tmp, sizeof(void *));
acquire_event.name = (char *)raw_field_ptr(event, "name", data);
+ acquire_event.flag = (int)raw_field_value(event, "flag", data);

if (trace_handler->acquire_event)
trace_handler->acquire_event(&acquire_event, event, cpu, timestamp, thread);
@@ -441,8 +697,8 @@ process_lock_release_event(void *data,
}

static void
-process_raw_event(void *data, int cpu,
- u64 timestamp, struct thread *thread)
+process_raw_event(void *data, int cpu __used,
+ u64 timestamp __used, struct thread *thread __used)
{
struct event *event;
int type;
@@ -604,14 +860,15 @@ static void queue_raw_event(void *data, int raw_size, int cpu,
}
}

-static int process_sample_event(event_t *event, struct perf_session *session)
+static int process_sample_event(event_t *event, struct perf_session *s)
{
struct thread *thread;
struct sample_data data;

bzero(&data, sizeof(struct sample_data));
- event__parse_sample(event, session->sample_type, &data);
- thread = perf_session__findnew(session, data.pid);
+ event__parse_sample(event, s->sample_type, &data);
+ /* CAUTION: using tid as thread.pid */
+ thread = perf_session__findnew(s, data.tid);

if (thread == NULL) {
pr_debug("problem processing %d event, skipping it.\n",
@@ -634,8 +891,8 @@ static void print_result(void)
{
struct lock_stat *st;
char cut_name[20];
+ int bad, total;

- printf("%18s ", "ID");
printf("%20s ", "Name");
printf("%10s ", "acquired");
printf("%10s ", "contended");
@@ -646,11 +903,15 @@ static void print_result(void)

printf("\n\n");

+ bad = total = 0;
while ((st = pop_from_result())) {
+ total++;
+ if (st->discard) {
+ bad++;
+ continue;
+ }
bzero(cut_name, 20);

- printf("%p ", st->addr);
-
if (strlen(st->name) < 16) {
/* output raw name */
printf("%20s ", st->name);
@@ -673,6 +934,21 @@ static void print_result(void)
0 : st->wait_time_min);
printf("\n");
}
+
+ {
+ /* Output for debug, this have to be removed */
+ int i;
+ const char *name[4] =
+ { "acquire", "acquired", "contended", "release" };
+
+ printf("\n=== output for debug===\n\n");
+ printf("bad:%d, total:%d\n", bad, total);
+ printf("bad rate:%f\n", (double)(bad / total));
+
+ printf("histogram of events caused bad sequence\n");
+ for (i = 0; i < 4; i++)
+ printf(" %10s: %d\n", name[i], bad_hist[i]);
+ }
}

static void dump_map(void)
@@ -692,8 +968,6 @@ static struct perf_event_ops eops = {
.comm = event__process_comm,
};

-static struct perf_session *session;
-
static int read_events(void)
{
session = perf_session__new(input_name, O_RDONLY, 0);
--
1.6.2.3

2010-04-24 02:06:19

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 3/9] perf: Generalize perf lock's sample event reordering to the session layer

The sample events recorded by perf record are not time ordered
because we have one buffer per cpu for each event (even demultiplexed
per task/per cpu for task bound events). But when we read trace events
we want them to be ordered by time because many state machines are
involved.

There are currently two ways perf tools deal with that:

- use -M to multiplex every buffers (perf sched, perf kmem)
But this creates a lot of contention in SMP machines on
record time.

- use a post-processing time reordering (perf timechart, perf lock)
The reordering used by timechart is simple but doesn't scale well
with huge flow of events, in terms of performance and memory use
(unusable with perf lock for example).
Perf lock has its own samples reordering that flushes its memory
use in a regular basis and that uses a sorting based on the
previous event queued (a new event to be queued is close to the
previous one most of the time).

This patch proposes to export perf lock's samples reordering facility
to the session layer that reads the events. So if a tool wants to
get ordered sample events, it needs to set its
struct perf_event_ops::ordered_samples to true and that's it.

This prepares tracing based perf tools to get rid of the need to
use buffers multiplexing (-M) or to implement their own
reordering.

Also lower the flush period to 2 as it's sufficient already.

Signed-off-by: Frederic Weisbecker <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Hitoshi Mitake <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Masami Hiramatsu <[email protected]>
Cc: Tom Zanussi <[email protected]>
---
tools/perf/builtin-lock.c | 197 +++++----------------------------------------
tools/perf/util/session.c | 179 ++++++++++++++++++++++++++++++++++++++++-
tools/perf/util/session.h | 10 +++
3 files changed, 210 insertions(+), 176 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 716d8c5..ce27675 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -316,8 +316,6 @@ alloc_failed:

static char const *input_name = "perf.data";

-static int profile_cpu = -1;
-
struct raw_event_sample {
u32 size;
char data[0];
@@ -697,8 +695,7 @@ process_lock_release_event(void *data,
}

static void
-process_raw_event(void *data, int cpu __used,
- u64 timestamp __used, struct thread *thread __used)
+process_raw_event(void *data, int cpu, u64 timestamp, struct thread *thread)
{
struct event *event;
int type;
@@ -716,176 +713,6 @@ process_raw_event(void *data, int cpu __used,
process_lock_release_event(data, event, cpu, timestamp, thread);
}

-struct raw_event_queue {
- u64 timestamp;
- int cpu;
- void *data;
- struct thread *thread;
- struct list_head list;
-};
-
-static LIST_HEAD(raw_event_head);
-
-#define FLUSH_PERIOD (5 * NSEC_PER_SEC)
-
-static u64 flush_limit = ULLONG_MAX;
-static u64 last_flush = 0;
-struct raw_event_queue *last_inserted;
-
-static void flush_raw_event_queue(u64 limit)
-{
- struct raw_event_queue *tmp, *iter;
-
- list_for_each_entry_safe(iter, tmp, &raw_event_head, list) {
- if (iter->timestamp > limit)
- return;
-
- if (iter == last_inserted)
- last_inserted = NULL;
-
- process_raw_event(iter->data, iter->cpu, iter->timestamp,
- iter->thread);
-
- last_flush = iter->timestamp;
- list_del(&iter->list);
- free(iter->data);
- free(iter);
- }
-}
-
-static void __queue_raw_event_end(struct raw_event_queue *new)
-{
- struct raw_event_queue *iter;
-
- list_for_each_entry_reverse(iter, &raw_event_head, list) {
- if (iter->timestamp < new->timestamp) {
- list_add(&new->list, &iter->list);
- return;
- }
- }
-
- list_add(&new->list, &raw_event_head);
-}
-
-static void __queue_raw_event_before(struct raw_event_queue *new,
- struct raw_event_queue *iter)
-{
- list_for_each_entry_continue_reverse(iter, &raw_event_head, list) {
- if (iter->timestamp < new->timestamp) {
- list_add(&new->list, &iter->list);
- return;
- }
- }
-
- list_add(&new->list, &raw_event_head);
-}
-
-static void __queue_raw_event_after(struct raw_event_queue *new,
- struct raw_event_queue *iter)
-{
- list_for_each_entry_continue(iter, &raw_event_head, list) {
- if (iter->timestamp > new->timestamp) {
- list_add_tail(&new->list, &iter->list);
- return;
- }
- }
- list_add_tail(&new->list, &raw_event_head);
-}
-
-/* The queue is ordered by time */
-static void __queue_raw_event(struct raw_event_queue *new)
-{
- if (!last_inserted) {
- __queue_raw_event_end(new);
- return;
- }
-
- /*
- * Most of the time the current event has a timestamp
- * very close to the last event inserted, unless we just switched
- * to another event buffer. Having a sorting based on a list and
- * on the last inserted event that is close to the current one is
- * probably more efficient than an rbtree based sorting.
- */
- if (last_inserted->timestamp >= new->timestamp)
- __queue_raw_event_before(new, last_inserted);
- else
- __queue_raw_event_after(new, last_inserted);
-}
-
-static void queue_raw_event(void *data, int raw_size, int cpu,
- u64 timestamp, struct thread *thread)
-{
- struct raw_event_queue *new;
-
- if (flush_limit == ULLONG_MAX)
- flush_limit = timestamp + FLUSH_PERIOD;
-
- if (timestamp < last_flush) {
- printf("Warning: Timestamp below last timeslice flush\n");
- return;
- }
-
- new = malloc(sizeof(*new));
- if (!new)
- die("Not enough memory\n");
-
- new->timestamp = timestamp;
- new->cpu = cpu;
- new->thread = thread;
-
- new->data = malloc(raw_size);
- if (!new->data)
- die("Not enough memory\n");
-
- memcpy(new->data, data, raw_size);
-
- __queue_raw_event(new);
- last_inserted = new;
-
- /*
- * We want to have a slice of events covering 2 * FLUSH_PERIOD
- * If FLUSH_PERIOD is big enough, it ensures every events that occured
- * in the first half of the timeslice have all been buffered and there
- * are none remaining (we need that because of the weakly ordered
- * event recording we have). Then once we reach the 2 * FLUSH_PERIOD
- * timeslice, we flush the first half to be gentle with the memory
- * (the second half can still get new events in the middle, so wait
- * another period to flush it)
- */
- if (new->timestamp > flush_limit &&
- new->timestamp - flush_limit > FLUSH_PERIOD) {
- flush_limit += FLUSH_PERIOD;
- flush_raw_event_queue(flush_limit);
- }
-}
-
-static int process_sample_event(event_t *event, struct perf_session *s)
-{
- struct thread *thread;
- struct sample_data data;
-
- bzero(&data, sizeof(struct sample_data));
- event__parse_sample(event, s->sample_type, &data);
- /* CAUTION: using tid as thread.pid */
- thread = perf_session__findnew(s, data.tid);
-
- if (thread == NULL) {
- pr_debug("problem processing %d event, skipping it.\n",
- event->header.type);
- return -1;
- }
-
- dump_printf(" ... thread: %s:%d\n", thread->comm, thread->pid);
-
- if (profile_cpu != -1 && profile_cpu != (int) data.cpu)
- return 0;
-
- queue_raw_event(data.raw_data, data.raw_size, data.cpu, data.time, thread);
-
- return 0;
-}
-
/* TODO: various way to print, coloring, nano or milli sec */
static void print_result(void)
{
@@ -963,9 +790,30 @@ static void dump_map(void)
}
}

+static int process_sample_event(event_t *self, struct perf_session *s)
+{
+ struct sample_data data;
+ struct thread *thread;
+
+ bzero(&data, sizeof(data));
+ event__parse_sample(self, s->sample_type, &data);
+
+ thread = perf_session__findnew(s, data.tid);
+ if (thread == NULL) {
+ pr_debug("problem processing %d event, skipping it.\n",
+ self->header.type);
+ return -1;
+ }
+
+ process_raw_event(data.raw_data, data.cpu, data.time, thread);
+
+ return 0;
+}
+
static struct perf_event_ops eops = {
.sample = process_sample_event,
.comm = event__process_comm,
+ .ordered_samples = true,
};

static int read_events(void)
@@ -994,7 +842,6 @@ static void __cmd_report(void)
setup_pager();
select_key();
read_events();
- flush_raw_event_queue(ULLONG_MAX);
sort_result();
print_result();
}
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 7d88ae5..b7aade2 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -98,6 +98,8 @@ struct perf_session *perf_session__new(const char *filename, int mode, bool forc
self->cwdlen = 0;
self->unknown_events = 0;
self->kerninfo_root = RB_ROOT;
+ self->ordered_samples.flush_limit = ULLONG_MAX;
+ INIT_LIST_HEAD(&self->ordered_samples.samples_head);

if (mode == O_RDONLY) {
if (perf_session__open(self, force) < 0)
@@ -351,6 +353,178 @@ static event__swap_op event__swap_ops[] = {
[PERF_RECORD_HEADER_MAX] = NULL,
};

+struct sample_queue {
+ u64 timestamp;
+ struct sample_event *event;
+ struct list_head list;
+};
+
+#define FLUSH_PERIOD (2 * NSEC_PER_SEC)
+
+static void flush_sample_queue(struct perf_session *s,
+ struct perf_event_ops *ops)
+{
+ struct list_head *head = &s->ordered_samples.samples_head;
+ u64 limit = s->ordered_samples.flush_limit;
+ struct sample_queue *tmp, *iter;
+
+ if (!ops->ordered_samples)
+ return;
+
+ list_for_each_entry_safe(iter, tmp, head, list) {
+ if (iter->timestamp > limit)
+ return;
+
+ if (iter == s->ordered_samples.last_inserted)
+ s->ordered_samples.last_inserted = NULL;
+
+ ops->sample((event_t *)iter->event, s);
+
+ s->ordered_samples.last_flush = iter->timestamp;
+ list_del(&iter->list);
+ free(iter->event);
+ free(iter);
+ }
+}
+
+static void __queue_sample_end(struct sample_queue *new, struct list_head *head)
+{
+ struct sample_queue *iter;
+
+ list_for_each_entry_reverse(iter, head, list) {
+ if (iter->timestamp < new->timestamp) {
+ list_add(&new->list, &iter->list);
+ return;
+ }
+ }
+
+ list_add(&new->list, head);
+}
+
+static void __queue_sample_before(struct sample_queue *new,
+ struct sample_queue *iter,
+ struct list_head *head)
+{
+ list_for_each_entry_continue_reverse(iter, head, list) {
+ if (iter->timestamp < new->timestamp) {
+ list_add(&new->list, &iter->list);
+ return;
+ }
+ }
+
+ list_add(&new->list, head);
+}
+
+static void __queue_sample_after(struct sample_queue *new,
+ struct sample_queue *iter,
+ struct list_head *head)
+{
+ list_for_each_entry_continue(iter, head, list) {
+ if (iter->timestamp > new->timestamp) {
+ list_add_tail(&new->list, &iter->list);
+ return;
+ }
+ }
+ list_add_tail(&new->list, head);
+}
+
+/* The queue is ordered by time */
+static void __queue_sample_event(struct sample_queue *new,
+ struct perf_session *s)
+{
+ struct sample_queue *last_inserted = s->ordered_samples.last_inserted;
+ struct list_head *head = &s->ordered_samples.samples_head;
+
+
+ if (!last_inserted) {
+ __queue_sample_end(new, head);
+ return;
+ }
+
+ /*
+ * Most of the time the current event has a timestamp
+ * very close to the last event inserted, unless we just switched
+ * to another event buffer. Having a sorting based on a list and
+ * on the last inserted event that is close to the current one is
+ * probably more efficient than an rbtree based sorting.
+ */
+ if (last_inserted->timestamp >= new->timestamp)
+ __queue_sample_before(new, last_inserted, head);
+ else
+ __queue_sample_after(new, last_inserted, head);
+}
+
+static int queue_sample_event(event_t *event, struct sample_data *data,
+ struct perf_session *s,
+ struct perf_event_ops *ops)
+{
+ u64 timestamp = data->time;
+ struct sample_queue *new;
+ u64 flush_limit;
+
+
+ if (s->ordered_samples.flush_limit == ULLONG_MAX)
+ s->ordered_samples.flush_limit = timestamp + FLUSH_PERIOD;
+
+ if (timestamp < s->ordered_samples.last_flush) {
+ printf("Warning: Timestamp below last timeslice flush\n");
+ return -EINVAL;
+ }
+
+ new = malloc(sizeof(*new));
+ if (!new)
+ return -ENOMEM;
+
+ new->timestamp = timestamp;
+
+ new->event = malloc(event->header.size);
+ if (!new->event) {
+ free(new);
+ return -ENOMEM;
+ }
+
+ memcpy(new->event, event, event->header.size);
+
+ __queue_sample_event(new, s);
+ s->ordered_samples.last_inserted = new;
+
+ /*
+ * We want to have a slice of events covering 2 * FLUSH_PERIOD
+ * If FLUSH_PERIOD is big enough, it ensures every events that occured
+ * in the first half of the timeslice have all been buffered and there
+ * are none remaining (we need that because of the weakly ordered
+ * event recording we have). Then once we reach the 2 * FLUSH_PERIOD
+ * timeslice, we flush the first half to be gentle with the memory
+ * (the second half can still get new events in the middle, so wait
+ * another period to flush it)
+ */
+ flush_limit = s->ordered_samples.flush_limit;
+
+ if (new->timestamp > flush_limit &&
+ new->timestamp - flush_limit > FLUSH_PERIOD) {
+ s->ordered_samples.flush_limit += FLUSH_PERIOD;
+ flush_sample_queue(s, ops);
+ }
+
+ return 0;
+}
+
+static int perf_session__process_sample(event_t *event, struct perf_session *s,
+ struct perf_event_ops *ops)
+{
+ struct sample_data data;
+
+ if (!ops->ordered_samples)
+ return ops->sample(event, s);
+
+ bzero(&data, sizeof(struct sample_data));
+ event__parse_sample(event, s->sample_type, &data);
+
+ queue_sample_event(event, &data, s, ops);
+
+ return 0;
+}
+
static int perf_session__process_event(struct perf_session *self,
event_t *event,
struct perf_event_ops *ops,
@@ -371,7 +545,7 @@ static int perf_session__process_event(struct perf_session *self,

switch (event->header.type) {
case PERF_RECORD_SAMPLE:
- return ops->sample(event, self);
+ return perf_session__process_sample(event, self, ops);
case PERF_RECORD_MMAP:
return ops->mmap(event, self);
case PERF_RECORD_COMM:
@@ -611,6 +785,9 @@ more:
goto more;
done:
err = 0;
+ /* do the final flush for ordered samples */
+ self->ordered_samples.flush_limit = ULLONG_MAX;
+ flush_sample_queue(self, ops);
out_err:
ui_progress__delete(progress);
return err;
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index 5e47c87..796e229 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -8,9 +8,17 @@
#include <linux/rbtree.h>
#include "../../../include/linux/perf_event.h"

+struct sample_queue;
struct ip_callchain;
struct thread;

+struct ordered_samples {
+ u64 last_flush;
+ u64 flush_limit;
+ struct list_head samples_head;
+ struct sample_queue *last_inserted;
+};
+
struct perf_session {
struct perf_header header;
unsigned long size;
@@ -28,6 +36,7 @@ struct perf_session {
bool fd_pipe;
int cwdlen;
char *cwd;
+ struct ordered_samples ordered_samples;
char filename[0];
};

@@ -47,6 +56,7 @@ struct perf_event_ops {
event_type,
tracing_data,
build_id;
+ bool ordered_samples;
};

struct perf_session *perf_session__new(const char *filename, int mode, bool force);
--
1.6.2.3

2010-04-24 02:06:24

by Frederic Weisbecker

[permalink] [raw]
Subject: [PATCH 5/9] perf: Use generic sample reordering in perf kmem

Use the new generic sample events reordering from perf kmem,
this drops the need of multiplexing the buffers on record time,
improving the scalability of perf kmem.

Signed-off-by: Frederic Weisbecker <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Hitoshi Mitake <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Masami Hiramatsu <[email protected]>
Cc: Tom Zanussi <[email protected]>
Cc: Pekka Enberg <[email protected]>
Cc: Li Zefan <[email protected]>
---
tools/perf/builtin-kmem.c | 6 +++---
1 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/tools/perf/builtin-kmem.c b/tools/perf/builtin-kmem.c
index db474bb..ab906cb 100644
--- a/tools/perf/builtin-kmem.c
+++ b/tools/perf/builtin-kmem.c
@@ -335,8 +335,9 @@ static int process_sample_event(event_t *event, struct perf_session *session)
}

static struct perf_event_ops event_ops = {
- .sample = process_sample_event,
- .comm = event__process_comm,
+ .sample = process_sample_event,
+ .comm = event__process_comm,
+ .ordered_samples = true,
};

static double fragmentation(unsigned long n_req, unsigned long n_alloc)
@@ -730,7 +731,6 @@ static const char *record_args[] = {
"record",
"-a",
"-R",
- "-M",
"-f",
"-c", "1",
"-e", "kmem:kmalloc",
--
1.6.2.3

2010-04-24 02:27:25

by Frederic Weisbecker

[permalink] [raw]
Subject: Re: [GIT PULL] perf tools updates

On Sat, Apr 24, 2010 at 04:05:33AM +0200, Frederic Weisbecker wrote:
> Ingo,
>
> Please pull the perf/core branch that can be found at:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git
> perf/core
>
> Thanks,
> Frederic



I forgot to highlight some things here.

- The -M option is not used anymore. Well actually I just checked and it's
used by the record perl/python scripts. But it's not needed there anymore, so
I'll drop it in another pass. But globally it's over with the buffers
multiplexing needs.

- But I haven't plugged the reordering thing to the live mode, because I'm
not sure exactly if that would be welcome. With live mode we want the
events as they arrive, using the reordering there would make it get the
events per bunches of 2 seconds slices. I guess we'll figure out a solution
for that.

- Perf lock gets into a better shape. There is still some work to make
it truly usable though. I need to unearth the event injection thing
to lower the size of the events, profile by lock classes, etc...

- Various important fixes

Thanks.

2010-04-24 10:43:35

by Hitoshi Mitake

[permalink] [raw]
Subject: [PATCH] perf lock: add "info" subcommand for dumping misc information

Hi Frederic,

I added "info" subcommand to perf lock,
this can be used as dumping metadata like thread or address of lock instances.
"map" was removed because info should do the work of it.

This will be useful not only for debugging but also for ordinary analyzing.

I made this patch on perf/core of your tree, could you queue this?

Signed-off-by: Hitoshi Mitake <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Jens Axboe <[email protected]>
Cc: Jason Baron <[email protected]>
Cc: Xiao Guangrong <[email protected]>
---
tools/perf/builtin-lock.c | 68 +++++++++++++++++++++++++++++++++++++++++++--
1 files changed, 65 insertions(+), 3 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index ce27675..c54211e 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -778,18 +778,61 @@ static void print_result(void)
}
}

+static int info_threads;
+static int info_map;
+
+static void rec_dump_threads(struct rb_node *node)
+{
+ struct thread_stat *st;
+ struct thread *t;
+
+ if (!node)
+ return;
+
+ if (node->rb_left)
+ rec_dump_threads(node->rb_left);
+
+ st = container_of(node, struct thread_stat, rb);
+ BUG_ON(!st);
+ t = perf_session__findnew(session, st->tid);
+ BUG_ON(!t);
+
+ printf("%10d: %s\n", st->tid, t->comm);
+
+ if (node->rb_right)
+ rec_dump_threads(node->rb_right);
+}
+
+static void dump_threads(void)
+{
+ printf("%10s: comm\n", "Thread ID");
+ rec_dump_threads(thread_stats.rb_node);
+}
+
static void dump_map(void)
{
unsigned int i;
struct lock_stat *st;

+ printf("Address of instance: name of class\n");
for (i = 0; i < LOCKHASH_SIZE; i++) {
list_for_each_entry(st, &lockhash_table[i], hash_entry) {
- printf("%p: %s\n", st->addr, st->name);
+ printf(" %p: %s\n", st->addr, st->name);
}
}
}

+static void dump_info(void)
+{
+ /* ugly... */
+ if (info_threads)
+ dump_threads();
+ else if (info_map)
+ dump_map();
+ else
+ die("Unknown type of information\n");
+}
+
static int process_sample_event(event_t *self, struct perf_session *s)
{
struct sample_data data;
@@ -858,6 +901,19 @@ static const struct option report_options[] = {
OPT_END()
};

+static const char * const info_usage[] = {
+ "perf lock info [<options>]",
+ NULL
+};
+
+static const struct option info_options[] = {
+ OPT_BOOLEAN('t', "threads", &info_threads,
+ "dump thread list in perf.data"),
+ OPT_BOOLEAN('m', "map", &info_map,
+ "map of lock instances (name:address table)"),
+ OPT_END()
+};
+
static const char * const lock_usage[] = {
"perf lock [<options>] {record|trace|report}",
NULL
@@ -929,12 +985,18 @@ int cmd_lock(int argc, const char **argv, const char *prefix __used)
} else if (!strcmp(argv[0], "trace")) {
/* Aliased to 'perf trace' */
return cmd_trace(argc, argv, prefix);
- } else if (!strcmp(argv[0], "map")) {
+ } else if (!strcmp(argv[0], "info")) {
+ if (argc) {
+ argc = parse_options(argc, argv,
+ info_options, info_usage, 0);
+ if (argc)
+ usage_with_options(info_usage, info_options);
+ }
/* recycling report_lock_ops */
trace_handler = &report_lock_ops;
setup_pager();
read_events();
- dump_map();
+ dump_info();
} else {
usage_with_options(lock_usage, lock_options);
}
--
1.6.5.2

2010-04-24 10:46:17

by Hitoshi Mitake

[permalink] [raw]
Subject: Re: [PATCH] perf lock: add "info" subcommand for dumping misc information

On 04/24/10 19:43, Hitoshi Mitake wrote:
> Hi Frederic,
>
> I added "info" subcommand to perf lock,
> this can be used as dumping metadata like thread or address of lock
instances.
> "map" was removed because info should do the work of it.
>
> This will be useful not only for debugging but also for ordinary
analyzing.
>
> I made this patch on perf/core of your tree, could you queue this?

Sorry, I should add example of usage :(
I resend v2, please discard it.

2010-04-24 10:46:43

by Hitoshi Mitake

[permalink] [raw]
Subject: [PATCH v2] perf lock: add "info" subcommand for dumping misc information

Hi Frederic,

I added "info" subcommand to perf lock,
this can be used as dumping metadata like thread or address of lock instances.
"map" was removed because info should do the work of it.

This will be useful not only for debugging but also for ordinary analyzing.

I made this patch on perf/core of your tree, could you queue this?

v2: adding example of usage
% sudo ./perf lock info -t
| Thread ID: comm
| 0: swapper
| 1: init
| 18: migration/5
| 29: events/2
| 32: events/5
| 33: events/6
...

% sudo ./perf lock info -m
| Address of instance: name of class
| 0xffff8800b95adae0: &(&sighand->siglock)->rlock
| 0xffff8800bbb41ae0: &(&sighand->siglock)->rlock
| 0xffff8800bf165ae0: &(&sighand->siglock)->rlock
| 0xffff8800b9576a98: &p->cred_guard_mutex
| 0xffff8800bb890a08: &(&p->alloc_lock)->rlock
| 0xffff8800b9522a08: &(&p->alloc_lock)->rlock
| 0xffff8800bb8aaa08: &(&p->alloc_lock)->rlock
| 0xffff8800bba72a08: &(&p->alloc_lock)->rlock
| 0xffff8800bf18ea08: &(&p->alloc_lock)->rlock
| 0xffff8800b8a0d8a0: &(&ip->i_lock)->mr_lock
| 0xffff88009bf818a0: &(&ip->i_lock)->mr_lock
| 0xffff88004c66b8a0: &(&ip->i_lock)->mr_lock
| 0xffff8800bb6478a0: &(shost->host_lock)->rlock
Signed-off-by: Hitoshi Mitake <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Paul Mackerras <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: Jens Axboe <[email protected]>
Cc: Jason Baron <[email protected]>
Cc: Xiao Guangrong <[email protected]>
---
tools/perf/builtin-lock.c | 68 +++++++++++++++++++++++++++++++++++++++++++--
1 files changed, 65 insertions(+), 3 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index ce27675..c54211e 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -778,18 +778,61 @@ static void print_result(void)
}
}

+static int info_threads;
+static int info_map;
+
+static void rec_dump_threads(struct rb_node *node)
+{
+ struct thread_stat *st;
+ struct thread *t;
+
+ if (!node)
+ return;
+
+ if (node->rb_left)
+ rec_dump_threads(node->rb_left);
+
+ st = container_of(node, struct thread_stat, rb);
+ BUG_ON(!st);
+ t = perf_session__findnew(session, st->tid);
+ BUG_ON(!t);
+
+ printf("%10d: %s\n", st->tid, t->comm);
+
+ if (node->rb_right)
+ rec_dump_threads(node->rb_right);
+}
+
+static void dump_threads(void)
+{
+ printf("%10s: comm\n", "Thread ID");
+ rec_dump_threads(thread_stats.rb_node);
+}
+
static void dump_map(void)
{
unsigned int i;
struct lock_stat *st;

+ printf("Address of instance: name of class\n");
for (i = 0; i < LOCKHASH_SIZE; i++) {
list_for_each_entry(st, &lockhash_table[i], hash_entry) {
- printf("%p: %s\n", st->addr, st->name);
+ printf(" %p: %s\n", st->addr, st->name);
}
}
}

+static void dump_info(void)
+{
+ /* ugly... */
+ if (info_threads)
+ dump_threads();
+ else if (info_map)
+ dump_map();
+ else
+ die("Unknown type of information\n");
+}
+
static int process_sample_event(event_t *self, struct perf_session *s)
{
struct sample_data data;
@@ -858,6 +901,19 @@ static const struct option report_options[] = {
OPT_END()
};

+static const char * const info_usage[] = {
+ "perf lock info [<options>]",
+ NULL
+};
+
+static const struct option info_options[] = {
+ OPT_BOOLEAN('t', "threads", &info_threads,
+ "dump thread list in perf.data"),
+ OPT_BOOLEAN('m', "map", &info_map,
+ "map of lock instances (name:address table)"),
+ OPT_END()
+};
+
static const char * const lock_usage[] = {
"perf lock [<options>] {record|trace|report}",
NULL
@@ -929,12 +985,18 @@ int cmd_lock(int argc, const char **argv, const char *prefix __used)
} else if (!strcmp(argv[0], "trace")) {
/* Aliased to 'perf trace' */
return cmd_trace(argc, argv, prefix);
- } else if (!strcmp(argv[0], "map")) {
+ } else if (!strcmp(argv[0], "info")) {
+ if (argc) {
+ argc = parse_options(argc, argv,
+ info_options, info_usage, 0);
+ if (argc)
+ usage_with_options(info_usage, info_options);
+ }
/* recycling report_lock_ops */
trace_handler = &report_lock_ops;
setup_pager();
read_events();
- dump_map();
+ dump_info();
} else {
usage_with_options(lock_usage, lock_options);
}
--
1.6.5.2

2010-04-24 13:41:38

by Frederic Weisbecker

[permalink] [raw]
Subject: Re: [PATCH v2] perf lock: add "info" subcommand for dumping misc information

On Sat, Apr 24, 2010 at 07:46:41PM +0900, Hitoshi Mitake wrote:
> Hi Frederic,
>
> I added "info" subcommand to perf lock,
> this can be used as dumping metadata like thread or address of lock instances.
> "map" was removed because info should do the work of it.
>
> This will be useful not only for debugging but also for ordinary analyzing.
>
> I made this patch on perf/core of your tree, could you queue this?
>
> v2: adding example of usage
> % sudo ./perf lock info -t
> | Thread ID: comm
> | 0: swapper
> | 1: init
> | 18: migration/5
> | 29: events/2
> | 32: events/5
> | 33: events/6
> ...
>
> % sudo ./perf lock info -m
> | Address of instance: name of class
> | 0xffff8800b95adae0: &(&sighand->siglock)->rlock
> | 0xffff8800bbb41ae0: &(&sighand->siglock)->rlock
> | 0xffff8800bf165ae0: &(&sighand->siglock)->rlock
> | 0xffff8800b9576a98: &p->cred_guard_mutex
> | 0xffff8800bb890a08: &(&p->alloc_lock)->rlock
> | 0xffff8800b9522a08: &(&p->alloc_lock)->rlock
> | 0xffff8800bb8aaa08: &(&p->alloc_lock)->rlock
> | 0xffff8800bba72a08: &(&p->alloc_lock)->rlock
> | 0xffff8800bf18ea08: &(&p->alloc_lock)->rlock
> | 0xffff8800b8a0d8a0: &(&ip->i_lock)->mr_lock
> | 0xffff88009bf818a0: &(&ip->i_lock)->mr_lock
> | 0xffff88004c66b8a0: &(&ip->i_lock)->mr_lock
> | 0xffff8800bb6478a0: &(shost->host_lock)->rlock



Thanks, I queue it for the next pass.

2010-04-24 16:14:03

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH 8/9] perf: Add a perf trace option to check samples ordering reliability

Hi Frederic,

Frederic Weisbecker wrote:
> To ensure sample events time reordering is reliable, add a -d option
> to perf trace to check that automatically.

Just out of curiosity, is there any possibility to add
other debugging options to perf-trace?
If so, I think we can pass some arguments for
this -d option, e.g. "-d ordering,events" and so on.
Just an idea.

Thank you,



--
Masami Hiramatsu
e-mail: [email protected]

2010-04-25 18:08:23

by Frederic Weisbecker

[permalink] [raw]
Subject: Re: [PATCH 8/9] perf: Add a perf trace option to check samples ordering reliability

On Sat, Apr 24, 2010 at 12:13:05PM -0400, Masami Hiramatsu wrote:
> Hi Frederic,
>
> Frederic Weisbecker wrote:
> > To ensure sample events time reordering is reliable, add a -d option
> > to perf trace to check that automatically.
>
> Just out of curiosity, is there any possibility to add
> other debugging options to perf-trace?
> If so, I think we can pass some arguments for
> this -d option, e.g. "-d ordering,events" and so on.
> Just an idea.
>
> Thank you,



Sure, if somebody wants to come with another debugging option
in perf trace, no problem.

2010-04-27 09:16:38

by Ingo Molnar

[permalink] [raw]
Subject: Re: [GIT PULL] perf tools updates


* Frederic Weisbecker <[email protected]> wrote:

> Ingo,
>
> Please pull the perf/core branch that can be found at:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git
> perf/core
>
> Thanks,
> Frederic
> ---
>
> Frederic Weisbecker (6):
> perf: Generalize perf lock's sample event reordering to the session layer
> perf: Use generic sample reordering in perf sched
> perf: Use generic sample reordering in perf kmem
> perf: Use generic sample reordering in perf trace
> perf: Use generic sample reordering in perf timechart
> perf: Add a perf trace option to check samples ordering reliability
>
> Hitoshi Mitake (1):
> perf lock: Fix state machine to recognize lock sequence
>
> Stephane Eranian (1):
> perf: Fix initialization bug in parse_single_tracepoint_event()
>
> William Cohen (1):
> perf: Some perf-kvm documentation edits
>
>
> tools/perf/Documentation/perf-kvm.txt | 9 +-
> tools/perf/builtin-kmem.c | 6 +-
> tools/perf/builtin-lock.c | 595 ++++++++++++++++++++-------------
> tools/perf/builtin-sched.c | 8 +-
> tools/perf/builtin-timechart.c | 112 +------
> tools/perf/builtin-trace.c | 13 +
> tools/perf/util/parse-events.c | 13 +-
> tools/perf/util/session.c | 179 ++++++++++-
> tools/perf/util/session.h | 10 +
> 9 files changed, 583 insertions(+), 362 deletions(-)

Pulled, thanks a lot Frederic!

Ingo

2010-04-30 18:50:10

by Frederic Weisbecker

[permalink] [raw]
Subject: Re: [PATCH v2] perf lock: add "info" subcommand for dumping misc information

On Sat, Apr 24, 2010 at 07:46:41PM +0900, Hitoshi Mitake wrote:
> Hi Frederic,
>
> I added "info" subcommand to perf lock,
> this can be used as dumping metadata like thread or address of lock instances.
> "map" was removed because info should do the work of it.
>
> This will be useful not only for debugging but also for ordinary analyzing.
>
> I made this patch on perf/core of your tree, could you queue this?
>
> v2: adding example of usage
> % sudo ./perf lock info -t
> | Thread ID: comm
> | 0: swapper
> | 1: init
> | 18: migration/5
> | 29: events/2
> | 32: events/5
> | 33: events/6
> ...
>
> % sudo ./perf lock info -m
> | Address of instance: name of class
> | 0xffff8800b95adae0: &(&sighand->siglock)->rlock
> | 0xffff8800bbb41ae0: &(&sighand->siglock)->rlock
> | 0xffff8800bf165ae0: &(&sighand->siglock)->rlock
> | 0xffff8800b9576a98: &p->cred_guard_mutex
> | 0xffff8800bb890a08: &(&p->alloc_lock)->rlock
> | 0xffff8800b9522a08: &(&p->alloc_lock)->rlock
> | 0xffff8800bb8aaa08: &(&p->alloc_lock)->rlock
> | 0xffff8800bba72a08: &(&p->alloc_lock)->rlock
> | 0xffff8800bf18ea08: &(&p->alloc_lock)->rlock
> | 0xffff8800b8a0d8a0: &(&ip->i_lock)->mr_lock
> | 0xffff88009bf818a0: &(&ip->i_lock)->mr_lock
> | 0xffff88004c66b8a0: &(&ip->i_lock)->mr_lock
> | 0xffff8800bb6478a0: &(shost->host_lock)->rlock
> Signed-off-by: Hitoshi Mitake <[email protected]>
> Cc: Ingo Molnar <[email protected]>
> Cc: Peter Zijlstra <[email protected]>
> Cc: Paul Mackerras <[email protected]>
> Cc: Arnaldo Carvalho de Melo <[email protected]>
> Cc: Jens Axboe <[email protected]>
> Cc: Jason Baron <[email protected]>
> Cc: Xiao Guangrong <[email protected]>


I've eventually not queued it because of some various
problems, see below:



> ---
> tools/perf/builtin-lock.c | 68 +++++++++++++++++++++++++++++++++++++++++++--
> 1 files changed, 65 insertions(+), 3 deletions(-)
>
> diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
> index ce27675..c54211e 100644
> --- a/tools/perf/builtin-lock.c
> +++ b/tools/perf/builtin-lock.c
> @@ -778,18 +778,61 @@ static void print_result(void)
> }
> }
>
> +static int info_threads;
> +static int info_map;
> +
> +static void rec_dump_threads(struct rb_node *node)
> +{
> + struct thread_stat *st;
> + struct thread *t;
> +
> + if (!node)
> + return;
> +
> + if (node->rb_left)
> + rec_dump_threads(node->rb_left);


That only walks the left nodes of the rbtree, imagine the following
rbtree, W are visited nodes, U are the unvisited:

Root
/ \
W U
/ \ / \
W U U U


Better iterate using rb_first() then rb_next() until it is NULL.



> +
> + st = container_of(node, struct thread_stat, rb);
> + BUG_ON(!st);


You won't ever have !st because container_of computes an address
based on a struct type and a contained address inside this struct.

struct thread_stat {
struct list_head hash_entry;
struct rb_node rb;
[...]
} ts;

If ts->rb == 1000, ts == 1000 - 16 or something like this.

What matters is the "if (!node)" check you did before.



> + t = perf_session__findnew(session, st->tid);
> + BUG_ON(!t);
> +
> + printf("%10d: %s\n", st->tid, t->comm);



Please don't use printf anymore (I did the same mistakes lately),
now that are using a TUI and we might use a GUI one day, we
can't assume anymore we are dealing with a normal stdout.

So better use pr_debug, pr_err, pr_warning, etc...



> +
> + if (node->rb_right)
> + rec_dump_threads(node->rb_right);
> +}
> +
> +static void dump_threads(void)
> +{
> + printf("%10s: comm\n", "Thread ID");



Same here and below.



> + rec_dump_threads(thread_stats.rb_node);
> +}
> +
> static void dump_map(void)
> {
> unsigned int i;
> struct lock_stat *st;
>
> + printf("Address of instance: name of class\n");
> for (i = 0; i < LOCKHASH_SIZE; i++) {
> list_for_each_entry(st, &lockhash_table[i], hash_entry) {
> - printf("%p: %s\n", st->addr, st->name);
> + printf(" %p: %s\n", st->addr, st->name);
> }
> }
> }
>
> +static void dump_info(void)
> +{
> + /* ugly... */
> + if (info_threads)
> + dump_threads();


No it's not ugly, it's ok, we do this everywhere in perf tools :)

Thanks.