]>
Commit | Line | Data |
---|---|---|
9b5e350c HM |
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 | ||
e4cef1f6 HM |
26 | static struct perf_session *session; |
27 | ||
9b5e350c HM |
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 | ||
9b5e350c | 37 | struct lock_stat { |
59f411b6 IM |
38 | struct list_head hash_entry; |
39 | struct rb_node rb; /* used for sorting */ | |
9b5e350c | 40 | |
59f411b6 IM |
41 | /* |
42 | * FIXME: raw_field_value() returns unsigned long long, | |
9b5e350c | 43 | * so address of lockdep_map should be dealed as 64bit. |
59f411b6 IM |
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 */ | |
9b5e350c | 48 | |
59f411b6 | 49 | unsigned int nr_acquire; |
e4cef1f6 | 50 | unsigned int nr_acquired; |
59f411b6 IM |
51 | unsigned int nr_contended; |
52 | unsigned int nr_release; | |
9b5e350c | 53 | |
e4cef1f6 HM |
54 | unsigned int nr_readlock; |
55 | unsigned int nr_trylock; | |
9b5e350c | 56 | /* these times are in nano sec. */ |
59f411b6 IM |
57 | u64 wait_time_total; |
58 | u64 wait_time_min; | |
59 | u64 wait_time_max; | |
e4cef1f6 HM |
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; | |
9b5e350c HM |
101 | }; |
102 | ||
e4cef1f6 HM |
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 | ||
9b5e350c | 194 | /* build simple key function one is bigger than two */ |
59f411b6 | 195 | #define SINGLE_KEY(member) \ |
9b5e350c HM |
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 | */ | |
59f411b6 IM |
214 | const char *name; |
215 | int (*key)(struct lock_stat*, struct lock_stat*); | |
9b5e350c HM |
216 | }; |
217 | ||
59f411b6 IM |
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 */ | |
9b5e350c HM |
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 | ||
9b5e350c | 252 | static void insert_to_result(struct lock_stat *st, |
59f411b6 | 253 | int (*bigger)(struct lock_stat *, struct lock_stat *)) |
9b5e350c HM |
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 | ||
59f411b6 | 288 | static struct lock_stat *lock_stat_findnew(void *addr, const char *name) |
9b5e350c HM |
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); | |
9b5e350c | 307 | |
9b5e350c HM |
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 | static int profile_cpu = -1; | |
320 | ||
321 | struct raw_event_sample { | |
59f411b6 IM |
322 | u32 size; |
323 | char data[0]; | |
9b5e350c HM |
324 | }; |
325 | ||
326 | struct trace_acquire_event { | |
59f411b6 IM |
327 | void *addr; |
328 | const char *name; | |
e4cef1f6 | 329 | int flag; |
9b5e350c HM |
330 | }; |
331 | ||
332 | struct trace_acquired_event { | |
59f411b6 IM |
333 | void *addr; |
334 | const char *name; | |
9b5e350c HM |
335 | }; |
336 | ||
337 | struct trace_contended_event { | |
59f411b6 IM |
338 | void *addr; |
339 | const char *name; | |
9b5e350c HM |
340 | }; |
341 | ||
342 | struct trace_release_event { | |
59f411b6 IM |
343 | void *addr; |
344 | const char *name; | |
9b5e350c HM |
345 | }; |
346 | ||
347 | struct trace_lock_handler { | |
348 | void (*acquire_event)(struct trace_acquire_event *, | |
349 | struct event *, | |
350 | int cpu, | |
351 | u64 timestamp, | |
352 | struct thread *thread); | |
353 | ||
354 | void (*acquired_event)(struct trace_acquired_event *, | |
355 | struct event *, | |
356 | int cpu, | |
357 | u64 timestamp, | |
358 | struct thread *thread); | |
359 | ||
360 | void (*contended_event)(struct trace_contended_event *, | |
361 | struct event *, | |
362 | int cpu, | |
363 | u64 timestamp, | |
364 | struct thread *thread); | |
365 | ||
366 | void (*release_event)(struct trace_release_event *, | |
367 | struct event *, | |
368 | int cpu, | |
369 | u64 timestamp, | |
370 | struct thread *thread); | |
371 | }; | |
372 | ||
e4cef1f6 HM |
373 | static struct lock_seq_stat *get_seq(struct thread_stat *ts, void *addr) |
374 | { | |
375 | struct lock_seq_stat *seq; | |
376 | ||
377 | list_for_each_entry(seq, &ts->seq_list, list) { | |
378 | if (seq->addr == addr) | |
379 | return seq; | |
380 | } | |
381 | ||
382 | seq = zalloc(sizeof(struct lock_seq_stat)); | |
383 | if (!seq) | |
384 | die("Not enough memory\n"); | |
385 | seq->state = SEQ_STATE_UNINITIALIZED; | |
386 | seq->addr = addr; | |
387 | ||
388 | list_add(&seq->list, &ts->seq_list); | |
389 | return seq; | |
390 | } | |
391 | ||
392 | static int bad_hist[4]; | |
393 | ||
59f411b6 IM |
394 | static void |
395 | report_lock_acquire_event(struct trace_acquire_event *acquire_event, | |
9b5e350c HM |
396 | struct event *__event __used, |
397 | int cpu __used, | |
e4cef1f6 | 398 | u64 timestamp __used, |
9b5e350c HM |
399 | struct thread *thread __used) |
400 | { | |
e4cef1f6 HM |
401 | struct lock_stat *ls; |
402 | struct thread_stat *ts; | |
403 | struct lock_seq_stat *seq; | |
404 | ||
405 | ls = lock_stat_findnew(acquire_event->addr, acquire_event->name); | |
406 | if (ls->discard) | |
407 | return; | |
9b5e350c | 408 | |
e4cef1f6 HM |
409 | ts = thread_stat_findnew(thread->pid); |
410 | seq = get_seq(ts, acquire_event->addr); | |
9b5e350c | 411 | |
e4cef1f6 HM |
412 | switch (seq->state) { |
413 | case SEQ_STATE_UNINITIALIZED: | |
414 | case SEQ_STATE_RELEASED: | |
415 | if (!acquire_event->flag) { | |
416 | seq->state = SEQ_STATE_ACQUIRING; | |
417 | } else { | |
418 | if (acquire_event->flag & 1) | |
419 | ls->nr_trylock++; | |
420 | if (acquire_event->flag & 2) | |
421 | ls->nr_readlock++; | |
422 | seq->state = SEQ_STATE_READ_ACQUIRED; | |
423 | seq->read_count = 1; | |
424 | ls->nr_acquired++; | |
425 | } | |
426 | break; | |
427 | case SEQ_STATE_READ_ACQUIRED: | |
428 | if (acquire_event->flag & 2) { | |
429 | seq->read_count++; | |
430 | ls->nr_acquired++; | |
431 | goto end; | |
432 | } else { | |
433 | goto broken; | |
434 | } | |
9b5e350c | 435 | break; |
e4cef1f6 HM |
436 | case SEQ_STATE_ACQUIRED: |
437 | case SEQ_STATE_ACQUIRING: | |
438 | case SEQ_STATE_CONTENDED: | |
439 | broken: | |
440 | /* broken lock sequence, discard it */ | |
441 | ls->discard = 1; | |
442 | bad_hist[0]++; | |
443 | list_del(&seq->list); | |
444 | free(seq); | |
445 | goto end; | |
9b5e350c HM |
446 | break; |
447 | default: | |
e4cef1f6 | 448 | BUG_ON("Unknown state of lock sequence found!\n"); |
9b5e350c HM |
449 | break; |
450 | } | |
451 | ||
e4cef1f6 HM |
452 | ls->nr_acquire++; |
453 | seq->prev_event_time = timestamp; | |
454 | end: | |
455 | return; | |
9b5e350c HM |
456 | } |
457 | ||
59f411b6 IM |
458 | static void |
459 | report_lock_acquired_event(struct trace_acquired_event *acquired_event, | |
9b5e350c HM |
460 | struct event *__event __used, |
461 | int cpu __used, | |
e4cef1f6 | 462 | u64 timestamp __used, |
9b5e350c HM |
463 | struct thread *thread __used) |
464 | { | |
e4cef1f6 HM |
465 | struct lock_stat *ls; |
466 | struct thread_stat *ts; | |
467 | struct lock_seq_stat *seq; | |
468 | u64 contended_term; | |
9b5e350c | 469 | |
e4cef1f6 HM |
470 | ls = lock_stat_findnew(acquired_event->addr, acquired_event->name); |
471 | if (ls->discard) | |
472 | return; | |
473 | ||
474 | ts = thread_stat_findnew(thread->pid); | |
475 | seq = get_seq(ts, acquired_event->addr); | |
9b5e350c | 476 | |
e4cef1f6 HM |
477 | switch (seq->state) { |
478 | case SEQ_STATE_UNINITIALIZED: | |
479 | /* orphan event, do nothing */ | |
480 | return; | |
481 | case SEQ_STATE_ACQUIRING: | |
9b5e350c | 482 | break; |
e4cef1f6 HM |
483 | case SEQ_STATE_CONTENDED: |
484 | contended_term = timestamp - seq->prev_event_time; | |
485 | ls->wait_time_total += contended_term; | |
486 | ||
487 | if (contended_term < ls->wait_time_min) | |
488 | ls->wait_time_min = contended_term; | |
489 | else if (ls->wait_time_max < contended_term) | |
490 | ls->wait_time_max = contended_term; | |
9b5e350c | 491 | break; |
e4cef1f6 HM |
492 | case SEQ_STATE_RELEASED: |
493 | case SEQ_STATE_ACQUIRED: | |
494 | case SEQ_STATE_READ_ACQUIRED: | |
495 | /* broken lock sequence, discard it */ | |
496 | ls->discard = 1; | |
497 | bad_hist[1]++; | |
498 | list_del(&seq->list); | |
499 | free(seq); | |
500 | goto end; | |
501 | break; | |
502 | ||
9b5e350c | 503 | default: |
e4cef1f6 | 504 | BUG_ON("Unknown state of lock sequence found!\n"); |
9b5e350c HM |
505 | break; |
506 | } | |
507 | ||
e4cef1f6 HM |
508 | seq->state = SEQ_STATE_ACQUIRED; |
509 | ls->nr_acquired++; | |
510 | seq->prev_event_time = timestamp; | |
511 | end: | |
512 | return; | |
9b5e350c HM |
513 | } |
514 | ||
59f411b6 IM |
515 | static void |
516 | report_lock_contended_event(struct trace_contended_event *contended_event, | |
9b5e350c HM |
517 | struct event *__event __used, |
518 | int cpu __used, | |
e4cef1f6 | 519 | u64 timestamp __used, |
9b5e350c HM |
520 | struct thread *thread __used) |
521 | { | |
e4cef1f6 HM |
522 | struct lock_stat *ls; |
523 | struct thread_stat *ts; | |
524 | struct lock_seq_stat *seq; | |
525 | ||
526 | ls = lock_stat_findnew(contended_event->addr, contended_event->name); | |
527 | if (ls->discard) | |
528 | return; | |
9b5e350c | 529 | |
e4cef1f6 HM |
530 | ts = thread_stat_findnew(thread->pid); |
531 | seq = get_seq(ts, contended_event->addr); | |
9b5e350c | 532 | |
e4cef1f6 HM |
533 | switch (seq->state) { |
534 | case SEQ_STATE_UNINITIALIZED: | |
535 | /* orphan event, do nothing */ | |
536 | return; | |
537 | case SEQ_STATE_ACQUIRING: | |
9b5e350c | 538 | break; |
e4cef1f6 HM |
539 | case SEQ_STATE_RELEASED: |
540 | case SEQ_STATE_ACQUIRED: | |
541 | case SEQ_STATE_READ_ACQUIRED: | |
542 | case SEQ_STATE_CONTENDED: | |
543 | /* broken lock sequence, discard it */ | |
544 | ls->discard = 1; | |
545 | bad_hist[2]++; | |
546 | list_del(&seq->list); | |
547 | free(seq); | |
548 | goto end; | |
9b5e350c HM |
549 | break; |
550 | default: | |
e4cef1f6 | 551 | BUG_ON("Unknown state of lock sequence found!\n"); |
9b5e350c HM |
552 | break; |
553 | } | |
554 | ||
e4cef1f6 HM |
555 | seq->state = SEQ_STATE_CONTENDED; |
556 | ls->nr_contended++; | |
557 | seq->prev_event_time = timestamp; | |
558 | end: | |
559 | return; | |
9b5e350c HM |
560 | } |
561 | ||
59f411b6 IM |
562 | static void |
563 | report_lock_release_event(struct trace_release_event *release_event, | |
9b5e350c HM |
564 | struct event *__event __used, |
565 | int cpu __used, | |
e4cef1f6 | 566 | u64 timestamp __used, |
9b5e350c HM |
567 | struct thread *thread __used) |
568 | { | |
e4cef1f6 HM |
569 | struct lock_stat *ls; |
570 | struct thread_stat *ts; | |
571 | struct lock_seq_stat *seq; | |
9b5e350c | 572 | |
e4cef1f6 HM |
573 | ls = lock_stat_findnew(release_event->addr, release_event->name); |
574 | if (ls->discard) | |
575 | return; | |
9b5e350c | 576 | |
e4cef1f6 HM |
577 | ts = thread_stat_findnew(thread->pid); |
578 | seq = get_seq(ts, release_event->addr); | |
9b5e350c | 579 | |
e4cef1f6 HM |
580 | switch (seq->state) { |
581 | case SEQ_STATE_UNINITIALIZED: | |
582 | goto end; | |
583 | break; | |
584 | case SEQ_STATE_ACQUIRED: | |
585 | break; | |
586 | case SEQ_STATE_READ_ACQUIRED: | |
587 | seq->read_count--; | |
588 | BUG_ON(seq->read_count < 0); | |
589 | if (!seq->read_count) { | |
590 | ls->nr_release++; | |
9b5e350c HM |
591 | goto end; |
592 | } | |
e4cef1f6 HM |
593 | break; |
594 | case SEQ_STATE_ACQUIRING: | |
595 | case SEQ_STATE_CONTENDED: | |
596 | case SEQ_STATE_RELEASED: | |
597 | /* broken lock sequence, discard it */ | |
598 | ls->discard = 1; | |
599 | bad_hist[3]++; | |
600 | goto free_seq; | |
9b5e350c HM |
601 | break; |
602 | default: | |
e4cef1f6 | 603 | BUG_ON("Unknown state of lock sequence found!\n"); |
9b5e350c HM |
604 | break; |
605 | } | |
606 | ||
e4cef1f6 HM |
607 | ls->nr_release++; |
608 | free_seq: | |
609 | list_del(&seq->list); | |
610 | free(seq); | |
9b5e350c | 611 | end: |
e4cef1f6 | 612 | return; |
9b5e350c HM |
613 | } |
614 | ||
615 | /* lock oriented handlers */ | |
616 | /* TODO: handlers for CPU oriented, thread oriented */ | |
59f411b6 IM |
617 | static struct trace_lock_handler report_lock_ops = { |
618 | .acquire_event = report_lock_acquire_event, | |
619 | .acquired_event = report_lock_acquired_event, | |
620 | .contended_event = report_lock_contended_event, | |
621 | .release_event = report_lock_release_event, | |
9b5e350c HM |
622 | }; |
623 | ||
624 | static struct trace_lock_handler *trace_handler; | |
625 | ||
626 | static void | |
627 | process_lock_acquire_event(void *data, | |
628 | struct event *event __used, | |
629 | int cpu __used, | |
630 | u64 timestamp __used, | |
631 | struct thread *thread __used) | |
632 | { | |
633 | struct trace_acquire_event acquire_event; | |
634 | u64 tmp; /* this is required for casting... */ | |
635 | ||
636 | tmp = raw_field_value(event, "lockdep_addr", data); | |
637 | memcpy(&acquire_event.addr, &tmp, sizeof(void *)); | |
638 | acquire_event.name = (char *)raw_field_ptr(event, "name", data); | |
e4cef1f6 | 639 | acquire_event.flag = (int)raw_field_value(event, "flag", data); |
9b5e350c | 640 | |
59f411b6 IM |
641 | if (trace_handler->acquire_event) |
642 | trace_handler->acquire_event(&acquire_event, event, cpu, timestamp, thread); | |
9b5e350c HM |
643 | } |
644 | ||
645 | static void | |
646 | process_lock_acquired_event(void *data, | |
647 | struct event *event __used, | |
648 | int cpu __used, | |
649 | u64 timestamp __used, | |
650 | struct thread *thread __used) | |
651 | { | |
652 | struct trace_acquired_event acquired_event; | |
653 | u64 tmp; /* this is required for casting... */ | |
654 | ||
655 | tmp = raw_field_value(event, "lockdep_addr", data); | |
656 | memcpy(&acquired_event.addr, &tmp, sizeof(void *)); | |
657 | acquired_event.name = (char *)raw_field_ptr(event, "name", data); | |
9b5e350c | 658 | |
59f411b6 IM |
659 | if (trace_handler->acquire_event) |
660 | trace_handler->acquired_event(&acquired_event, event, cpu, timestamp, thread); | |
9b5e350c HM |
661 | } |
662 | ||
663 | static void | |
664 | process_lock_contended_event(void *data, | |
665 | struct event *event __used, | |
666 | int cpu __used, | |
667 | u64 timestamp __used, | |
668 | struct thread *thread __used) | |
669 | { | |
670 | struct trace_contended_event contended_event; | |
671 | u64 tmp; /* this is required for casting... */ | |
672 | ||
673 | tmp = raw_field_value(event, "lockdep_addr", data); | |
674 | memcpy(&contended_event.addr, &tmp, sizeof(void *)); | |
675 | contended_event.name = (char *)raw_field_ptr(event, "name", data); | |
9b5e350c | 676 | |
59f411b6 IM |
677 | if (trace_handler->acquire_event) |
678 | trace_handler->contended_event(&contended_event, event, cpu, timestamp, thread); | |
9b5e350c HM |
679 | } |
680 | ||
681 | static void | |
682 | process_lock_release_event(void *data, | |
683 | struct event *event __used, | |
684 | int cpu __used, | |
685 | u64 timestamp __used, | |
686 | struct thread *thread __used) | |
687 | { | |
688 | struct trace_release_event release_event; | |
689 | u64 tmp; /* this is required for casting... */ | |
690 | ||
691 | tmp = raw_field_value(event, "lockdep_addr", data); | |
692 | memcpy(&release_event.addr, &tmp, sizeof(void *)); | |
693 | release_event.name = (char *)raw_field_ptr(event, "name", data); | |
9b5e350c | 694 | |
59f411b6 IM |
695 | if (trace_handler->acquire_event) |
696 | trace_handler->release_event(&release_event, event, cpu, timestamp, thread); | |
9b5e350c HM |
697 | } |
698 | ||
699 | static void | |
e4cef1f6 HM |
700 | process_raw_event(void *data, int cpu __used, |
701 | u64 timestamp __used, struct thread *thread __used) | |
9b5e350c HM |
702 | { |
703 | struct event *event; | |
704 | int type; | |
705 | ||
706 | type = trace_parse_common_type(data); | |
707 | event = trace_find_event(type); | |
708 | ||
709 | if (!strcmp(event->name, "lock_acquire")) | |
710 | process_lock_acquire_event(data, event, cpu, timestamp, thread); | |
711 | if (!strcmp(event->name, "lock_acquired")) | |
712 | process_lock_acquired_event(data, event, cpu, timestamp, thread); | |
713 | if (!strcmp(event->name, "lock_contended")) | |
714 | process_lock_contended_event(data, event, cpu, timestamp, thread); | |
715 | if (!strcmp(event->name, "lock_release")) | |
716 | process_lock_release_event(data, event, cpu, timestamp, thread); | |
717 | } | |
718 | ||
b67577df FW |
719 | struct raw_event_queue { |
720 | u64 timestamp; | |
721 | int cpu; | |
722 | void *data; | |
723 | struct thread *thread; | |
724 | struct list_head list; | |
725 | }; | |
726 | ||
727 | static LIST_HEAD(raw_event_head); | |
728 | ||
729 | #define FLUSH_PERIOD (5 * NSEC_PER_SEC) | |
730 | ||
731 | static u64 flush_limit = ULLONG_MAX; | |
732 | static u64 last_flush = 0; | |
733 | struct raw_event_queue *last_inserted; | |
734 | ||
735 | static void flush_raw_event_queue(u64 limit) | |
736 | { | |
737 | struct raw_event_queue *tmp, *iter; | |
738 | ||
739 | list_for_each_entry_safe(iter, tmp, &raw_event_head, list) { | |
740 | if (iter->timestamp > limit) | |
741 | return; | |
742 | ||
743 | if (iter == last_inserted) | |
744 | last_inserted = NULL; | |
745 | ||
746 | process_raw_event(iter->data, iter->cpu, iter->timestamp, | |
747 | iter->thread); | |
748 | ||
749 | last_flush = iter->timestamp; | |
750 | list_del(&iter->list); | |
751 | free(iter->data); | |
752 | free(iter); | |
753 | } | |
754 | } | |
755 | ||
756 | static void __queue_raw_event_end(struct raw_event_queue *new) | |
757 | { | |
758 | struct raw_event_queue *iter; | |
759 | ||
760 | list_for_each_entry_reverse(iter, &raw_event_head, list) { | |
761 | if (iter->timestamp < new->timestamp) { | |
762 | list_add(&new->list, &iter->list); | |
763 | return; | |
764 | } | |
765 | } | |
766 | ||
767 | list_add(&new->list, &raw_event_head); | |
768 | } | |
769 | ||
770 | static void __queue_raw_event_before(struct raw_event_queue *new, | |
771 | struct raw_event_queue *iter) | |
772 | { | |
773 | list_for_each_entry_continue_reverse(iter, &raw_event_head, list) { | |
774 | if (iter->timestamp < new->timestamp) { | |
775 | list_add(&new->list, &iter->list); | |
776 | return; | |
777 | } | |
778 | } | |
779 | ||
780 | list_add(&new->list, &raw_event_head); | |
781 | } | |
782 | ||
783 | static void __queue_raw_event_after(struct raw_event_queue *new, | |
784 | struct raw_event_queue *iter) | |
785 | { | |
786 | list_for_each_entry_continue(iter, &raw_event_head, list) { | |
787 | if (iter->timestamp > new->timestamp) { | |
788 | list_add_tail(&new->list, &iter->list); | |
789 | return; | |
790 | } | |
791 | } | |
792 | list_add_tail(&new->list, &raw_event_head); | |
793 | } | |
794 | ||
795 | /* The queue is ordered by time */ | |
796 | static void __queue_raw_event(struct raw_event_queue *new) | |
797 | { | |
798 | if (!last_inserted) { | |
799 | __queue_raw_event_end(new); | |
800 | return; | |
801 | } | |
802 | ||
803 | /* | |
804 | * Most of the time the current event has a timestamp | |
805 | * very close to the last event inserted, unless we just switched | |
806 | * to another event buffer. Having a sorting based on a list and | |
807 | * on the last inserted event that is close to the current one is | |
808 | * probably more efficient than an rbtree based sorting. | |
809 | */ | |
810 | if (last_inserted->timestamp >= new->timestamp) | |
811 | __queue_raw_event_before(new, last_inserted); | |
812 | else | |
813 | __queue_raw_event_after(new, last_inserted); | |
814 | } | |
815 | ||
816 | static void queue_raw_event(void *data, int raw_size, int cpu, | |
817 | u64 timestamp, struct thread *thread) | |
818 | { | |
819 | struct raw_event_queue *new; | |
820 | ||
821 | if (flush_limit == ULLONG_MAX) | |
822 | flush_limit = timestamp + FLUSH_PERIOD; | |
823 | ||
824 | if (timestamp < last_flush) { | |
825 | printf("Warning: Timestamp below last timeslice flush\n"); | |
826 | return; | |
827 | } | |
828 | ||
829 | new = malloc(sizeof(*new)); | |
830 | if (!new) | |
831 | die("Not enough memory\n"); | |
832 | ||
833 | new->timestamp = timestamp; | |
834 | new->cpu = cpu; | |
835 | new->thread = thread; | |
836 | ||
837 | new->data = malloc(raw_size); | |
838 | if (!new->data) | |
839 | die("Not enough memory\n"); | |
840 | ||
841 | memcpy(new->data, data, raw_size); | |
842 | ||
843 | __queue_raw_event(new); | |
844 | last_inserted = new; | |
845 | ||
846 | /* | |
847 | * We want to have a slice of events covering 2 * FLUSH_PERIOD | |
848 | * If FLUSH_PERIOD is big enough, it ensures every events that occured | |
849 | * in the first half of the timeslice have all been buffered and there | |
850 | * are none remaining (we need that because of the weakly ordered | |
851 | * event recording we have). Then once we reach the 2 * FLUSH_PERIOD | |
852 | * timeslice, we flush the first half to be gentle with the memory | |
853 | * (the second half can still get new events in the middle, so wait | |
854 | * another period to flush it) | |
855 | */ | |
856 | if (new->timestamp > flush_limit && | |
857 | new->timestamp - flush_limit > FLUSH_PERIOD) { | |
858 | flush_limit += FLUSH_PERIOD; | |
859 | flush_raw_event_queue(flush_limit); | |
860 | } | |
861 | } | |
862 | ||
e4cef1f6 | 863 | static int process_sample_event(event_t *event, struct perf_session *s) |
9b5e350c HM |
864 | { |
865 | struct thread *thread; | |
866 | struct sample_data data; | |
867 | ||
868 | bzero(&data, sizeof(struct sample_data)); | |
e4cef1f6 HM |
869 | event__parse_sample(event, s->sample_type, &data); |
870 | /* CAUTION: using tid as thread.pid */ | |
871 | thread = perf_session__findnew(s, data.tid); | |
9b5e350c | 872 | |
9b5e350c HM |
873 | if (thread == NULL) { |
874 | pr_debug("problem processing %d event, skipping it.\n", | |
875 | event->header.type); | |
876 | return -1; | |
877 | } | |
878 | ||
879 | dump_printf(" ... thread: %s:%d\n", thread->comm, thread->pid); | |
880 | ||
881 | if (profile_cpu != -1 && profile_cpu != (int) data.cpu) | |
882 | return 0; | |
883 | ||
b67577df | 884 | queue_raw_event(data.raw_data, data.raw_size, data.cpu, data.time, thread); |
9b5e350c HM |
885 | |
886 | return 0; | |
887 | } | |
888 | ||
889 | /* TODO: various way to print, coloring, nano or milli sec */ | |
890 | static void print_result(void) | |
891 | { | |
892 | struct lock_stat *st; | |
893 | char cut_name[20]; | |
e4cef1f6 | 894 | int bad, total; |
9b5e350c | 895 | |
9b5e350c HM |
896 | printf("%20s ", "Name"); |
897 | printf("%10s ", "acquired"); | |
898 | printf("%10s ", "contended"); | |
899 | ||
900 | printf("%15s ", "total wait (ns)"); | |
901 | printf("%15s ", "max wait (ns)"); | |
902 | printf("%15s ", "min wait (ns)"); | |
903 | ||
904 | printf("\n\n"); | |
905 | ||
e4cef1f6 | 906 | bad = total = 0; |
9b5e350c | 907 | while ((st = pop_from_result())) { |
e4cef1f6 HM |
908 | total++; |
909 | if (st->discard) { | |
910 | bad++; | |
911 | continue; | |
912 | } | |
9b5e350c HM |
913 | bzero(cut_name, 20); |
914 | ||
9b5e350c HM |
915 | if (strlen(st->name) < 16) { |
916 | /* output raw name */ | |
917 | printf("%20s ", st->name); | |
918 | } else { | |
919 | strncpy(cut_name, st->name, 16); | |
920 | cut_name[16] = '.'; | |
921 | cut_name[17] = '.'; | |
922 | cut_name[18] = '.'; | |
923 | cut_name[19] = '\0'; | |
924 | /* cut off name for saving output style */ | |
925 | printf("%20s ", cut_name); | |
926 | } | |
927 | ||
928 | printf("%10u ", st->nr_acquired); | |
929 | printf("%10u ", st->nr_contended); | |
930 | ||
931 | printf("%15llu ", st->wait_time_total); | |
932 | printf("%15llu ", st->wait_time_max); | |
933 | printf("%15llu ", st->wait_time_min == ULLONG_MAX ? | |
934 | 0 : st->wait_time_min); | |
935 | printf("\n"); | |
936 | } | |
e4cef1f6 HM |
937 | |
938 | { | |
939 | /* Output for debug, this have to be removed */ | |
940 | int i; | |
941 | const char *name[4] = | |
942 | { "acquire", "acquired", "contended", "release" }; | |
943 | ||
944 | printf("\n=== output for debug===\n\n"); | |
945 | printf("bad:%d, total:%d\n", bad, total); | |
946 | printf("bad rate:%f\n", (double)(bad / total)); | |
947 | ||
948 | printf("histogram of events caused bad sequence\n"); | |
949 | for (i = 0; i < 4; i++) | |
950 | printf(" %10s: %d\n", name[i], bad_hist[i]); | |
951 | } | |
9b5e350c HM |
952 | } |
953 | ||
954 | static void dump_map(void) | |
955 | { | |
956 | unsigned int i; | |
957 | struct lock_stat *st; | |
958 | ||
959 | for (i = 0; i < LOCKHASH_SIZE; i++) { | |
960 | list_for_each_entry(st, &lockhash_table[i], hash_entry) { | |
59f411b6 | 961 | printf("%p: %s\n", st->addr, st->name); |
9b5e350c HM |
962 | } |
963 | } | |
964 | } | |
965 | ||
966 | static struct perf_event_ops eops = { | |
59f411b6 IM |
967 | .sample = process_sample_event, |
968 | .comm = event__process_comm, | |
9b5e350c HM |
969 | }; |
970 | ||
9b5e350c HM |
971 | static int read_events(void) |
972 | { | |
973 | session = perf_session__new(input_name, O_RDONLY, 0); | |
974 | if (!session) | |
975 | die("Initializing perf session failed\n"); | |
976 | ||
977 | return perf_session__process_events(session, &eops); | |
978 | } | |
979 | ||
980 | static void sort_result(void) | |
981 | { | |
982 | unsigned int i; | |
983 | struct lock_stat *st; | |
984 | ||
985 | for (i = 0; i < LOCKHASH_SIZE; i++) { | |
986 | list_for_each_entry(st, &lockhash_table[i], hash_entry) { | |
987 | insert_to_result(st, compare); | |
988 | } | |
989 | } | |
990 | } | |
991 | ||
59f411b6 | 992 | static void __cmd_report(void) |
9b5e350c HM |
993 | { |
994 | setup_pager(); | |
995 | select_key(); | |
996 | read_events(); | |
b67577df | 997 | flush_raw_event_queue(ULLONG_MAX); |
9b5e350c HM |
998 | sort_result(); |
999 | print_result(); | |
1000 | } | |
1001 | ||
59f411b6 IM |
1002 | static const char * const report_usage[] = { |
1003 | "perf lock report [<options>]", | |
9b5e350c HM |
1004 | NULL |
1005 | }; | |
1006 | ||
59f411b6 | 1007 | static const struct option report_options[] = { |
9b5e350c HM |
1008 | OPT_STRING('k', "key", &sort_key, "acquired", |
1009 | "key for sorting"), | |
1010 | /* TODO: type */ | |
1011 | OPT_END() | |
1012 | }; | |
1013 | ||
1014 | static const char * const lock_usage[] = { | |
59f411b6 | 1015 | "perf lock [<options>] {record|trace|report}", |
9b5e350c HM |
1016 | NULL |
1017 | }; | |
1018 | ||
1019 | static const struct option lock_options[] = { | |
59f411b6 | 1020 | OPT_STRING('i', "input", &input_name, "file", "input file name"), |
c0555642 | 1021 | OPT_INCR('v', "verbose", &verbose, "be more verbose (show symbol address, etc)"), |
59f411b6 | 1022 | OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace, "dump raw trace in ASCII"), |
9b5e350c HM |
1023 | OPT_END() |
1024 | }; | |
1025 | ||
1026 | static const char *record_args[] = { | |
1027 | "record", | |
1028 | "-a", | |
1029 | "-R", | |
9b5e350c HM |
1030 | "-f", |
1031 | "-m", "1024", | |
1032 | "-c", "1", | |
1033 | "-e", "lock:lock_acquire:r", | |
1034 | "-e", "lock:lock_acquired:r", | |
1035 | "-e", "lock:lock_contended:r", | |
1036 | "-e", "lock:lock_release:r", | |
1037 | }; | |
1038 | ||
1039 | static int __cmd_record(int argc, const char **argv) | |
1040 | { | |
1041 | unsigned int rec_argc, i, j; | |
1042 | const char **rec_argv; | |
1043 | ||
1044 | rec_argc = ARRAY_SIZE(record_args) + argc - 1; | |
1045 | rec_argv = calloc(rec_argc + 1, sizeof(char *)); | |
1046 | ||
1047 | for (i = 0; i < ARRAY_SIZE(record_args); i++) | |
1048 | rec_argv[i] = strdup(record_args[i]); | |
1049 | ||
1050 | for (j = 1; j < (unsigned int)argc; j++, i++) | |
1051 | rec_argv[i] = argv[j]; | |
1052 | ||
1053 | BUG_ON(i != rec_argc); | |
1054 | ||
1055 | return cmd_record(i, rec_argv, NULL); | |
1056 | } | |
1057 | ||
1058 | int cmd_lock(int argc, const char **argv, const char *prefix __used) | |
1059 | { | |
1060 | unsigned int i; | |
1061 | ||
1062 | symbol__init(); | |
1063 | for (i = 0; i < LOCKHASH_SIZE; i++) | |
1064 | INIT_LIST_HEAD(lockhash_table + i); | |
1065 | ||
1066 | argc = parse_options(argc, argv, lock_options, lock_usage, | |
1067 | PARSE_OPT_STOP_AT_NON_OPTION); | |
1068 | if (!argc) | |
1069 | usage_with_options(lock_usage, lock_options); | |
1070 | ||
1071 | if (!strncmp(argv[0], "rec", 3)) { | |
1072 | return __cmd_record(argc, argv); | |
59f411b6 IM |
1073 | } else if (!strncmp(argv[0], "report", 6)) { |
1074 | trace_handler = &report_lock_ops; | |
9b5e350c HM |
1075 | if (argc) { |
1076 | argc = parse_options(argc, argv, | |
59f411b6 | 1077 | report_options, report_usage, 0); |
9b5e350c | 1078 | if (argc) |
59f411b6 | 1079 | usage_with_options(report_usage, report_options); |
9b5e350c | 1080 | } |
59f411b6 | 1081 | __cmd_report(); |
9b5e350c HM |
1082 | } else if (!strcmp(argv[0], "trace")) { |
1083 | /* Aliased to 'perf trace' */ | |
1084 | return cmd_trace(argc, argv, prefix); | |
1085 | } else if (!strcmp(argv[0], "map")) { | |
59f411b6 IM |
1086 | /* recycling report_lock_ops */ |
1087 | trace_handler = &report_lock_ops; | |
9b5e350c HM |
1088 | setup_pager(); |
1089 | read_events(); | |
1090 | dump_map(); | |
1091 | } else { | |
1092 | usage_with_options(lock_usage, lock_options); | |
1093 | } | |
1094 | ||
1095 | return 0; | |
1096 | } |