All of lore.kernel.org
 help / color / mirror / Atom feed
* [GIT PULL] perf updates
@ 2010-05-09 20:43 Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 01/10] perf lock: Add "info" subcommand for dumping misc information Frederic Weisbecker
                   ` (11 more replies)
  0 siblings, 12 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Frederic Weisbecker, Hitoshi Mitake, Peter Zijlstra,
	Paul Mackerras, Arnaldo Carvalho de Melo, Jens Axboe,
	Jason Baron, Xiao Guangrong, Tom Zanussi, Masami Hiramatsu,
	Steven Rostedt

Ingo,

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

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

I've already posted the new reordering patches.

Summary:

- Now the reordering works with any kind of raw sample flow. I
  know I already said that with the previous period based reordering,
  but now it seems to be true. I hope...

- Perf lock cleanups and improvements.

- Lock events cleanups

Now I observed we lose a lot of events with perf lock. It's just
that the flow can be so huge that perf record can't keep up with
the buffers, and the kernel often meets the buffer size limit.
Increasing the buffers size makes the things better but it's still not
enough.

In fact we have strong scalability problems that can be solved after
we reach the two following steps:

- I need to unearth the injection thing, so that I'll be able to reduce
the size of the lock events: putting the name in the lock_init event only
and only pass the address of the lock instance in the other lock events.

- Introducing "perf muliplex". The way perf record saves the events by
walking through every counters in a linear way is nice if you have a small
flow and few cpus. I did all my tests on an SMT 2 threads machine (Atom) and
it loses lots of lock events (even with 8192 pages per counters), due to the
huge flow, and this linear walking: the time you read a counter and write the
events to the file, another counter may have reached its buffer size limit already.

Now I can imagine what will be the result after a test on this sparc machine
with 64 cpus.

So we need a perf record mode that does this: multiplex counters buffers per
cpu, so that we have one buffer per cpu. Having one thread per cpu that does its
own cpu record in its own file. Then pass the whole to perf multiplex that can
handle the multiplexing into a single file (useful as a multiplexing remote point
too for perf pipe).

Anyway, lot of work in prevision.

Thanks,
	Frederic
---

Frederic Weisbecker (9):
      perf: Introduce a new "round of buffers read" pseudo event
      perf: Provide a new deterministic events reordering algorithm
      perf: Cleanup perf lock broken states
      perf: Humanize lock flags in perf lock
      perf: Fix perf lock bad rate
      perf lock: Always check min AND max wait time
      tracing: Drop lock_acquired waittime field
      tracing: Drop the nested field from lock_release event
      tracing: Factorize lock events in a lock class

Hitoshi Mitake (2):
      perf lock: Add "info" subcommand for dumping misc information
      perf lock: Drop "-a" option from cmd_record() default arguments set

Tom Zanussi (1):
      perf/live-mode: Handle payload-less events


 include/trace/events/lock.h |   55 +++++-----------
 kernel/lockdep.c            |    4 +-
 tools/perf/builtin-lock.c   |  145 +++++++++++++++++++++++++++++++------------
 tools/perf/builtin-record.c |   34 +++++++---
 tools/perf/util/event.h     |    3 +-
 tools/perf/util/session.c   |  125 ++++++++++++++++++++++++++-----------
 tools/perf/util/session.h   |   36 ++++++-----
 7 files changed, 257 insertions(+), 145 deletions(-)

^ permalink raw reply	[flat|nested] 13+ messages in thread

* [PATCH 01/10] perf lock: Add "info" subcommand for dumping misc information
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 02/10] perf: Cleanup perf lock broken states Frederic Weisbecker
                   ` (10 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Hitoshi Mitake, Ingo Molnar, Peter Zijlstra,
	Paul Mackerras, Arnaldo Carvalho de Melo, Jens Axboe,
	Jason Baron, Xiao Guangrong, Frederic Weisbecker

From: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>

This adds the "info" subcommand to perf lock which can be used
to dump metadata like threads or addresses of lock instances.
"map" was removed because info should do the work for it.

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

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

v3: fixed some problems Frederic pointed out
 * better rbtree tracking in dump_threads()
 * removed printf() and used pr_info() and pr_debug()

Signed-off-by: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jens Axboe <jens.axboe@oracle.com>
Cc: Jason Baron <jbaron@redhat.com>
Cc: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
LKML-Reference: <1272863520-16179-1-git-send-email-mitake@dcl.info.waseda.ac.jp>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 tools/perf/builtin-lock.c |   96 ++++++++++++++++++++++++++++++++++-----------
 1 files changed, 73 insertions(+), 23 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 6605000..c4eb854 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -720,15 +720,15 @@ static void print_result(void)
 	char cut_name[20];
 	int bad, total;
 
-	printf("%20s ", "Name");
-	printf("%10s ", "acquired");
-	printf("%10s ", "contended");
+	pr_info("%20s ", "Name");
+	pr_info("%10s ", "acquired");
+	pr_info("%10s ", "contended");
 
-	printf("%15s ", "total wait (ns)");
-	printf("%15s ", "max wait (ns)");
-	printf("%15s ", "min wait (ns)");
+	pr_info("%15s ", "total wait (ns)");
+	pr_info("%15s ", "max wait (ns)");
+	pr_info("%15s ", "min wait (ns)");
 
-	printf("\n\n");
+	pr_info("\n\n");
 
 	bad = total = 0;
 	while ((st = pop_from_result())) {
@@ -741,7 +741,7 @@ static void print_result(void)
 
 		if (strlen(st->name) < 16) {
 			/* output raw name */
-			printf("%20s ", st->name);
+			pr_info("%20s ", st->name);
 		} else {
 			strncpy(cut_name, st->name, 16);
 			cut_name[16] = '.';
@@ -749,17 +749,17 @@ static void print_result(void)
 			cut_name[18] = '.';
 			cut_name[19] = '\0';
 			/* cut off name for saving output style */
-			printf("%20s ", cut_name);
+			pr_info("%20s ", cut_name);
 		}
 
-		printf("%10u ", st->nr_acquired);
-		printf("%10u ", st->nr_contended);
+		pr_info("%10u ", st->nr_acquired);
+		pr_info("%10u ", st->nr_contended);
 
-		printf("%15llu ", st->wait_time_total);
-		printf("%15llu ", st->wait_time_max);
-		printf("%15llu ", st->wait_time_min == ULLONG_MAX ?
+		pr_info("%15llu ", st->wait_time_total);
+		pr_info("%15llu ", st->wait_time_max);
+		pr_info("%15llu ", st->wait_time_min == ULLONG_MAX ?
 		       0 : st->wait_time_min);
-		printf("\n");
+		pr_info("\n");
 	}
 
 	{
@@ -768,28 +768,59 @@ static void print_result(void)
 		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));
+		pr_debug("\n=== output for debug===\n\n");
+		pr_debug("bad:%d, total:%d\n", bad, total);
+		pr_debug("bad rate:%f\n", (double)(bad / total));
 
-		printf("histogram of events caused bad sequence\n");
+		pr_debug("histogram of events caused bad sequence\n");
 		for (i = 0; i < 4; i++)
-			printf(" %10s: %d\n", name[i], bad_hist[i]);
+			pr_debug(" %10s: %d\n", name[i], bad_hist[i]);
 	}
 }
 
