Question about lock sequence

Question about lock sequence

[Hitoshi Mitake]

Hi,

I found that my understand about lockdep is completely wrong :( ,
so state machine of perf lock should be fixed before optimization.

And I found that behaviour related to some of spin locks are strange.
The concrete example is lock sequences targeting dcache_lock (defined in
head of fs/dcache.c).

I made a little (and not essential) change to perf lock, and observe
lock sequence targeting it.
Changed perf lock shows sequence of locks in time order,
and I grepped the output of it with dcache, like this:

% sudo ./perf lock report | grep dcache

The head part of result is this:
# <name>-<pid> <time (in u64)> <action> <address of lockdep> <name of lock>
perf-3238 92430534170 acquire: 0xffffffff81a4b398 dcache_lock
perf-3238 92430536714 acquire: 0xffffffff81a4b398 dcache_lock
perf-3238 92431444481 acquire: 0xffffffff81a4b398 dcache_lock
perf-3238 92431446061 acquired: 0xffffffff81a4b398 dcache_lock
perf-3238 92431448157 acquire: 0xffffffff81a4b398 dcache_lock
perf-3238 92431449670 acquired: 0xffffffff81a4b398 dcache_lock
perf-3238 92432371136 acquire: 0xffffffff81a4b398 dcache_lock
perf-3238 92432372712 acquired: 0xffffffff81a4b398 dcache_lock
perf-3238 92432374718 acquire: 0xffffffff81a4b398 dcache_lock
perf-3238 92432376173 acquired: 0xffffffff81a4b398 dcache_lock
perf-3238 92433315563 acquire: 0xffffffff81a4b398 dcache_lock
perf-3238 92433317173 acquired: 0xffffffff81a4b398 dcache_lock

There are too many acquire and acquired without corresponding release
(or contended).
If dcache_lock is rwlock and these acquires mean read locks, this is not
so strange.
But, for me, this is a pattern of dead lock.
Of course perf lock finished its work, so there is no actual dead lock.

If you know something about this behaviour of lock, could you tell me?

Thanks,
	Hitoshi

Re: Question about lock sequence

[Frederic Weisbecker]

On Sat, Apr 10, 2010 at 07:44:07PM +0900, Hitoshi Mitake wrote:
>
> Hi,
>
> I found that my understand about lockdep is completely wrong :( ,
> so state machine of perf lock should be fixed before optimization.
>
> And I found that behaviour related to some of spin locks are strange.
> The concrete example is lock sequences targeting dcache_lock (defined in
> head of fs/dcache.c).
>
> I made a little (and not essential) change to perf lock, and observe
> lock sequence targeting it.
> Changed perf lock shows sequence of locks in time order,
> and I grepped the output of it with dcache, like this:
>
> % sudo ./perf lock report | grep dcache
>
> The head part of result is this:
> # <name>-<pid> <time (in u64)> <action> <address of lockdep> <name of lock>
> perf-3238 92430534170 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92430536714 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92431444481 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92431446061 acquired: 0xffffffff81a4b398 dcache_lock
> perf-3238 92431448157 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92431449670 acquired: 0xffffffff81a4b398 dcache_lock
> perf-3238 92432371136 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92432372712 acquired: 0xffffffff81a4b398 dcache_lock
> perf-3238 92432374718 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92432376173 acquired: 0xffffffff81a4b398 dcache_lock
> perf-3238 92433315563 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92433317173 acquired: 0xffffffff81a4b398 dcache_lock
>
> There are too many acquire and acquired without corresponding release
> (or contended).
> If dcache_lock is rwlock and these acquires mean read locks, this is not
> so strange.
> But, for me, this is a pattern of dead lock.
> Of course perf lock finished its work, so there is no actual dead lock.
>
> If you know something about this behaviour of lock, could you tell me?


If you can see nesting acquires on an rwlock, it's normal, because it can
be recursively acquired.

What wouldn't be normal is an unbalanced stacking of acquire - release.

If you see:

acquire
 acquire
  acquire

You should find the symetric releases:

  release
 release
release

Otherwise we have something wrong.

Also I wonder about the fact you seem to have acquire without acquired
in your trace.

I'm going to look at this, hopefully I'll survive after looking in all these
rwlock_* _rwlock_* __rwlock_* arch_* raw* _raw* __raw* do_raw* mess... :)

Re: Question about lock sequence

[Peter Zijlstra]

On Sat, 2010-04-10 at 19:44 +0900, Hitoshi Mitake wrote:
> Hi,
> 
> I found that my understand about lockdep is completely wrong :( ,
> so state machine of perf lock should be fixed before optimization.
> 
> And I found that behaviour related to some of spin locks are strange.
> The concrete example is lock sequences targeting dcache_lock (defined in
> head of fs/dcache.c).
> 
> I made a little (and not essential) change to perf lock, and observe
> lock sequence targeting it.
> Changed perf lock shows sequence of locks in time order,
> and I grepped the output of it with dcache, like this:
> 
> % sudo ./perf lock report | grep dcache
> 
> The head part of result is this:
> # <name>-<pid> <time (in u64)> <action> <address of lockdep> <name of lock>
> perf-3238 92430534170 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92430536714 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92431444481 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92431446061 acquired: 0xffffffff81a4b398 dcache_lock
> perf-3238 92431448157 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92431449670 acquired: 0xffffffff81a4b398 dcache_lock
> perf-3238 92432371136 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92432372712 acquired: 0xffffffff81a4b398 dcache_lock
> perf-3238 92432374718 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92432376173 acquired: 0xffffffff81a4b398 dcache_lock
> perf-3238 92433315563 acquire: 0xffffffff81a4b398 dcache_lock
> perf-3238 92433317173 acquired: 0xffffffff81a4b398 dcache_lock
> 
> There are too many acquire and acquired without corresponding release
> (or contended).
> If dcache_lock is rwlock and these acquires mean read locks, this is not
> so strange.
> But, for me, this is a pattern of dead lock.
> Of course perf lock finished its work, so there is no actual dead lock.
> 
> If you know something about this behaviour of lock, could you tell me?

Well dcache_lock is a regular spinlock and there is only one of them, my
guess is that your timeline got messed up somehow.

Also, there doesn't appear to be a proper balance between acquires and
releases.

Re: Question about lock sequence

[Hitoshi Mitake]

On 04/10/10 22:07, Frederic Weisbecker wrote:
 > On Sat, Apr 10, 2010 at 07:44:07PM +0900, Hitoshi Mitake wrote:
 >>
 >> Hi,
 >>
 >> I found that my understand about lockdep is completely wrong :( ,
 >> so state machine of perf lock should be fixed before optimization.
 >>
 >> And I found that behaviour related to some of spin locks are strange.
 >> The concrete example is lock sequences targeting dcache_lock (defined in
 >> head of fs/dcache.c).
 >>
 >> I made a little (and not essential) change to perf lock, and observe
 >> lock sequence targeting it.
 >> Changed perf lock shows sequence of locks in time order,
 >> and I grepped the output of it with dcache, like this:
 >>
 >> % sudo ./perf lock report | grep dcache
 >>
 >> The head part of result is this:
 >> #<name>-<pid>  <time (in u64)>  <action>  <address of lockdep> 
<name of lock>
 >> perf-3238 92430534170 acquire: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92430536714 acquire: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92431444481 acquire: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92431446061 acquired: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92431448157 acquire: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92431449670 acquired: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92432371136 acquire: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92432372712 acquired: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92432374718 acquire: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92432376173 acquired: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92433315563 acquire: 0xffffffff81a4b398 dcache_lock
 >> perf-3238 92433317173 acquired: 0xffffffff81a4b398 dcache_lock
 >>
 >> There are too many acquire and acquired without corresponding release
 >> (or contended).
 >> If dcache_lock is rwlock and these acquires mean read locks, this is not
 >> so strange.
 >> But, for me, this is a pattern of dead lock.
 >> Of course perf lock finished its work, so there is no actual dead lock.
 >>
 >> If you know something about this behaviour of lock, could you tell me?
 >
 >
 > If you can see nesting acquires on an rwlock, it's normal, because it can
 > be recursively acquired.
 >
 > What wouldn't be normal is an unbalanced stacking of acquire - release.
 >
 > If you see:
 >
 > acquire
 >   acquire
 >    acquire
 >
 > You should find the symetric releases:
 >
 >    release
 >   release
 > release

Yes. All acquire must have their corresponding release.
According to my result, some of ordinary spin locks
make the not symmetric pattern.


 >
 > Otherwise we have something wrong.

I'm considering it. But I cannot find something wrong now :(
There should be some cause...

 >
 > Also I wonder about the fact you seem to have acquire without acquired
 > in your trace.

Yeah, if acquire is trylock, it isn't strange.
But these acquires are not trylock.

 >
 > I'm going to look at this, hopefully I'll survive after looking in 
all these
 > rwlock_* _rwlock_* __rwlock_* arch_* raw* _raw* __raw* do_raw* mess... :)
 >
 >

Oh thanks :) I'll continue my quest the cause.
    Hitoshi

[PATCH] perf lock: Fix state machine to recognize lock sequence

[Hitoshi Mitake]

Hi Ingo,

I'm developing the model to recognize the correct sequence of lock events.
Previous state machine of perf lock was really broken.
This patch improves it a little.

This patch prepares the array of state machine represents lock sequence for each threads.
These state machines represent one of these sequence:

      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 state machine of sequence
counts read lock number, and permit double acquire and release.

But, things are not so simple. Something of 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:122, total:1956

There is another new bad thing.
The size of array of state machine is equal to max depth lockdep defines.
If perf lock record tries to record lock events of the programs with lots of
system call like "perf bench sched messaging", the array will be exhausted :(

I believe my new model can recognize many case,
but some of locks is at beyond of my understanding...

I made too long silence, so I thought that this is time to dump my progress.
Could you make testing branch on your tip tree?

Signed-off-by: Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jens Axboe <jens.axboe@oracle.com>
Cc: Jason Baron <jbaron@redhat.com>
Cc: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
---
 tools/perf/builtin-lock.c |  399 +++++++++++++++++++++++++++++++++++++--------
 1 files changed, 330 insertions(+), 69 deletions(-)

diff --git a/tools/perf/builtin-lock.c b/tools/perf/builtin-lock.c
index 6c38e4f..f277856 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
+ *
+ * UNINITED 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_UNINITED      0	       /* initial state */
+#define SEQ_STATE_RELEASED	1
+#define SEQ_STATE_ACQUIRING	2
+#define SEQ_STATE_ACQUIRED	3
+#define SEQ_STATE_CONTENDED	4
+
+/*
+ * 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 {
+	int			state;
+	u64			prev_event_time;
+	void                    *addr_of_lock;
+
+	int                     read_count;
 };
 
+struct thread_stat {
+	struct rb_node		rb;
+
+	pid_t                   pid;
+	int                     seq_index_cache;
+	struct lock_seq_stat    seq_stack[MAX_LOCK_DEPTH];
+};
+
+static struct rb_root		thread_stats;
+
+static struct thread_stat *thread_stat_find(pid_t pid)
+{
+	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->pid == pid)
+			return st;
+		else if (pid < st->pid)
+			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->pid < p->pid)
+			rb = &(*rb)->rb_left;
+		else if (new->pid > p->pid)
+			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(pid_t pid)
+{
+	int i;
+	struct thread_stat *st;
+
+	st = thread_stat_find(pid);
+	if (st)
+		return st;
+
+	st = zalloc(sizeof(struct thread_stat));
+	if (!st)
+		die("memory allocation failed\n");
+
+	st->pid = pid;
+	for (i = 0; i < MAX_LOCK_DEPTH; i++)
+		st->seq_stack[i].state = SEQ_STATE_UNINITED;
+
+	thread_stat_insert(st);
+
+	return st;
+}
+
+static struct thread_stat *thread_stat_findnew_first(pid_t pid);
+static struct thread_stat *(*thread_stat_findnew)(pid_t pid) =
+	thread_stat_findnew_first;
+
+static struct thread_stat *thread_stat_findnew_first(pid_t pid)
+{
+	struct thread_stat *st;
+
+	st = zalloc(sizeof(struct thread_stat));
+	if (!st)
+		die("memory allocation failed\n");
+	st->pid = pid;
+
+	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,245 @@ struct trace_lock_handler {
 			      struct thread *thread);
 };
 
+static struct lock_seq_stat *get_seq(struct thread_stat *ts, void *addr)
+{
+	int i, min_unused;
+	struct lock_seq_stat *seq;
+
+	seq = &ts->seq_stack[ts->seq_index_cache];
+
+	if (seq->addr_of_lock != addr) {
+		min_unused = -1;
+		for (i = 0; i < MAX_LOCK_DEPTH; i++) {
+			seq = &ts->seq_stack[i];
+			if (min_unused < 0 && !seq->addr_of_lock)
+				min_unused = i;
+			if (seq->addr_of_lock == addr) {
+				ts->seq_index_cache = i;
+				return seq;
+			}
+		}
+
+		if (min_unused == -1) {
+			for (i = 0; i < MAX_LOCK_DEPTH; i++) {
+				struct lock_stat *l;
+
+				l = lock_stat_findnew(
+					ts->seq_stack[i].addr_of_lock, NULL);
+				printf("%s:%p\n", l->name, l->addr);
+			}
+			BUG_ON("seq_stack overflowed, "
+			       "please expand MAX_LOCK_DEPTH\n");
+		}
+
+		seq = &ts->seq_stack[min_unused];
+		seq->addr_of_lock = addr;
+		ts->seq_index_cache = min_unused;
+	}
+
+	return seq;
+}
+
 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;
 
-	st = lock_stat_findnew(acquire_event->addr, acquire_event->name);
+	ls = lock_stat_findnew(acquire_event->addr, acquire_event->name);
+	if (ls->discard)
+		return;
 
-	switch (st->state) {
-	case LOCK_STATE_UNLOCKED:
+	ts = thread_stat_findnew(thread->pid);
+	seq = get_seq(ts, acquire_event->addr);
+
+	switch (seq->state) {
+	case SEQ_STATE_UNINITED:
+	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_ACQUIRED;
+		}
+		break;
+	case SEQ_STATE_ACQUIRED:
+		if (acquire_event->flag & 2)
+			seq->read_count++;
+		else
+			goto broken;
 		break;
-	case LOCK_STATE_LOCKED:
+	case SEQ_STATE_ACQUIRING:
+	case SEQ_STATE_CONTENDED:
+broken:
+		/* broken lock sequence, discard it */
+		ls->discard = 1;
+		seq->addr_of_lock = NULL;
+		seq->state = SEQ_STATE_UNINITED;
 		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;
 }
 
 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;
+
+	ls = lock_stat_findnew(acquired_event->addr, acquired_event->name);
+	if (ls->discard)
+		return;
 
-	st = lock_stat_findnew(acquired_event->addr, acquired_event->name);
+	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_UNINITED:
+		/* orphan event, do nothing */
+		return;
+	case SEQ_STATE_ACQUIRING:
+		break;
+	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 LOCK_STATE_LOCKED:
+	case SEQ_STATE_RELEASED:
+	case SEQ_STATE_ACQUIRED:
+		/* broken lock sequence, discard it */
+		ls->discard = 1;
+		seq->addr_of_lock = NULL;
+		seq->state = SEQ_STATE_UNINITED;
 		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;
 }
 
 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_UNINITED:
