aboutsummaryrefslogtreecommitdiffstats
path: root/tools/perf/builtin-lock.c
blob: fb9ab2ad3f923c56c4bb745e0eb294c8a5d0a1ea (plain) (blame)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
#include "builtin.h"
#include "perf.h"

#include "util/util.h"
#include "util/cache.h"
#include "util/symbol.h"
#include "util/thread.h"
#include "util/header.h"

#include "util/parse-options.h"
#include "util/trace-event.h"

#include "util/debug.h"
#include "util/session.h"

#include <sys/types.h>
#include <sys/prctl.h>
#include <semaphore.h>
#include <pthread.h>
#include <math.h>
#include <limits.h>

#include <linux/list.h>
#include <linux/hash.h>

/* based on kernel/lockdep.c */
#define LOCKHASH_BITS		12
#define LOCKHASH_SIZE		(1UL << LOCKHASH_BITS)

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 */

	/*
	 * FIXME: raw_field_value() returns unsigned long long,
	 * so address of lockdep_map should be dealed as 64bit.
	 * Is there more better solution?
	 */
	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_contended;
	unsigned int		nr_release;

	/* these times are in nano sec. */
	u64			wait_time_total;
	u64			wait_time_min;
	u64			wait_time_max;
};

/* build simple key function one is bigger than two */
#define SINGLE_KEY(member)						\
	static int lock_stat_key_ ## member(struct lock_stat *one,	\
					 struct lock_stat *two)		\
	{								\
		return one->member > two->member;			\
	}

SINGLE_KEY(nr_acquired)
SINGLE_KEY(nr_contended)
SINGLE_KEY(wait_time_total)
SINGLE_KEY(wait_time_min)
SINGLE_KEY(wait_time_max)

struct lock_key {
	/*
	 * name: the value for specify by user
	 * this should be simpler than raw name of member
	 * e.g. nr_acquired -> acquired, wait_time_total -> wait_total
	 */
	const char		*name;
	int			(*key)(struct lock_stat*, struct lock_stat*);
};

static const char		*sort_key = "acquired";

static int			(*compare)(struct lock_stat *, struct lock_stat *);

static struct rb_root		result;	/* place to store sorted data */