+static int			info_threads;
+static int			info_map;
+
+static void dump_threads(void)
+{
+	struct thread_stat *st;
+	struct rb_node *node;
+	struct thread *t;
+
+	pr_info("%10s: comm\n", "Thread ID");
+
+	node = rb_first(&thread_stats);
+	while (node) {
+		st = container_of(node, struct thread_stat, rb);
+		t = perf_session__findnew(session, st->tid);
+		pr_info("%10d: %s\n", st->tid, t->comm);
+		node = rb_next(node);
+	};
+}
+
 static void dump_map(void)
 {
 	unsigned int i;
 	struct lock_stat *st;
 
+	pr_info("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);
+			pr_info(" %p: %s\n", st->addr, st->name);
 		}
 	}
 }
 
+static void dump_info(void)
+{
+	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 +889,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 +973,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.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 02/10] perf: Cleanup perf lock broken states
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 01/10] perf lock: Add "info" subcommand for dumping misc information Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 03/10] perf: Humanize lock flags in perf lock Frederic Weisbecker
                   ` (9 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Arnaldo Carvalho de Melo, Paul Mackerras, Hitoshi Mitake

Use enum to get a human view of bad_hist indexes and
put bad histogram output in its own function.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
---
 tools/perf/builtin-lock.c |   49 ++++++++++++++++++++++++++------------------
 1 files changed, 29 insertions(+), 20 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index c4eb854..1e93179 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -387,7 +387,15 @@ static struct lock_seq_stat *get_seq(struct thread_stat *ts, void *addr)
 	return seq;
 }
 
-static int bad_hist[4];
+enum broken_state {
+	BROKEN_ACQUIRE,
+	BROKEN_ACQUIRED,
+	BROKEN_CONTENDED,
+	BROKEN_RELEASE,
+	BROKEN_MAX,
+};
+
+static int bad_hist[BROKEN_MAX];
 
 static void
 report_lock_acquire_event(struct trace_acquire_event *acquire_event,
@@ -437,7 +445,7 @@ report_lock_acquire_event(struct trace_acquire_event *acquire_event,
 broken:
 		/* broken lock sequence, discard it */
 		ls->discard = 1;
-		bad_hist[0]++;
+		bad_hist[BROKEN_ACQUIRE]++;
 		list_del(&seq->list);
 		free(seq);
 		goto end;
@@ -481,7 +489,6 @@ report_lock_acquired_event(struct trace_acquired_event *acquired_event,
 	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)
@@ -492,7 +499,7 @@ report_lock_acquired_event(struct trace_acquired_event *acquired_event,
 	case SEQ_STATE_READ_ACQUIRED:
 		/* broken lock sequence, discard it */
 		ls->discard = 1;
-		bad_hist[1]++;
+		bad_hist[BROKEN_ACQUIRED]++;
 		list_del(&seq->list);
 		free(seq);
 		goto end;
@@ -540,7 +547,7 @@ report_lock_contended_event(struct trace_contended_event *contended_event,
 	case SEQ_STATE_CONTENDED:
 		/* broken lock sequence, discard it */
 		ls->discard = 1;
-		bad_hist[2]++;
+		bad_hist[BROKEN_CONTENDED]++;
 		list_del(&seq->list);
 		free(seq);
 		goto end;
@@ -594,7 +601,7 @@ report_lock_release_event(struct trace_release_event *release_event,
 	case SEQ_STATE_RELEASED:
 		/* broken lock sequence, discard it */
 		ls->discard = 1;
-		bad_hist[3]++;
+		bad_hist[BROKEN_RELEASE]++;
 		goto free_seq;
 		break;
 	default:
@@ -713,6 +720,21 @@ process_raw_event(void *data, int cpu, u64 timestamp, struct thread *thread)
 		process_lock_release_event(data, event, cpu, timestamp, thread);
 }
 
+static void print_bad_events(int bad, int total)
+{
+	/* Output for debug, this have to be removed */
+	int i;
+	const char *name[4] =
+		{ "acquire", "acquired", "contended", "release" };
+
+	pr_info("\n=== output for debug===\n\n");
+	pr_info("bad:%d, total:%d\n", bad, total);
+	pr_info("bad rate:%f\n", (double)(bad / total));
+	pr_info("histogram of events caused bad sequence\n");
+	for (i = 0; i < BROKEN_MAX; i++)
+		pr_info(" %10s: %d\n", name[i], bad_hist[i]);
+}
+
 /* TODO: various way to print, coloring, nano or milli sec */
 static void print_result(void)
 {
@@ -762,20 +784,7 @@ static void print_result(void)
 		pr_info("\n");
 	}
 
-	{
-		/* Output for debug, this have to be removed */
-		int i;
-		const char *name[4] =
-			{ "acquire", "acquired", "contended", "release" };
-
-		pr_debug("\n=== output for debug===\n\n");
-		pr_debug("bad:%d, total:%d\n", bad, total);
-		pr_debug("bad rate:%f\n", (double)(bad / total));
-
-		pr_debug("histogram of events caused bad sequence\n");
-		for (i = 0; i < 4; i++)
-			pr_debug(" %10s: %d\n", name[i], bad_hist[i]);
-	}
+	print_bad_events(bad, total);
 }
 
 static int			info_threads;
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 03/10] perf: Humanize lock flags in perf lock
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 01/10] perf lock: Add "info" subcommand for dumping misc information Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 02/10] perf: Cleanup perf lock broken states Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 04/10] perf: Fix perf lock bad rate Frederic Weisbecker
                   ` (8 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Arnaldo Carvalho de Melo, Paul Mackerras, Hitoshi Mitake

Use an enum instead of plain constants for lock flags.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
---
 tools/perf/builtin-lock.c |   11 ++++++++---
 1 files changed, 8 insertions(+), 3 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 1e93179..3b304ed 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -397,6 +397,11 @@ enum broken_state {
 
 static int bad_hist[BROKEN_MAX];
 
+enum acquire_flags {
+	TRY_LOCK = 1,
+	READ_LOCK = 2,
+};
+
 static void
 report_lock_acquire_event(struct trace_acquire_event *acquire_event,
 			struct event *__event __used,
@@ -421,9 +426,9 @@ report_lock_acquire_event(struct trace_acquire_event *acquire_event,
 		if (!acquire_event->flag) {
 			seq->state = SEQ_STATE_ACQUIRING;
 		} else {
-			if (acquire_event->flag & 1)
+			if (acquire_event->flag & TRY_LOCK)
 				ls->nr_trylock++;
-			if (acquire_event->flag & 2)
+			if (acquire_event->flag & READ_LOCK)
 				ls->nr_readlock++;
 			seq->state = SEQ_STATE_READ_ACQUIRED;
 			seq->read_count = 1;
@@ -431,7 +436,7 @@ report_lock_acquire_event(struct trace_acquire_event *acquire_event,
 		}
 		break;
 	case SEQ_STATE_READ_ACQUIRED:
-		if (acquire_event->flag & 2) {
+		if (acquire_event->flag & READ_LOCK) {
 			seq->read_count++;
 			ls->nr_acquired++;
 			goto end;
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 04/10] perf: Fix perf lock bad rate
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (2 preceding siblings ...)
  2010-05-09 20:43 ` [PATCH 03/10] perf: Humanize lock flags in perf lock Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 05/10] perf lock: Always check min AND max wait time Frederic Weisbecker
                   ` (7 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Arnaldo Carvalho de Melo, Paul Mackerras, Hitoshi Mitake

Fix the cast made to get the bad rate. It is made in the result
instead of the operands. We need the operands to be cast in double,
otherwise the result will always be zero.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
---
 tools/perf/builtin-lock.c |    4 ++--
 1 files changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 3b304ed..d7dde9c 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -733,8 +733,8 @@ static void print_bad_events(int bad, int total)
 		{ "acquire", "acquired", "contended", "release" };
 
 	pr_info("\n=== output for debug===\n\n");
-	pr_info("bad:%d, total:%d\n", bad, total);
-	pr_info("bad rate:%f\n", (double)(bad / total));
+	pr_info("bad: %d, total: %d\n", bad, total);
+	pr_info("bad rate: %f %%\n", (double)bad / (double)total * 100);
 	pr_info("histogram of events caused bad sequence\n");
 	for (i = 0; i < BROKEN_MAX; i++)
 		pr_info(" %10s: %d\n", name[i], bad_hist[i]);
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 05/10] perf lock: Always check min AND max wait time
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (3 preceding siblings ...)
  2010-05-09 20:43 ` [PATCH 04/10] perf: Fix perf lock bad rate Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 06/10] tracing: Drop lock_acquired waittime field Frederic Weisbecker
                   ` (6 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Arnaldo Carvalho de Melo, Paul Mackerras, Hitoshi Mitake

When a lock is acquired after beeing contended, we update the
wait time statistics for the given lock.
But if the min wait time is updated, we don't check the max wait
time. This is wrong because the first time we update the wait time,
we want to update both min and max wait time.

Before:
	Name   acquired  contended total wait (ns)   max wait (ns)   min wait (ns)
	key          8          1           21656           0           21656

After:
	Name   acquired  contended total wait (ns)   max wait (ns)   min wait (ns)
	key          8          1           21656           21656           21656

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
---
 tools/perf/builtin-lock.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index d7dde9c..e549f45 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -496,7 +496,7 @@ report_lock_acquired_event(struct trace_acquired_event *acquired_event,
 		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)
+		if (ls->wait_time_max < contended_term)
 			ls->wait_time_max = contended_term;
 		break;
 	case SEQ_STATE_RELEASED:
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 06/10] tracing: Drop lock_acquired waittime field
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (4 preceding siblings ...)
  2010-05-09 20:43 ` [PATCH 05/10] perf lock: Always check min AND max wait time Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 07/10] tracing: Drop the nested field from lock_release event Frederic Weisbecker
                   ` (5 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Arnaldo Carvalho de Melo, Paul Mackerras, Hitoshi Mitake,
	Steven Rostedt

Drop the waittime field from the lock_acquired event, we can
calculate it by substracting the lock_acquired event timestamp
with the matching lock_acquire one.

It is not needed and takes useless space in the traces.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/lock.h |   11 ++++-------
 kernel/lockdep.c            |    2 +-
 2 files changed, 5 insertions(+), 8 deletions(-)

diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
index 5c1dcfc..17ca287 100644
--- a/include/trace/events/lock.h
+++ b/include/trace/events/lock.h
@@ -78,24 +78,21 @@ TRACE_EVENT(lock_contended,
 );
 
 TRACE_EVENT(lock_acquired,
-	TP_PROTO(struct lockdep_map *lock, unsigned long ip, s64 waittime),
+	TP_PROTO(struct lockdep_map *lock, unsigned long ip),
 
-	TP_ARGS(lock, ip, waittime),
+	TP_ARGS(lock, ip),
 
 	TP_STRUCT__entry(
 		__string(name, lock->name)
-		__field(s64, wait_nsec)
 		__field(void *, lockdep_addr)
 	),
 
 	TP_fast_assign(
 		__assign_str(name, lock->name);
-		__entry->wait_nsec = waittime;
 		__entry->lockdep_addr = lock;
 	),
-	TP_printk("%p %s (%llu ns)", __entry->lockdep_addr,
-		  __get_str(name),
-		  __entry->wait_nsec)
+	TP_printk("%p %s", __entry->lockdep_addr,
+		  __get_str(name))
 );
 
 #endif
diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index 2594e1c..31e22e7 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -3380,7 +3380,7 @@ found_it:
 		hlock->holdtime_stamp = now;
 	}
 
-	trace_lock_acquired(lock, ip, waittime);
+	trace_lock_acquired(lock, ip);
 
 	stats = get_lock_stats(hlock_class(hlock));
 	if (waittime) {
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 07/10] tracing: Drop the nested field from lock_release event
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (5 preceding siblings ...)
  2010-05-09 20:43 ` [PATCH 06/10] tracing: Drop lock_acquired waittime field Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 08/10] tracing: Factorize lock events in a lock class Frederic Weisbecker
                   ` (4 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Hitoshi Mitake, Steven Rostedt

Drop the nested field as we don't use it. Every nested state can
be computed from a state machine on post processing already.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/lock.h |    4 ++--
 kernel/lockdep.c            |    2 +-
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
index 17ca287..fde4c38 100644
--- a/include/trace/events/lock.h
+++ b/include/trace/events/lock.h
@@ -37,9 +37,9 @@ TRACE_EVENT(lock_acquire,
 
 TRACE_EVENT(lock_release,
 
-	TP_PROTO(struct lockdep_map *lock, int nested, unsigned long ip),
+	TP_PROTO(struct lockdep_map *lock, unsigned long ip),
 
-	TP_ARGS(lock, nested, ip),
+	TP_ARGS(lock, ip),
 
 	TP_STRUCT__entry(
 		__string(name, lock->name)
diff --git a/kernel/lockdep.c b/kernel/lockdep.c
index 31e22e7..e9c759f 100644
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -3227,7 +3227,7 @@ void lock_release(struct lockdep_map *lock, int nested,
 	raw_local_irq_save(flags);
 	check_flags(flags);
 	current->lockdep_recursion = 1;
-	trace_lock_release(lock, nested, ip);
+	trace_lock_release(lock, ip);
 	__lock_release(lock, nested, ip);
 	current->lockdep_recursion = 0;
 	raw_local_irq_restore(flags);
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 08/10] tracing: Factorize lock events in a lock class
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (6 preceding siblings ...)
  2010-05-09 20:43 ` [PATCH 07/10] tracing: Drop the nested field from lock_release event Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 09/10] perf/live-mode: Handle payload-less events Frederic Weisbecker
                   ` (3 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Frederic Weisbecker, Ingo Molnar, Peter Zijlstra,
	Hitoshi Mitake, Steven Rostedt

lock_acquired, lock_contended and lock_release now share the
same prototype and format. Let's factorize them into a lock
event class.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
Cc: Steven Rostedt <rostedt@goodmis.org>
---
 include/trace/events/lock.h |   48 +++++++++++++-----------------------------
 1 files changed, 15 insertions(+), 33 deletions(-)

diff --git a/include/trace/events/lock.h b/include/trace/events/lock.h
index fde4c38..2821b86 100644
--- a/include/trace/events/lock.h
+++ b/include/trace/events/lock.h
@@ -35,15 +35,15 @@ TRACE_EVENT(lock_acquire,
 		  __get_str(name))
 );
 
-TRACE_EVENT(lock_release,
+DECLARE_EVENT_CLASS(lock,
 
 	TP_PROTO(struct lockdep_map *lock, unsigned long ip),
 
 	TP_ARGS(lock, ip),
 
 	TP_STRUCT__entry(
-		__string(name, lock->name)
-		__field(void *, lockdep_addr)
+		__string(	name, 	lock->name	)
+		__field(	void *, lockdep_addr	)
 	),
 
 	TP_fast_assign(
@@ -51,48 +51,30 @@ TRACE_EVENT(lock_release,
 		__entry->lockdep_addr = lock;
 	),
 
-	TP_printk("%p %s",
-		  __entry->lockdep_addr, __get_str(name))
+	TP_printk("%p %s",  __entry->lockdep_addr, __get_str(name))
 );
 
-#ifdef CONFIG_LOCK_STAT
-
-TRACE_EVENT(lock_contended,
+DEFINE_EVENT(lock, lock_release,
 
 	TP_PROTO(struct lockdep_map *lock, unsigned long ip),
 
-	TP_ARGS(lock, ip),
-
-	TP_STRUCT__entry(
-		__string(name, lock->name)
-		__field(void *, lockdep_addr)
-	),
+	TP_ARGS(lock, ip)
+);
 
-	TP_fast_assign(
-		__assign_str(name, lock->name);
-		__entry->lockdep_addr = lock;
-	),
+#ifdef CONFIG_LOCK_STAT
 
-	TP_printk("%p %s",
-		  __entry->lockdep_addr, __get_str(name))
-);
+DEFINE_EVENT(lock, lock_contended,
 
-TRACE_EVENT(lock_acquired,
 	TP_PROTO(struct lockdep_map *lock, unsigned long ip),
 
-	TP_ARGS(lock, ip),
+	TP_ARGS(lock, ip)
+);
 
-	TP_STRUCT__entry(
-		__string(name, lock->name)
-		__field(void *, lockdep_addr)
-	),
+DEFINE_EVENT(lock, lock_acquired,
 
-	TP_fast_assign(
-		__assign_str(name, lock->name);
-		__entry->lockdep_addr = lock;
-	),
-	TP_printk("%p %s", __entry->lockdep_addr,
-		  __get_str(name))
+	TP_PROTO(struct lockdep_map *lock, unsigned long ip),
+
+	TP_ARGS(lock, ip)
 );
 
 #endif
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 09/10] perf/live-mode: Handle payload-less events
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (7 preceding siblings ...)
  2010-05-09 20:43 ` [PATCH 08/10] tracing: Factorize lock events in a lock class Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-09 20:43 ` [PATCH 10/10] perf lock: Drop "-a" option from cmd_record() default arguments set Frederic Weisbecker
                   ` (2 subsequent siblings)
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Tom Zanussi, Arnaldo Carvalho de Melo, Ingo Molnar,
	Peter Zijlstra, Paul Mackerras, Masami Hiramatsu,
	Frederic Weisbecker

From: Tom Zanussi <tzanussi@gmail.com>

Some events, such as the PERF_RECORD_FINISHED_ROUND event consist of
only an event header and no data.  In this case, a 0-length payload
will be read, and the 0 return value will be wrongly interpreted as an
'unexpected end of event stream'.

This patch allows for proper handling of data-less events by skipping
0-length reads.

Signed-off-by: Tom Zanussi <tzanussi@gmail.com>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Masami Hiramatsu <mhiramat@redhat.com>
LKML-Reference: <1273038527.6383.51.camel@tropicana>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 tools/perf/util/session.c |   19 +++++++++++--------
 1 files changed, 11 insertions(+), 8 deletions(-)

diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 9401909..00ab298 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -696,15 +696,18 @@ more:
 	p = &event;
 	p += sizeof(struct perf_event_header);
 
-	err = do_read(self->fd, p, size - sizeof(struct perf_event_header));
-	if (err <= 0) {
-		if (err == 0) {
-			pr_err("unexpected end of event stream\n");
-			goto done;
-		}
+	if (size - sizeof(struct perf_event_header)) {
+		err = do_read(self->fd, p,
+			      size - sizeof(struct perf_event_header));
+		if (err <= 0) {
+			if (err == 0) {
+				pr_err("unexpected end of event stream\n");
+				goto done;
+			}
 
-		pr_err("failed to read event data\n");
-		goto out_err;
+			pr_err("failed to read event data\n");
+			goto out_err;
+		}
 	}
 
 	if (size == 0 ||
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* [PATCH 10/10] perf lock: Drop "-a" option from cmd_record() default arguments set
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (8 preceding siblings ...)
  2010-05-09 20:43 ` [PATCH 09/10] perf/live-mode: Handle payload-less events Frederic Weisbecker
@ 2010-05-09 20:43 ` Frederic Weisbecker
  2010-05-10  5:10 ` [GIT PULL] perf updates Frederic Weisbecker
  2010-05-10  6:46 ` Ingo Molnar
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-09 20:43 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Hitoshi Mitake, Ingo Molnar, Peter Zijlstra,
	Paul Mackerras, Arnaldo Carvalho de Melo, Jens Axboe,
	Jason Baron, Xiao Guangrong, Frederic Weisbecker

From: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>

This patch drops "-a" from the default arguments passed to
perf record by perf lock.

If a user wants to do a system wide record of lock events,
        perf lock record -a <program> <argument> ...
is enough for this purpose.

This can reduce the size of the perf.data file.

% sudo ./perf lock record whoami
root
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.439 MB perf.data (~19170 samples) ]
% sudo ./perf lock record -a whoami   # with -a option
root
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 48.962 MB perf.data (~2139197 samples) ]

Signed-off-by: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
Cc: Ingo Molnar <mingo@elte.hu>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Jens Axboe <jens.axboe@oracle.com>
Cc: Jason Baron <jbaron@redhat.com>
Cc: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
LKML-Reference: Message-Id: <1273306229-5216-1-git-send-email-mitake@dcl.info.waseda.ac.jp>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 tools/perf/builtin-lock.c |    1 -
 1 files changed, 0 insertions(+), 1 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index e549f45..e18dfdc 100644
--- a/tools/perf/builtin-lock.c
+++ b/tools/perf/builtin-lock.c
@@ -930,7 +930,6 @@ static const struct option lock_options[] = {
 
 static const char *record_args[] = {
 	"record",
-	"-a",
 	"-R",
 	"-f",
 	"-m", "1024",
-- 
1.6.2.3


^ permalink raw reply related	[flat|nested] 13+ messages in thread

* Re: [GIT PULL] perf updates
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (9 preceding siblings ...)
  2010-05-09 20:43 ` [PATCH 10/10] perf lock: Drop "-a" option from cmd_record() default arguments set Frederic Weisbecker
@ 2010-05-10  5:10 ` Frederic Weisbecker
  2010-05-10  6:46 ` Ingo Molnar
  11 siblings, 0 replies; 13+ messages in thread
From: Frederic Weisbecker @ 2010-05-10  5:10 UTC (permalink / raw)
  To: Ingo Molnar
  Cc: LKML, Hitoshi Mitake, Peter Zijlstra, Paul Mackerras,
	Arnaldo Carvalho de Melo, Jens Axboe, Jason Baron,
	Xiao Guangrong, Tom Zanussi, Masami Hiramatsu, Steven Rostedt

On Sun, May 09, 2010 at 10:43:28PM +0200, Frederic Weisbecker wrote:
> Ingo,
> 
> Please pull the perf/test branch that can be found at:
> 
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git
> 	perf/test


It's for tip:perf/core btw.


^ permalink raw reply	[flat|nested] 13+ messages in thread

* Re: [GIT PULL] perf updates
  2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
                   ` (10 preceding siblings ...)
  2010-05-10  5:10 ` [GIT PULL] perf updates Frederic Weisbecker
@ 2010-05-10  6:46 ` Ingo Molnar
  11 siblings, 0 replies; 13+ messages in thread
From: Ingo Molnar @ 2010-05-10  6:46 UTC (permalink / raw)
  To: Frederic Weisbecker
  Cc: LKML, Hitoshi Mitake, Peter Zijlstra, Paul Mackerras,
	Arnaldo Carvalho de Melo, Jens Axboe, Jason Baron,
	Xiao Guangrong, Tom Zanussi, Masami Hiramatsu, Steven Rostedt


* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> Ingo,
> 
> Please pull the perf/test branch that can be found at:
> 
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git
> 	perf/test

Pulled, thanks a lot Frederic!

	Ingo

^ permalink raw reply	[flat|nested] 13+ messages in thread

end of thread, other threads:[~2010-05-10  6:46 UTC | newest]

Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2010-05-09 20:43 [GIT PULL] perf updates Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 01/10] perf lock: Add "info" subcommand for dumping misc information Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 02/10] perf: Cleanup perf lock broken states Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 03/10] perf: Humanize lock flags in perf lock Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 04/10] perf: Fix perf lock bad rate Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 05/10] perf lock: Always check min AND max wait time Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 06/10] tracing: Drop lock_acquired waittime field Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 07/10] tracing: Drop the nested field from lock_release event Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 08/10] tracing: Factorize lock events in a lock class Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 09/10] perf/live-mode: Handle payload-less events Frederic Weisbecker
2010-05-09 20:43 ` [PATCH 10/10] perf lock: Drop "-a" option from cmd_record() default arguments set Frederic Weisbecker
2010-05-10  5:10 ` [GIT PULL] perf updates Frederic Weisbecker
2010-05-10  6:46 ` Ingo Molnar

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.