+		/* 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_CONTENDED:
+		/* broken lock sequence, discard it */
+		ls->discard = 1;
+		seq->addr_of_lock = NULL;
+		seq->state = SEQ_STATE_UNINITED;
 		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;
 }
 
 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... */
-			goto end;
+	switch (seq->state) {
+	case SEQ_STATE_UNINITED:
+		goto end;
+		break;
+	case SEQ_STATE_ACQUIRED:
+		/*
+		 * FIXME: for this case, lock_release()
+		 * should have flag to represent read unlock
+		 */
+		if (seq->read_count > 0) {
+			if (--seq->read_count) {
+				ls->nr_release++;
+				return;
+			}
 		}
-
-		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;
+		seq->addr_of_lock = NULL;
+		seq->state = SEQ_STATE_UNINITED;
 		break;
 	default:
-		BUG_ON(1);
+		BUG_ON("Unknown state of lock sequence found!\n");
 		break;
 	}
 
+	ls->nr_release++;
 end:
-	st->prev_event_time = timestamp;
+	seq->addr_of_lock = NULL;
+	seq->state = SEQ_STATE_UNINITED;
+	ts->seq_index_cache = 0;
 }
 
 /* lock oriented handlers */
@@ -381,6 +635,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 +696,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 +859,14 @@ 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);
+	thread = perf_session__findnew(s, data.pid);
 
 	if (thread == NULL) {
 		pr_debug("problem processing %d event, skipping it.\n",
@@ -634,8 +889,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 +901,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 +932,10 @@ static void print_result(void)
 		       0 : st->wait_time_min);
 		printf("\n");
 	}