#define DEF_KEY_LOCK(name, fn_suffix)	\
	{ #name, lock_stat_key_ ## fn_suffix }
struct lock_key keys[] = {
	DEF_KEY_LOCK(acquired, nr_acquired),
	DEF_KEY_LOCK(contended, nr_contended),
	DEF_KEY_LOCK(wait_total, wait_time_total),
	DEF_KEY_LOCK(wait_min, wait_time_min),
	DEF_KEY_LOCK(wait_max, wait_time_max),

	/* extra comparisons much complicated should be here */

	{ NULL, NULL }
};

static void select_key(void)
{
	int i;

	for (i = 0; keys[i].name; i++) {
		if (!strcmp(keys[i].name, sort_key)) {
			compare = keys[i].key;
			return;
		}
	}

	die("Unknown compare key:%s\n", sort_key);
}

static void insert_to_result(struct lock_stat *st,
			     int (*bigger)(struct lock_stat *, struct lock_stat *))
{
	struct rb_node **rb = &result.rb_node;
	struct rb_node *parent = NULL;
	struct lock_stat *p;

	while (*rb) {
		p = container_of(*rb, struct lock_stat, rb);
		parent = *rb;

		if (bigger(st, p))
			rb = &(*rb)->rb_left;
		else
			rb = &(*rb)->rb_right;
	}

	rb_link_node(&st->rb, parent, rb);
	rb_insert_color(&st->rb, &result);
}

/* returns left most element of result, and erase it */
static struct lock_stat *pop_from_result(void)
{
	struct rb_node *node = result.rb_node;

	if (!node)
		return NULL;

	while (node->rb_left)
		node = node->rb_left;

	rb_erase(node, &result);
	return container_of(node, struct lock_stat, rb);
}

static struct lock_stat *lock_stat_findnew(void *addr, const char *name)
{
	struct list_head *entry = lockhashentry(addr);
	struct lock_stat *ret, *new;

	list_for_each_entry(ret, entry, hash_entry) {
		if (ret->addr == addr)
			return ret;
	}

	new = zalloc(sizeof(struct lock_stat));
	if (!new)
		goto alloc_failed;

	new->addr = addr;
	new->name = zalloc(sizeof(char) * strlen(name) + 1);
	if (!new->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);
	return new;

alloc_failed:
	die("memory allocation failed\n");
}

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

static int			profile_cpu = -1;

struct raw_event_sample {
	u32			size;
	char			data[0];
};

struct trace_acquire_event {
	void			*addr;
	const char		*name;
};

struct trace_acquired_event {
	void			*addr;
	const char		*name;
};

struct trace_contended_event {
	void			*addr;
	const char		*name;
};

struct trace_release_event {
	void			*addr;
	const char		*name;
};

struct trace_lock_handler {
	void (*acquire_event)(struct trace_acquire_event *,
			      struct event *,
			      int cpu,
			      u64 timestamp,
			      struct thread *thread);

	void (*acquired_event)(struct trace_acquired_event *,
			       struct event *,
			       int cpu,
			       u64 timestamp,
			       struct thread *thread);

	void (*contended_event)(struct trace_contended_event *,
				struct event *,
				int cpu,
				u64 timestamp,
				struct thread *thread);

	void (*release_event)(struct trace_release_event *,
			      struct event *,
			      int cpu,
			      u64 timestamp,
			      struct thread *thread);
};

static void
report_lock_acquire_event(struct trace_acquire_event *acquire_event,
			struct event *__event __used,
			int cpu __used,
			u64 timestamp,
			struct thread *thread __used)
{
	struct lock_stat *st;

	st = lock_stat_findnew(acquire_event->addr, acquire_event->name);

	switch (st->state) {
	case LOCK_STATE_UNLOCKED:
		break;
	case LOCK_STATE_LOCKED:
		break;
	default:
		BUG_ON(1);
		break;
	}

	st->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,
			 struct thread *thread __used)
{
	struct lock_stat *st;

	st = lock_stat_findnew(acquired_event->addr, acquired_event->name);

	switch (st->state) {
	case LOCK_STATE_UNLOCKED:
		st->state = LOCK_STATE_LOCKED;
		st->nr_acquired++;
		break;
	case LOCK_STATE_LOCKED:
		break;
	default:
		BUG_ON(1);
		break;
	}

	st->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,
			  struct thread *thread __used)
{
	struct lock_stat *st;

	st = lock_stat_findnew(contended_event->addr, contended_event->name);

	switch (st->state) {
	case LOCK_STATE_UNLOCKED:
		break;
	case LOCK_STATE_LOCKED:
		st->nr_contended++;
		break;
	default:
		BUG_ON(1);
		break;
	}

	st->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,
			struct thread *thread __used)
{
	struct lock_stat *st;
	u64 hold_time;

	st = lock_stat_findnew(release_event->addr, release_event->name);

	switch (st->state) {
	case LOCK_STATE_UNLOCKED:
		break;
	case LOCK_STATE_LOCKED:
		st->state = LOCK_STATE_UNLOCKED;
		hold_time = timestamp - st->prev_event_time;

		if (timestamp < st->prev_event_time) {
			/* terribly, this can happen... */
			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;
	default:
		BUG_ON(1);
		break;
	}

end:
	st->prev_event_time = timestamp;
}

/* lock oriented handlers */
/* TODO: handlers for CPU oriented, thread oriented */
static struct trace_lock_handler report_lock_ops  = {
	.acquire_event		= report_lock_acquire_event,
	.acquired_event		= report_lock_acquired_event,
	.contended_event	= report_lock_contended_event,
	.release_event		= report_lock_release_event,
};

static struct trace_lock_handler *trace_handler;

static void
process_lock_acquire_event(void *data,
			   struct event *event __used,
			   int cpu __used,
			   u64 timestamp __used,
			   struct thread *thread __used)
{
	struct trace_acquire_event acquire_event;
	u64 tmp;		/* this is required for casting... */

	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);

	if (trace_handler->acquire_event)
		trace_handler->acquire_event(&acquire_event, event, cpu, timestamp, thread);
}

static void
process_lock_acquired_event(void *data,
			    struct event *event __used,
			    int cpu __used,
			    u64 timestamp __used,
			    struct thread *thread __used)
{
	struct trace_acquired_event acquired_event;
	u64 tmp;		/* this is required for casting... */

	tmp = raw_field_value(event, "lockdep_addr", data);
	memcpy(&acquired_event.addr, &tmp, sizeof(void *));
	acquired_event.name = (char *)raw_field_ptr(event, "name", data);

	if (trace_handler->acquire_event)
		trace_handler->acquired_event(&acquired_event, event, cpu, timestamp, thread);
}

static void
process_lock_contended_event(void *data,
			     struct event *event __used,
			     int cpu __used,
			     u64 timestamp __used,
			     struct thread *thread __used)
{
	struct trace_contended_event contended_event;
	u64 tmp;		/* this is required for casting... */

	tmp = raw_field_value(event, "lockdep_addr", data);
	memcpy(&contended_event.addr, &tmp, sizeof(void *));
	contended_event.name = (char *)raw_field_ptr(event, "name", data);

	if (trace_handler->acquire_event)
		trace_handler->contended_event(&contended_event, event, cpu, timestamp, thread);
}

static void
process_lock_release_event(void *data,
			   struct event *event __used,
			   int cpu __used,
			   u64 timestamp __used,
			   struct thread *thread __used)
{
	struct trace_release_event release_event;
	u64 tmp;		/* this is required for casting... */

	tmp = raw_field_value(event, "lockdep_addr", data);
	memcpy(&release_event.addr, &tmp, sizeof(void *));
	release_event.name = (char *)raw_field_ptr(event, "name", data);

	if (trace_handler->acquire_event)
		trace_handler->release_event(&release_event, event, cpu, timestamp, thread);
}

static void
process_raw_event(void *data, int cpu,
		  u64 timestamp, struct thread *thread)
{
	struct event *event;
	int type;

	type = trace_parse_common_type(data);
	event = trace_find_event(type);

	if (!strcmp(event->name, "lock_acquire"))
		process_lock_acquire_event(data, event, cpu, timestamp, thread);
	if (!strcmp(event->name, "lock_acquired"))
		process_lock_acquired_event(data, event, cpu, timestamp, thread);
	if (!strcmp(event->name, "lock_contended"))
		process_lock_contended_event(data, event, cpu, timestamp, thread);
	if (!strcmp(event->name, "lock_release"))
		process_lock_release_event(data, event, cpu, timestamp, thread);
}

static int process_sample_event(event_t *event, struct perf_session *session)
{
	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);

	if (thread == NULL) {
		pr_debug("problem processing %d event, skipping it.\n",
			 event->header.type);
		return -1;
	}

	dump_printf(" ... thread: %s:%d\n", thread->comm, thread->pid);

	if (profile_cpu != -1 && profile_cpu != (int) data.cpu)
		return 0;

	process_raw_event(data.raw_data, data.cpu, data.time, thread);

	return 0;
}

