xref: /openbmc/linux/tools/perf/builtin-lock.c (revision c61e52ee)
1 #include "builtin.h"
2 #include "perf.h"
3 
4 #include "util/util.h"
5 #include "util/cache.h"
6 #include "util/symbol.h"
7 #include "util/thread.h"
8 #include "util/header.h"
9 
10 #include "util/parse-options.h"
11 #include "util/trace-event.h"
12 
13 #include "util/debug.h"
14 #include "util/session.h"
15 
16 #include <sys/types.h>
17 #include <sys/prctl.h>
18 #include <semaphore.h>
19 #include <pthread.h>
20 #include <math.h>
21 #include <limits.h>
22 
23 #include <linux/list.h>
24 #include <linux/hash.h>
25 
26 static struct perf_session *session;
27 
28 /* based on kernel/lockdep.c */
29 #define LOCKHASH_BITS		12
30 #define LOCKHASH_SIZE		(1UL << LOCKHASH_BITS)
31 
32 static struct list_head lockhash_table[LOCKHASH_SIZE];
33 
34 #define __lockhashfn(key)	hash_long((unsigned long)key, LOCKHASH_BITS)
35 #define lockhashentry(key)	(lockhash_table + __lockhashfn((key)))
36 
37 struct lock_stat {
38 	struct list_head	hash_entry;
39 	struct rb_node		rb;		/* used for sorting */
40 
41 	/*
42 	 * FIXME: raw_field_value() returns unsigned long long,
43 	 * so address of lockdep_map should be dealed as 64bit.
44 	 * Is there more better solution?
45 	 */
46 	void			*addr;		/* address of lockdep_map, used as ID */
47 	char			*name;		/* for strcpy(), we cannot use const */
48 
49 	unsigned int		nr_acquire;
50 	unsigned int		nr_acquired;
51 	unsigned int		nr_contended;
52 	unsigned int		nr_release;
53 
54 	unsigned int		nr_readlock;
55 	unsigned int		nr_trylock;
56 	/* these times are in nano sec. */
57 	u64			wait_time_total;
58 	u64			wait_time_min;
59 	u64			wait_time_max;
60 
61 	int			discard; /* flag of blacklist */
62 };
63 
64 /*
65  * States of lock_seq_stat
66  *
67  * UNINITIALIZED is required for detecting first event of acquire.
68  * As the nature of lock events, there is no guarantee
69  * that the first event for the locks are acquire,
70  * it can be acquired, contended or release.
71  */
72 #define SEQ_STATE_UNINITIALIZED      0	       /* initial state */
73 #define SEQ_STATE_RELEASED	1
74 #define SEQ_STATE_ACQUIRING	2
75 #define SEQ_STATE_ACQUIRED	3
76 #define SEQ_STATE_READ_ACQUIRED	4
77 #define SEQ_STATE_CONTENDED	5
78 
79 /*
80  * MAX_LOCK_DEPTH
81  * Imported from include/linux/sched.h.
82  * Should this be synchronized?
83  */
84 #define MAX_LOCK_DEPTH 48
85 
86 /*
87  * struct lock_seq_stat:
88  * Place to put on state of one lock sequence
89  * 1) acquire -> acquired -> release
90  * 2) acquire -> contended -> acquired -> release
91  * 3) acquire (with read or try) -> release
92  * 4) Are there other patterns?
93  */
94 struct lock_seq_stat {
95 	struct list_head        list;
96 	int			state;
97 	u64			prev_event_time;
98 	void                    *addr;
99 
100 	int                     read_count;
101 };
102 
103 struct thread_stat {
104 	struct rb_node		rb;
105 
106 	u32                     tid;
107 	struct list_head        seq_list;
108 };
109 
110 static struct rb_root		thread_stats;
111 
112 static struct thread_stat *thread_stat_find(u32 tid)
113 {
114 	struct rb_node *node;
115 	struct thread_stat *st;
116 
117 	node = thread_stats.rb_node;
118 	while (node) {
119 		st = container_of(node, struct thread_stat, rb);
120 		if (st->tid == tid)
121 			return st;
122 		else if (tid < st->tid)
123 			node = node->rb_left;
124 		else
125 			node = node->rb_right;
126 	}
127 
128 	return NULL;
129 }
130 
131 static void thread_stat_insert(struct thread_stat *new)
132 {
133 	struct rb_node **rb = &thread_stats.rb_node;
134 	struct rb_node *parent = NULL;
135 	struct thread_stat *p;
136 
137 	while (*rb) {
138 		p = container_of(*rb, struct thread_stat, rb);
139 		parent = *rb;
140 
141 		if (new->tid < p->tid)
142 			rb = &(*rb)->rb_left;
143 		else if (new->tid > p->tid)
144 			rb = &(*rb)->rb_right;
145 		else
146 			BUG_ON("inserting invalid thread_stat\n");
147 	}
148 
149 	rb_link_node(&new->rb, parent, rb);
150 	rb_insert_color(&new->rb, &thread_stats);
151 }
152 
153 static struct thread_stat *thread_stat_findnew_after_first(u32 tid)
154 {
155 	struct thread_stat *st;
156 
157 	st = thread_stat_find(tid);
158 	if (st)
159 		return st;
160 
161 	st = zalloc(sizeof(struct thread_stat));
162 	if (!st)
163 		die("memory allocation failed\n");
164 
165 	st->tid = tid;
166 	INIT_LIST_HEAD(&st->seq_list);
167 
168 	thread_stat_insert(st);
169 
170 	return st;
171 }
172 
173 static struct thread_stat *thread_stat_findnew_first(u32 tid);
174 static struct thread_stat *(*thread_stat_findnew)(u32 tid) =
175 	thread_stat_findnew_first;
176 
177 static struct thread_stat *thread_stat_findnew_first(u32 tid)
178 {
179 	struct thread_stat *st;
180 
181 	st = zalloc(sizeof(struct thread_stat));
182 	if (!st)
183 		die("memory allocation failed\n");
184 	st->tid = tid;
185 	INIT_LIST_HEAD(&st->seq_list);
186 
187 	rb_link_node(&st->rb, NULL, &thread_stats.rb_node);
188 	rb_insert_color(&st->rb, &thread_stats);
189 
190 	thread_stat_findnew = thread_stat_findnew_after_first;
191 	return st;
192 }
193 
194 /* build simple key function one is bigger than two */
195 #define SINGLE_KEY(member)						\
196 	static int lock_stat_key_ ## member(struct lock_stat *one,	\
197 					 struct lock_stat *two)		\
198 	{								\
199 		return one->member > two->member;			\
200 	}
201 
202 SINGLE_KEY(nr_acquired)
203 SINGLE_KEY(nr_contended)
204 SINGLE_KEY(wait_time_total)
205 SINGLE_KEY(wait_time_min)
206 SINGLE_KEY(wait_time_max)
207 
208 struct lock_key {
209 	/*
210 	 * name: the value for specify by user
211 	 * this should be simpler than raw name of member
212 	 * e.g. nr_acquired -> acquired, wait_time_total -> wait_total
213 	 */
214 	const char		*name;
215 	int			(*key)(struct lock_stat*, struct lock_stat*);
216 };
217 
218 static const char		*sort_key = "acquired";
219 
220 static int			(*compare)(struct lock_stat *, struct lock_stat *);
221 
222 static struct rb_root		result;	/* place to store sorted data */
223 
224 #define DEF_KEY_LOCK(name, fn_suffix)	\
225 	{ #name, lock_stat_key_ ## fn_suffix }
226 struct lock_key keys[] = {
227 	DEF_KEY_LOCK(acquired, nr_acquired),
228 	DEF_KEY_LOCK(contended, nr_contended),
229 	DEF_KEY_LOCK(wait_total, wait_time_total),
230 	DEF_KEY_LOCK(wait_min, wait_time_min),
231 	DEF_KEY_LOCK(wait_max, wait_time_max),
232 
233 	/* extra comparisons much complicated should be here */
234 
235 	{ NULL, NULL }
236 };
237 
238 static void select_key(void)
239 {
240 	int i;
241 
242 	for (i = 0; keys[i].name; i++) {
243 		if (!strcmp(keys[i].name, sort_key)) {
244 			compare = keys[i].key;
245 			return;
246 		}
247 	}
248 
249 	die("Unknown compare key:%s\n", sort_key);
250 }
251 
252 static void insert_to_result(struct lock_stat *st,
253 			     int (*bigger)(struct lock_stat *, struct lock_stat *))
254 {
255 	struct rb_node **rb = &result.rb_node;
256 	struct rb_node *parent = NULL;
257 	struct lock_stat *p;
258 
259 	while (*rb) {
260 		p = container_of(*rb, struct lock_stat, rb);
261 		parent = *rb;
262 
263 		if (bigger(st, p))
264 			rb = &(*rb)->rb_left;
265 		else
266 			rb = &(*rb)->rb_right;
267 	}
268 
269 	rb_link_node(&st->rb, parent, rb);
270 	rb_insert_color(&st->rb, &result);
271 }
272 
273 /* returns left most element of result, and erase it */
274 static struct lock_stat *pop_from_result(void)
275 {
276 	struct rb_node *node = result.rb_node;
277 
278 	if (!node)
279 		return NULL;
280 
281 	while (node->rb_left)
282 		node = node->rb_left;
283 
284 	rb_erase(node, &result);
285 	return container_of(node, struct lock_stat, rb);
286 }
287 
288 static struct lock_stat *lock_stat_findnew(void *addr, const char *name)
289 {
290 	struct list_head *entry = lockhashentry(addr);
291 	struct lock_stat *ret, *new;
292 
293 	list_for_each_entry(ret, entry, hash_entry) {
294 		if (ret->addr == addr)
295 			return ret;
296 	}
297 
298 	new = zalloc(sizeof(struct lock_stat));
299 	if (!new)
300 		goto alloc_failed;
301 
302 	new->addr = addr;
303 	new->name = zalloc(sizeof(char) * strlen(name) + 1);
304 	if (!new->name)
305 		goto alloc_failed;
306 	strcpy(new->name, name);
307 
308 	new->wait_time_min = ULLONG_MAX;
309 
310 	list_add(&new->hash_entry, entry);
311 	return new;
312 
313 alloc_failed:
314 	die("memory allocation failed\n");
315 }
316 
317 static char			const *input_name = "perf.data";
318 
319 struct raw_event_sample {
320 	u32			size;
321 	char			data[0];
322 };
323 
324 struct trace_acquire_event {
325 	void			*addr;
326 	const char		*name;
327 	int			flag;
328 };
329 
330 struct trace_acquired_event {
331 	void			*addr;
332 	const char		*name;
333 };
334 
335 struct trace_contended_event {
336 	void			*addr;
337 	const char		*name;
338 };
339 
340 struct trace_release_event {
341 	void			*addr;
342 	const char		*name;
343 };
344 
345 struct trace_lock_handler {
346 	void (*acquire_event)(struct trace_acquire_event *,
347 			      struct event *,
348 			      int cpu,
349 			      u64 timestamp,
350 			      struct thread *thread);
351 
352 	void (*acquired_event)(struct trace_acquired_event *,
353 			       struct event *,
354 			       int cpu,
355 			       u64 timestamp,
356 			       struct thread *thread);
357 
358 	void (*contended_event)(struct trace_contended_event *,
359 				struct event *,
360 				int cpu,
361 				u64 timestamp,
362 				struct thread *thread);
363 
364 	void (*release_event)(struct trace_release_event *,
365 			      struct event *,
366 			      int cpu,
367 			      u64 timestamp,
368 			      struct thread *thread);
369 };
370 
371 static struct lock_seq_stat *get_seq(struct thread_stat *ts, void *addr)
372 {
373 	struct lock_seq_stat *seq;
374 
375 	list_for_each_entry(seq, &ts->seq_list, list) {
376 		if (seq->addr == addr)
377 			return seq;
378 	}
379 
380 	seq = zalloc(sizeof(struct lock_seq_stat));
381 	if (!seq)
382 		die("Not enough memory\n");
383 	seq->state = SEQ_STATE_UNINITIALIZED;
384 	seq->addr = addr;
385 
386 	list_add(&seq->list, &ts->seq_list);
387 	return seq;
388 }
389 
390 static int bad_hist[4];
391 
392 static void
393 report_lock_acquire_event(struct trace_acquire_event *acquire_event,
394 			struct event *__event __used,
395 			int cpu __used,
396 			u64 timestamp __used,
397 			struct thread *thread __used)
398 {
399 	struct lock_stat *ls;
400 	struct thread_stat *ts;
401 	struct lock_seq_stat *seq;
402 
403 	ls = lock_stat_findnew(acquire_event->addr, acquire_event->name);
404 	if (ls->discard)
405 		return;
406 
407 	ts = thread_stat_findnew(thread->pid);
408 	seq = get_seq(ts, acquire_event->addr);
409 
410 	switch (seq->state) {
411 	case SEQ_STATE_UNINITIALIZED:
412 	case SEQ_STATE_RELEASED:
413 		if (!acquire_event->flag) {
414 			seq->state = SEQ_STATE_ACQUIRING;
415 		} else {
416 			if (acquire_event->flag & 1)
417 				ls->nr_trylock++;
418 			if (acquire_event->flag & 2)
419 				ls->nr_readlock++;
420 			seq->state = SEQ_STATE_READ_ACQUIRED;
421 			seq->read_count = 1;
422 			ls->nr_acquired++;
423 		}
424 		break;
425 	case SEQ_STATE_READ_ACQUIRED:
426 		if (acquire_event->flag & 2) {
427 			seq->read_count++;
428 			ls->nr_acquired++;
429 			goto end;
430 		} else {
431 			goto broken;
432 		}
433 		break;
434 	case SEQ_STATE_ACQUIRED:
435 	case SEQ_STATE_ACQUIRING:
436 	case SEQ_STATE_CONTENDED:
437 broken:
438 		/* broken lock sequence, discard it */
439 		ls->discard = 1;
440 		bad_hist[0]++;
441 		list_del(&seq->list);
442 		free(seq);
443 		goto end;
444 		break;
445 	default:
446 		BUG_ON("Unknown state of lock sequence found!\n");
447 		break;
448 	}
449 
450 	ls->nr_acquire++;
451 	seq->prev_event_time = timestamp;
452 end:
453 	return;
454 }
455 
456 static void
457 report_lock_acquired_event(struct trace_acquired_event *acquired_event,
458 			 struct event *__event __used,
459 			 int cpu __used,
460 			 u64 timestamp __used,
461 			 struct thread *thread __used)
462 {
463 	struct lock_stat *ls;
464 	struct thread_stat *ts;
465 	struct lock_seq_stat *seq;
466 	u64 contended_term;
467 
468 	ls = lock_stat_findnew(acquired_event->addr, acquired_event->name);
469 	if (ls->discard)
470 		return;
471 
472 	ts = thread_stat_findnew(thread->pid);
473 	seq = get_seq(ts, acquired_event->addr);
474 
475 	switch (seq->state) {
476 	case SEQ_STATE_UNINITIALIZED:
477 		/* orphan event, do nothing */
478 		return;
479 	case SEQ_STATE_ACQUIRING:
480 		break;
481 	case SEQ_STATE_CONTENDED:
482 		contended_term = timestamp - seq->prev_event_time;
483 		ls->wait_time_total += contended_term;
484 
485 		if (contended_term < ls->wait_time_min)
486 			ls->wait_time_min = contended_term;
487 		else if (ls->wait_time_max < contended_term)
488 			ls->wait_time_max = contended_term;
489 		break;
490 	case SEQ_STATE_RELEASED:
491 	case SEQ_STATE_ACQUIRED:
492 	case SEQ_STATE_READ_ACQUIRED:
493 		/* broken lock sequence, discard it */
494 		ls->discard = 1;
495 		bad_hist[1]++;
496 		list_del(&seq->list);
497 		free(seq);
498 		goto end;
499 		break;
500 
501 	default:
502 		BUG_ON("Unknown state of lock sequence found!\n");
503 		break;
504 	}
505 
506 	seq->state = SEQ_STATE_ACQUIRED;
507 	ls->nr_acquired++;
508 	seq->prev_event_time = timestamp;
509 end:
510 	return;
511 }
512 
513 static void
514 report_lock_contended_event(struct trace_contended_event *contended_event,
515 			  struct event *__event __used,
516 			  int cpu __used,
517 			  u64 timestamp __used,
518 			  struct thread *thread __used)
519 {
520 	struct lock_stat *ls;
521 	struct thread_stat *ts;
522 	struct lock_seq_stat *seq;
523 
524 	ls = lock_stat_findnew(contended_event->addr, contended_event->name);
525 	if (ls->discard)
526 		return;
527 
528 	ts = thread_stat_findnew(thread->pid);
529 	seq = get_seq(ts, contended_event->addr);
530 
531 	switch (seq->state) {
532 	case SEQ_STATE_UNINITIALIZED:
533 		/* orphan event, do nothing */
534 		return;
535 	case SEQ_STATE_ACQUIRING:
536 		break;
537 	case SEQ_STATE_RELEASED:
538 	case SEQ_STATE_ACQUIRED:
539 	case SEQ_STATE_READ_ACQUIRED:
540 	case SEQ_STATE_CONTENDED:
541 		/* broken lock sequence, discard it */
542 		ls->discard = 1;
543 		bad_hist[2]++;
544 		list_del(&seq->list);
545 		free(seq);
546 		goto end;
547 		break;
548 	default:
549 		BUG_ON("Unknown state of lock sequence found!\n");
550 		break;
551 	}
552 
553 	seq->state = SEQ_STATE_CONTENDED;
554 	ls->nr_contended++;
555 	seq->prev_event_time = timestamp;
556 end:
557 	return;
558 }
559 
560 static void
561 report_lock_release_event(struct trace_release_event *release_event,
562 			struct event *__event __used,
563 			int cpu __used,
564 			u64 timestamp __used,
565 			struct thread *thread __used)
566 {
567 	struct lock_stat *ls;
568 	struct thread_stat *ts;
569 	struct lock_seq_stat *seq;
570 
571 	ls = lock_stat_findnew(release_event->addr, release_event->name);
572 	if (ls->discard)
573 		return;
574 
575 	ts = thread_stat_findnew(thread->pid);
576 	seq = get_seq(ts, release_event->addr);
577 
578 	switch (seq->state) {
579 	case SEQ_STATE_UNINITIALIZED:
580 		goto end;
581 		break;
582 	case SEQ_STATE_ACQUIRED:
583 		break;
584 	case SEQ_STATE_READ_ACQUIRED:
585 		seq->read_count--;
586 		BUG_ON(seq->read_count < 0);
587 		if (!seq->read_count) {
588 			ls->nr_release++;
589 			goto end;
590 		}
591 		break;
592 	case SEQ_STATE_ACQUIRING:
593 	case SEQ_STATE_CONTENDED:
594 	case SEQ_STATE_RELEASED:
595 		/* broken lock sequence, discard it */
596 		ls->discard = 1;
597 		bad_hist[3]++;
598 		goto free_seq;
599 		break;
600 	default:
601 		BUG_ON("Unknown state of lock sequence found!\n");
602 		break;
603 	}
604 
605 	ls->nr_release++;
606 free_seq:
607 	list_del(&seq->list);
608 	free(seq);
609 end:
610 	return;
611 }
612 
613 /* lock oriented handlers */
614 /* TODO: handlers for CPU oriented, thread oriented */
615 static struct trace_lock_handler report_lock_ops  = {
616 	.acquire_event		= report_lock_acquire_event,
617 	.acquired_event		= report_lock_acquired_event,
618 	.contended_event	= report_lock_contended_event,
619 	.release_event		= report_lock_release_event,
620 };
621 
622 static struct trace_lock_handler *trace_handler;
623 
624 static void
625 process_lock_acquire_event(void *data,
626 			   struct event *event __used,
627 			   int cpu __used,
628 			   u64 timestamp __used,
629 			   struct thread *thread __used)
630 {
631 	struct trace_acquire_event acquire_event;
632 	u64 tmp;		/* this is required for casting... */
633 
634 	tmp = raw_field_value(event, "lockdep_addr", data);
635 	memcpy(&acquire_event.addr, &tmp, sizeof(void *));
636 	acquire_event.name = (char *)raw_field_ptr(event, "name", data);
637 	acquire_event.flag = (int)raw_field_value(event, "flag", data);
638 
639 	if (trace_handler->acquire_event)
640 		trace_handler->acquire_event(&acquire_event, event, cpu, timestamp, thread);
641 }
642 
643 static void
644 process_lock_acquired_event(void *data,
645 			    struct event *event __used,
646 			    int cpu __used,
647 			    u64 timestamp __used,
648 			    struct thread *thread __used)
649 {
650 	struct trace_acquired_event acquired_event;
651 	u64 tmp;		/* this is required for casting... */
652 
653 	tmp = raw_field_value(event, "lockdep_addr", data);
654 	memcpy(&acquired_event.addr, &tmp, sizeof(void *));
655 	acquired_event.name = (char *)raw_field_ptr(event, "name", data);
656 
657 	if (trace_handler->acquire_event)
658 		trace_handler->acquired_event(&acquired_event, event, cpu, timestamp, thread);
659 }
660 
661 static void
662 process_lock_contended_event(void *data,
663 			     struct event *event __used,
664 			     int cpu __used,
665 			     u64 timestamp __used,
666 			     struct thread *thread __used)
667 {
668 	struct trace_contended_event contended_event;
669 	u64 tmp;		/* this is required for casting... */
670 
671 	tmp = raw_field_value(event, "lockdep_addr", data);
672 	memcpy(&contended_event.addr, &tmp, sizeof(void *));
673 	contended_event.name = (char *)raw_field_ptr(event, "name", data);
674 
675 	if (trace_handler->acquire_event)
676 		trace_handler->contended_event(&contended_event, event, cpu, timestamp, thread);
677 }
678 
679 static void
680 process_lock_release_event(void *data,
681 			   struct event *event __used,
682 			   int cpu __used,
683 			   u64 timestamp __used,
684 			   struct thread *thread __used)
685 {
686 	struct trace_release_event release_event;
687 	u64 tmp;		/* this is required for casting... */
688 
689 	tmp = raw_field_value(event, "lockdep_addr", data);
690 	memcpy(&release_event.addr, &tmp, sizeof(void *));
691 	release_event.name = (char *)raw_field_ptr(event, "name", data);
692 
693 	if (trace_handler->acquire_event)
694 		trace_handler->release_event(&release_event, event, cpu, timestamp, thread);
695 }
696 
697 static void
698 process_raw_event(void *data, int cpu, u64 timestamp, struct thread *thread)
699 {
700 	struct event *event;
701 	int type;
702 
703 	type = trace_parse_common_type(data);
704 	event = trace_find_event(type);
705 
706 	if (!strcmp(event->name, "lock_acquire"))
707 		process_lock_acquire_event(data, event, cpu, timestamp, thread);
708 	if (!strcmp(event->name, "lock_acquired"))
709 		process_lock_acquired_event(data, event, cpu, timestamp, thread);
710 	if (!strcmp(event->name, "lock_contended"))
711 		process_lock_contended_event(data, event, cpu, timestamp, thread);
712 	if (!strcmp(event->name, "lock_release"))
713 		process_lock_release_event(data, event, cpu, timestamp, thread);
714 }
715 
716 /* TODO: various way to print, coloring, nano or milli sec */
717 static void print_result(void)
718 {
719 	struct lock_stat *st;
720 	char cut_name[20];
721 	int bad, total;
722 
723 	printf("%20s ", "Name");
724 	printf("%10s ", "acquired");
725 	printf("%10s ", "contended");
726 
727 	printf("%15s ", "total wait (ns)");
728 	printf("%15s ", "max wait (ns)");
729 	printf("%15s ", "min wait (ns)");
730 
731 	printf("\n\n");
732 
733 	bad = total = 0;
734 	while ((st = pop_from_result())) {
735 		total++;
736 		if (st->discard) {
737 			bad++;
738 			continue;
739 		}
740 		bzero(cut_name, 20);
741 
742 		if (strlen(st->name) < 16) {
743 			/* output raw name */
744 			printf("%20s ", st->name);
745 		} else {
746 			strncpy(cut_name, st->name, 16);
747 			cut_name[16] = '.';
748 			cut_name[17] = '.';
749 			cut_name[18] = '.';
750 			cut_name[19] = '\0';
751 			/* cut off name for saving output style */
752 			printf("%20s ", cut_name);
753 		}
754 
755 		printf("%10u ", st->nr_acquired);
756 		printf("%10u ", st->nr_contended);
757 
758 		printf("%15llu ", st->wait_time_total);
759 		printf("%15llu ", st->wait_time_max);
760 		printf("%15llu ", st->wait_time_min == ULLONG_MAX ?
761 		       0 : st->wait_time_min);
762 		printf("\n");
763 	}
764 
765 	{
766 		/* Output for debug, this have to be removed */
767 		int i;
768 		const char *name[4] =
769 			{ "acquire", "acquired", "contended", "release" };
770 
771 		printf("\n=== output for debug===\n\n");
772 		printf("bad:%d, total:%d\n", bad, total);
773 		printf("bad rate:%f\n", (double)(bad / total));
774 
775 		printf("histogram of events caused bad sequence\n");
776 		for (i = 0; i < 4; i++)
777 			printf(" %10s: %d\n", name[i], bad_hist[i]);
778 	}
779 }
780 
781 static void dump_map(void)
782 {
783 	unsigned int i;
784 	struct lock_stat *st;
785 
786 	for (i = 0; i < LOCKHASH_SIZE; i++) {
787 		list_for_each_entry(st, &lockhash_table[i], hash_entry) {
788 			printf("%p: %s\n", st->addr, st->name);
789 		}
790 	}
791 }
792 
793 static int process_sample_event(event_t *self, struct perf_session *s)
794 {
795 	struct sample_data data;
796 	struct thread *thread;
797 
798 	bzero(&data, sizeof(data));
799 	event__parse_sample(self, s->sample_type, &data);
800 
801 	thread = perf_session__findnew(s, data.tid);
802 	if (thread == NULL) {
803 		pr_debug("problem processing %d event, skipping it.\n",
804 			self->header.type);
805 		return -1;
806 	}
807 
808 	process_raw_event(data.raw_data, data.cpu, data.time, thread);
809 
810 	return 0;
811 }
812 
813 static struct perf_event_ops eops = {
814 	.sample			= process_sample_event,
815 	.comm			= event__process_comm,
816 	.ordered_samples	= true,
817 };
818 
819 static int read_events(void)
820 {
821 	session = perf_session__new(input_name, O_RDONLY, 0);
822 	if (!session)
823 		die("Initializing perf session failed\n");
824 
825 	return perf_session__process_events(session, &eops);
826 }
827 
828 static void sort_result(void)
829 {
830 	unsigned int i;
831 	struct lock_stat *st;
832 
833 	for (i = 0; i < LOCKHASH_SIZE; i++) {
834 		list_for_each_entry(st, &lockhash_table[i], hash_entry) {
835 			insert_to_result(st, compare);
836 		}
837 	}
838 }
839 
840 static void __cmd_report(void)
841 {
842 	setup_pager();
843 	select_key();
844 	read_events();
845 	sort_result();
846 	print_result();
847 }
848 
849 static const char * const report_usage[] = {
850 	"perf lock report [<options>]",
851 	NULL
852 };
853 
854 static const struct option report_options[] = {
855 	OPT_STRING('k', "key", &sort_key, "acquired",
856 		    "key for sorting"),
857 	/* TODO: type */
858 	OPT_END()
859 };
860 
861 static const char * const lock_usage[] = {
862 	"perf lock [<options>] {record|trace|report}",
863 	NULL
864 };
865 
866 static const struct option lock_options[] = {
867 	OPT_STRING('i', "input", &input_name, "file", "input file name"),
868 	OPT_INCR('v', "verbose", &verbose, "be more verbose (show symbol address, etc)"),
869 	OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace, "dump raw trace in ASCII"),
870 	OPT_END()
871 };
872 
873 static const char *record_args[] = {
874 	"record",
875 	"-a",
876 	"-R",
877 	"-f",
878 	"-m", "1024",
879 	"-c", "1",
880 	"-e", "lock:lock_acquire:r",
881 	"-e", "lock:lock_acquired:r",
882 	"-e", "lock:lock_contended:r",
883 	"-e", "lock:lock_release:r",
884 };
885 
886 static int __cmd_record(int argc, const char **argv)
887 {
888 	unsigned int rec_argc, i, j;
889 	const char **rec_argv;
890 
891 	rec_argc = ARRAY_SIZE(record_args) + argc - 1;
892 	rec_argv = calloc(rec_argc + 1, sizeof(char *));
893 
894 	for (i = 0; i < ARRAY_SIZE(record_args); i++)
895 		rec_argv[i] = strdup(record_args[i]);
896 
897 	for (j = 1; j < (unsigned int)argc; j++, i++)
898 		rec_argv[i] = argv[j];
899 
900 	BUG_ON(i != rec_argc);
901 
902 	return cmd_record(i, rec_argv, NULL);
903 }
904 
905 int cmd_lock(int argc, const char **argv, const char *prefix __used)
906 {
907 	unsigned int i;
908 
909 	symbol__init();
910 	for (i = 0; i < LOCKHASH_SIZE; i++)
911 		INIT_LIST_HEAD(lockhash_table + i);
912 
913 	argc = parse_options(argc, argv, lock_options, lock_usage,
914 			     PARSE_OPT_STOP_AT_NON_OPTION);
915 	if (!argc)
916 		usage_with_options(lock_usage, lock_options);
917 
918 	if (!strncmp(argv[0], "rec", 3)) {
919 		return __cmd_record(argc, argv);
920 	} else if (!strncmp(argv[0], "report", 6)) {
921 		trace_handler = &report_lock_ops;
922 		if (argc) {
923 			argc = parse_options(argc, argv,
924 					     report_options, report_usage, 0);
925 			if (argc)
926 				usage_with_options(report_usage, report_options);
927 		}
928 		__cmd_report();
929 	} else if (!strcmp(argv[0], "trace")) {
930 		/* Aliased to 'perf trace' */
931 		return cmd_trace(argc, argv, prefix);
932 	} else if (!strcmp(argv[0], "map")) {
933 		/* recycling report_lock_ops */
934 		trace_handler = &report_lock_ops;
935 		setup_pager();
936 		read_events();
937 		dump_map();
938 	} else {
939 		usage_with_options(lock_usage, lock_options);
940 	}
941 
942 	return 0;
943 }
944