+
+	/* Output for debug */
+	printf("bad:%d, total:%d\n", bad, total);
+	printf("bad rate:%f\n", (double)(bad / total));
 }
 
 static void dump_map(void)
@@ -692,8 +955,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.5.2

Re: [PATCH] perf lock: Fix state machine to recognize lock sequence

[Frederic Weisbecker]

On Fri, Apr 16, 2010 at 05:44:06PM +0900, Hitoshi Mitake wrote:
> Hi Ingo,
> 
> I'm developing the model to recognize the correct sequence of lock events.
> Previous state machine of perf lock was really broken.
> This patch improves it a little.
> 
> This patch prepares the array of state machine represents lock sequence for each threads.
> These state machines represent one of these sequence:
> 
>       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 state machine of sequence
> counts read lock number, and permit double acquire and release.
> 
> But, things are not so simple. Something of 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:122, total:1956



I just gave your patch a try and it's worse: almost every sequences
were reported bad (it wasn't working either before your patch :)

This is not the fault of your patch though. Actually your patch seems to
be a nice improvement.

In fact I just found two things:

1) We are working on tasks in pid basis. We should work on a task by using
its tid.
In fact we are processing the sequences of several threads in a process as
if we were dealing with a single task.

If A and B are two threads belonging to a same process, and if we have:

A: acquire lock 1, release lock 1
B: acquire lock 2, release lock 2

...then we are dealing with a random mess of sequences:

AB: acquire lock 1, acquire lock 2, release lock 1, and any kind of random
things like this.

2) I can't get lock_acquired traces. Not sure why yet...


> 
> There is another new bad thing.
> The size of array of state machine is equal to max depth lockdep defines.
> If perf lock record tries to record lock events of the programs with lots of
> system call like "perf bench sched messaging", the array will be exhausted :(



Yeah, I suggest you use a list for that in fact. The max lockdep depth may
change in the future, or become variable, so we can't relay on that.

But that's still a cool improvement.

I'm queuing this patch.

Thanks.

Re: [PATCH] perf lock: Fix state machine to recognize lock sequence

[Peter Zijlstra]

On Wed, 2010-04-21 at 03:26 +0200, Frederic Weisbecker wrote:
> The max lockdep depth may
> change in the future, or become variable, so we can't relay on that.
> 
Change, possible, variable unlikely, you need a memory allocation to
extend it, and memory allocation takes locks, which is not a nice thing
to do in the middle of lockdep.

Re: [PATCH] perf lock: Fix state machine to recognize lock sequence

[Hitoshi Mitake]

On 04/21/10 10:26, Frederic Weisbecker wrote:
 > On Fri, Apr 16, 2010 at 05:44:06PM +0900, Hitoshi Mitake wrote:
 >> Hi Ingo,
 >>
 >> I'm developing the model to recognize the correct sequence of lock 
events.
 >> Previous state machine of perf lock was really broken.
 >> This patch improves it a little.
 >>
 >> This patch prepares the array of state machine represents lock 
sequence for each threads.
 >> These state machines represent one of these sequence:
 >>
 >>        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 state machine of sequence
 >> counts read lock number, and permit double acquire and release.
 >>
 >> But, things are not so simple. Something of 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:122, total:1956
 >
 >
 >
 > I just gave your patch a try and it's worse: almost every sequences
 > were reported bad (it wasn't working either before your patch :)
 >
 > This is not the fault of your patch though. Actually your patch seems to
 > be a nice improvement.

Thanks for your review, Frederic!

 >
 > In fact I just found two things:
 >
 > 1) We are working on tasks in pid basis. We should work on a task by 
using
 > its tid.
 > In fact we are processing the sequences of several threads in a 
process as
 > if we were dealing with a single task.
 >
 > If A and B are two threads belonging to a same process, and if we have:
 >
 > A: acquire lock 1, release lock 1
 > B: acquire lock 2, release lock 2
 >
 > ...then we are dealing with a random mess of sequences:
 >
 > AB: acquire lock 1, acquire lock 2, release lock 1, and any kind of 
random
 > things like this.


Ah, I missed tid. I'll fix this point.

 >
 > 2) I can't get lock_acquired traces. Not sure why yet...