/* TODO: various way to print, coloring, nano or milli sec */
static void print_result(void)
{
	struct lock_stat *st;
	char cut_name[20];

	printf("%18s ", "ID");
	printf("%20s ", "Name");
	printf("%10s ", "acquired");
	printf("%10s ", "contended");

	printf("%15s ", "total wait (ns)");
	printf("%15s ", "max wait (ns)");
	printf("%15s ", "min wait (ns)");

	printf("\n\n");

	while ((st = pop_from_result())) {
		bzero(cut_name, 20);

		printf("%p ", st->addr);

		if (strlen(st->name) < 16) {
			/* output raw name */
			printf("%20s ", st->name);
		} else {
			strncpy(cut_name, st->name, 16);
			cut_name[16] = '.';
			cut_name[17] = '.';
			cut_name[18] = '.';
			cut_name[19] = '\0';
			/* cut off name for saving output style */
			printf("%20s ", cut_name);
		}

		printf("%10u ", st->nr_acquired);
		printf("%10u ", st->nr_contended);

		printf("%15llu ", st->wait_time_total);
		printf("%15llu ", st->wait_time_max);
		printf("%15llu ", st->wait_time_min == ULLONG_MAX ?
		       0 : st->wait_time_min);
		printf("\n");
	}
}

static void dump_map(void)
{
	unsigned int i;
	struct lock_stat *st;

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

static struct perf_event_ops eops = {
	.sample			= process_sample_event,
	.comm			= event__process_comm,
};

static struct perf_session *session;

static int read_events(void)
{
	session = perf_session__new(input_name, O_RDONLY, 0);
	if (!session)
		die("Initializing perf session failed\n");

	return perf_session__process_events(session, &eops);
}

static void sort_result(void)
{
	unsigned int i;
	struct lock_stat *st;

	for (i = 0; i < LOCKHASH_SIZE; i++) {
		list_for_each_entry(st, &lockhash_table[i], hash_entry) {
			insert_to_result(st, compare);
		}
	}
}

static void __cmd_report(void)
{
	setup_pager();
	select_key();
	read_events();
	sort_result();
	print_result();
}

static const char * const report_usage[] = {
	"perf lock report [<options>]",
	NULL
};

static const struct option report_options[] = {
	OPT_STRING('k', "key", &sort_key, "acquired",
		    "key for sorting"),
	/* TODO: type */
	OPT_END()
};

static const char * const lock_usage[] = {
	"perf lock [<options>] {record|trace|report}",
	NULL
};

static const struct option lock_options[] = {
	OPT_STRING('i', "input", &input_name, "file", "input file name"),
	OPT_BOOLEAN('v', "verbose", &verbose, "be more verbose (show symbol address, etc)"),
	OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace, "dump raw trace in ASCII"),
	OPT_END()
};