Really? It's mystery... I'll seek the cause.

 >
 >
 >>
 >> There is another new bad thing.
 >> The size of array of state machine is equal to max depth lockdep 
defines.
 >> If perf lock record tries to record lock events of the programs with 
lots of
 >> system call like "perf bench sched messaging", the array will be 
exhausted :(
 >
 >
 >
 > Yeah, I suggest you use a list for that in fact. The max lockdep 
depth may
 > change in the future, or become variable, so we can't relay on that.

Yeah, I'll use list or hashtable.

 >
 > But that's still a cool improvement.
 >
 > I'm queuing this patch.

Thanks! But I have to fix some points based on your advice.
Should I send v2 patch or make fix on your tree?

Thanks,
	Hitoshi

[PATCH v2] perf lock: Fix state machine to recognize lock sequence

[Hitoshi Mitake]

Hi Frederic,

I'm sending this v2 patch.
It seems that your tree doesn't contain previous one.
So could you queue this new one?

I'm developing the model to recognize the correct sequence of lock events.
Previous state machine of perf lock was really broken.
This patch improves it a little.

This patch prepares the list of state machine represents lock sequence for each threads.
These state machines represent one of these sequence:

      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 state machine of sequence
counts read lock number, and permit double acquire and release.

But, things are not so simple. Something of 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 <mitake@dcl.info.waseda.ac.jp>
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>
Cc: Ingo Molnar <mingo@elte.hu>

---
 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..9475208 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
+ *
+ * UNINITED 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_UNINITED      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_UNINITED;
+	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_UNINITED:
+	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_UNINITED:
+		/* 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_UNINITED:
+		/* 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_UNINITED:
+		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.5.2

Re: [PATCH] perf lock: Fix state machine to recognize lock sequence

[Hitoshi Mitake]

On 04/21/10 17:55, Peter Zijlstra wrote:
 > On Wed, 2010-04-21 at 03:26 +0200, Frederic Weisbecker wrote:
 >> The max lockdep depth may
 >> change in the future, or become variable, so we can't relay on that.
 >>
 > Change, possible, variable unlikely, you need a memory allocation to
 > extend it, and memory allocation takes locks, which is not a nice thing
 > to do in the middle of lockdep.

Thanks for your clear description.
It seems that we can think that maximum depth of lock will not be variable.

Thanks,
	Hitoshi

Re: [PATCH] perf lock: Fix state machine to recognize lock sequence

[Frederic Weisbecker]

On Wed, Apr 21, 2010 at 10:55:58AM +0200, Peter Zijlstra wrote:
> On Wed, 2010-04-21 at 03:26 +0200, Frederic Weisbecker wrote:
> > The max lockdep depth may
> > change in the future, or become variable, so we can't relay on that.
> > 
> Change, possible, variable unlikely, you need a memory allocation to
> extend it, and memory allocation takes locks, which is not a nice thing
> to do in the middle of lockdep.


Sure, I didn't meant on runtime but on boot, like in John's recent
proposal.

Thanks.

Re: [PATCH] perf lock: Fix state machine to recognize lock sequence

[Frederic Weisbecker]

On Wed, Apr 21, 2010 at 06:12:06PM +0900, Hitoshi Mitake wrote:
> On 04/21/10 10:26, Frederic Weisbecker wrote:
> > 2) I can't get lock_acquired traces. Not sure why yet...
>
> Really? It's mystery... I'll seek the cause.


In fact they are here, but not displayed in perf trace because
of a format file parse error. I'm investigating, I think it
doesn't impact perf lock though.

Thanks.

Re: [PATCH v2] perf lock: Fix state machine to recognize lock sequence

[Frederic Weisbecker]

On Wed, Apr 21, 2010 at 09:23:54PM +0900, Hitoshi Mitake wrote:
> Hi Frederic,
> 
> I'm sending this v2 patch.
> It seems that your tree doesn't contain previous one.
> So could you queue this new one?


Yep, thanks for this work.

I'm applying it.

[tip:perf/core] perf lock: Fix state machine to recognize lock sequence

[tip-bot for Hitoshi Mitake]

Commit-ID:  e4cef1f65061429c3e8b356233e87dc6653a9da5
Gitweb:     http://git.kernel.org/tip/e4cef1f65061429c3e8b356233e87dc6653a9da5
Author:     Hitoshi Mitake <mitake@dcl.info.waseda.ac.jp>
AuthorDate: Wed, 21 Apr 2010 21:23:54 +0900
Committer:  Frederic Weisbecker <fweisbec@gmail.com>
CommitDate: Sat, 24 Apr 2010 03:23:14 +0200

perf lock: Fix state machine to recognize lock sequence

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 <mitake@dcl.info.waseda.ac.jp>
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>
Cc: Ingo Molnar <mingo@elte.hu>
LKML-Reference: <1271852634-9351-1-git-send-email-mitake@dcl.info.waseda.ac.jp>
[rename SEQ_STATE_UNINITED to SEQ_STATE_UNINITIALIZED]
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 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);