static const char *record_args[] = {
	"record",
	"-a",
	"-R",
	"-M",
	"-f",
	"-m", "1024",
	"-c", "1",
	"-e", "lock:lock_acquire:r",
	"-e", "lock:lock_acquired:r",
	"-e", "lock:lock_contended:r",
	"-e", "lock:lock_release:r",
};

static int __cmd_record(int argc, const char **argv)
{
	unsigned int rec_argc, i, j;
	const char **rec_argv;

	rec_argc = ARRAY_SIZE(record_args) + argc - 1;
	rec_argv = calloc(rec_argc + 1, sizeof(char *));

	for (i = 0; i < ARRAY_SIZE(record_args); i++)
		rec_argv[i] = strdup(record_args[i]);

	for (j = 1; j < (unsigned int)argc; j++, i++)
		rec_argv[i] = argv[j];

	BUG_ON(i != rec_argc);

	return cmd_record(i, rec_argv, NULL);
}

int cmd_lock(int argc, const char **argv, const char *prefix __used)
{
	unsigned int i;

	symbol__init();
	for (i = 0; i < LOCKHASH_SIZE; i++)
		INIT_LIST_HEAD(lockhash_table + i);

	argc = parse_options(argc, argv, lock_options, lock_usage,
			     PARSE_OPT_STOP_AT_NON_OPTION);
	if (!argc)
		usage_with_options(lock_usage, lock_options);

	if (!strncmp(argv[0], "rec", 3)) {
		return __cmd_record(argc, argv);
	} else if (!strncmp(argv[0], "report", 6)) {
		trace_handler = &report_lock_ops;
		if (argc) {
			argc = parse_options(argc, argv,
					     report_options, report_usage, 0);
			if (argc)
				usage_with_options(report_usage, report_options);
		}
		__cmd_report();
	} else if (!strcmp(argv[0], "trace")) {
		/* Aliased to 'perf trace' */
		return cmd_trace(argc, argv, prefix);
	} else if (!strcmp(argv[0], "map")) {
		/* recycling report_lock_ops */
		trace_handler = &report_lock_ops;
		setup_pager();
		read_events();
		dump_map();
	} else {
		usage_with_options(lock_usage, lock_options);
	}

	return 0;
}