1 // SPDX-License-Identifier: GPL-2.0 2 #include <errno.h> 3 #include <inttypes.h> 4 #include "builtin.h" 5 #include "perf.h" 6 7 #include "util/evlist.h" // for struct evsel_str_handler 8 #include "util/evsel.h" 9 #include "util/symbol.h" 10 #include "util/thread.h" 11 #include "util/header.h" 12 #include "util/callchain.h" 13 14 #include <subcmd/pager.h> 15 #include <subcmd/parse-options.h> 16 #include "util/trace-event.h" 17 18 #include "util/debug.h" 19 #include "util/session.h" 20 #include "util/tool.h" 21 #include "util/data.h" 22 #include "util/string2.h" 23 #include "util/map.h" 24 25 #include <sys/types.h> 26 #include <sys/prctl.h> 27 #include <semaphore.h> 28 #include <pthread.h> 29 #include <math.h> 30 #include <limits.h> 31 32 #include <linux/list.h> 33 #include <linux/hash.h> 34 #include <linux/kernel.h> 35 #include <linux/zalloc.h> 36 #include <linux/err.h> 37 #include <linux/stringify.h> 38 39 static struct perf_session *session; 40 41 /* based on kernel/lockdep.c */ 42 #define LOCKHASH_BITS 12 43 #define LOCKHASH_SIZE (1UL << LOCKHASH_BITS) 44 45 static struct hlist_head lockhash_table[LOCKHASH_SIZE]; 46 47 #define __lockhashfn(key) hash_long((unsigned long)key, LOCKHASH_BITS) 48 #define lockhashentry(key) (lockhash_table + __lockhashfn((key))) 49 50 struct lock_stat { 51 struct hlist_node hash_entry; 52 struct rb_node rb; /* used for sorting */ 53 54 u64 addr; /* address of lockdep_map, used as ID */ 55 char *name; /* for strcpy(), we cannot use const */ 56 57 unsigned int nr_acquire; 58 unsigned int nr_acquired; 59 unsigned int nr_contended; 60 unsigned int nr_release; 61 62 union { 63 unsigned int nr_readlock; 64 unsigned int flags; 65 }; 66 unsigned int nr_trylock; 67 68 /* these times are in nano sec. */ 69 u64 avg_wait_time; 70 u64 wait_time_total; 71 u64 wait_time_min; 72 u64 wait_time_max; 73 74 int broken; /* flag of blacklist */ 75 int combined; 76 }; 77 78 /* 79 * States of lock_seq_stat 80 * 81 * UNINITIALIZED is required for detecting first event of acquire. 82 * As the nature of lock events, there is no guarantee 83 * that the first event for the locks are acquire, 84 * it can be acquired, contended or release. 85 */ 86 #define SEQ_STATE_UNINITIALIZED 0 /* initial state */ 87 #define SEQ_STATE_RELEASED 1 88 #define SEQ_STATE_ACQUIRING 2 89 #define SEQ_STATE_ACQUIRED 3 90 #define SEQ_STATE_READ_ACQUIRED 4 91 #define SEQ_STATE_CONTENDED 5 92 93 /* 94 * MAX_LOCK_DEPTH 95 * Imported from include/linux/sched.h. 96 * Should this be synchronized? 97 */ 98 #define MAX_LOCK_DEPTH 48 99 100 /* 101 * struct lock_seq_stat: 102 * Place to put on state of one lock sequence 103 * 1) acquire -> acquired -> release 104 * 2) acquire -> contended -> acquired -> release 105 * 3) acquire (with read or try) -> release 106 * 4) Are there other patterns? 107 */ 108 struct lock_seq_stat { 109 struct list_head list; 110 int state; 111 u64 prev_event_time; 112 u64 addr; 113 114 int read_count; 115 }; 116 117 struct thread_stat { 118 struct rb_node rb; 119 120 u32 tid; 121 struct list_head seq_list; 122 }; 123 124 static struct rb_root thread_stats; 125 126 static bool combine_locks; 127 static bool show_thread_stats; 128 129 static enum { 130 LOCK_AGGR_ADDR, 131 LOCK_AGGR_TASK, 132 LOCK_AGGR_CALLER, 133 } aggr_mode = LOCK_AGGR_ADDR; 134 135 /* 136 * CONTENTION_STACK_DEPTH 137 * Number of stack trace entries to find callers 138 */ 139 #define CONTENTION_STACK_DEPTH 8 140 141 /* 142 * CONTENTION_STACK_SKIP 143 * Number of stack trace entries to skip when finding callers. 144 * The first few entries belong to the locking implementation itself. 145 */ 146 #define CONTENTION_STACK_SKIP 3 147 148 /* 149 * flags for lock:contention_begin 150 * Imported from include/trace/events/lock.h. 151 */ 152 #define LCB_F_SPIN (1U << 0) 153 #define LCB_F_READ (1U << 1) 154 #define LCB_F_WRITE (1U << 2) 155 #define LCB_F_RT (1U << 3) 156 #define LCB_F_PERCPU (1U << 4) 157 #define LCB_F_MUTEX (1U << 5) 158 159 160 static u64 sched_text_start; 161 static u64 sched_text_end; 162 static u64 lock_text_start; 163 static u64 lock_text_end; 164 165 static struct thread_stat *thread_stat_find(u32 tid) 166 { 167 struct rb_node *node; 168 struct thread_stat *st; 169 170 node = thread_stats.rb_node; 171 while (node) { 172 st = container_of(node, struct thread_stat, rb); 173 if (st->tid == tid) 174 return st; 175 else if (tid < st->tid) 176 node = node->rb_left; 177 else 178 node = node->rb_right; 179 } 180 181 return NULL; 182 } 183 184 static void thread_stat_insert(struct thread_stat *new) 185 { 186 struct rb_node **rb = &thread_stats.rb_node; 187 struct rb_node *parent = NULL; 188 struct thread_stat *p; 189 190 while (*rb) { 191 p = container_of(*rb, struct thread_stat, rb); 192 parent = *rb; 193 194 if (new->tid < p->tid) 195 rb = &(*rb)->rb_left; 196 else if (new->tid > p->tid) 197 rb = &(*rb)->rb_right; 198 else 199 BUG_ON("inserting invalid thread_stat\n"); 200 } 201 202 rb_link_node(&new->rb, parent, rb); 203 rb_insert_color(&new->rb, &thread_stats); 204 } 205 206 static struct thread_stat *thread_stat_findnew_after_first(u32 tid) 207 { 208 struct thread_stat *st; 209 210 st = thread_stat_find(tid); 211 if (st) 212 return st; 213 214 st = zalloc(sizeof(struct thread_stat)); 215 if (!st) { 216 pr_err("memory allocation failed\n"); 217 return NULL; 218 } 219 220 st->tid = tid; 221 INIT_LIST_HEAD(&st->seq_list); 222 223 thread_stat_insert(st); 224 225 return st; 226 } 227 228 static struct thread_stat *thread_stat_findnew_first(u32 tid); 229 static struct thread_stat *(*thread_stat_findnew)(u32 tid) = 230 thread_stat_findnew_first; 231 232 static struct thread_stat *thread_stat_findnew_first(u32 tid) 233 { 234 struct thread_stat *st; 235 236 st = zalloc(sizeof(struct thread_stat)); 237 if (!st) { 238 pr_err("memory allocation failed\n"); 239 return NULL; 240 } 241 st->tid = tid; 242 INIT_LIST_HEAD(&st->seq_list); 243 244 rb_link_node(&st->rb, NULL, &thread_stats.rb_node); 245 rb_insert_color(&st->rb, &thread_stats); 246 247 thread_stat_findnew = thread_stat_findnew_after_first; 248 return st; 249 } 250 251 /* build simple key function one is bigger than two */ 252 #define SINGLE_KEY(member) \ 253 static int lock_stat_key_ ## member(struct lock_stat *one, \ 254 struct lock_stat *two) \ 255 { \ 256 return one->member > two->member; \ 257 } 258 259 SINGLE_KEY(nr_acquired) 260 SINGLE_KEY(nr_contended) 261 SINGLE_KEY(avg_wait_time) 262 SINGLE_KEY(wait_time_total) 263 SINGLE_KEY(wait_time_max) 264 265 static int lock_stat_key_wait_time_min(struct lock_stat *one, 266 struct lock_stat *two) 267 { 268 u64 s1 = one->wait_time_min; 269 u64 s2 = two->wait_time_min; 270 if (s1 == ULLONG_MAX) 271 s1 = 0; 272 if (s2 == ULLONG_MAX) 273 s2 = 0; 274 return s1 > s2; 275 } 276 277 struct lock_key { 278 /* 279 * name: the value for specify by user 280 * this should be simpler than raw name of member 281 * e.g. nr_acquired -> acquired, wait_time_total -> wait_total 282 */ 283 const char *name; 284 /* header: the string printed on the header line */ 285 const char *header; 286 /* len: the printing width of the field */ 287 int len; 288 /* key: a pointer to function to compare two lock stats for sorting */ 289 int (*key)(struct lock_stat*, struct lock_stat*); 290 /* print: a pointer to function to print a given lock stats */ 291 void (*print)(struct lock_key*, struct lock_stat*); 292 /* list: list entry to link this */ 293 struct list_head list; 294 }; 295 296 static void lock_stat_key_print_time(unsigned long long nsec, int len) 297 { 298 static const struct { 299 float base; 300 const char *unit; 301 } table[] = { 302 { 1e9 * 3600, "h " }, 303 { 1e9 * 60, "m " }, 304 { 1e9, "s " }, 305 { 1e6, "ms" }, 306 { 1e3, "us" }, 307 { 0, NULL }, 308 }; 309 310 for (int i = 0; table[i].unit; i++) { 311 if (nsec < table[i].base) 312 continue; 313 314 pr_info("%*.2f %s", len - 3, nsec / table[i].base, table[i].unit); 315 return; 316 } 317 318 pr_info("%*llu %s", len - 3, nsec, "ns"); 319 } 320 321 #define PRINT_KEY(member) \ 322 static void lock_stat_key_print_ ## member(struct lock_key *key, \ 323 struct lock_stat *ls) \ 324 { \ 325 pr_info("%*llu", key->len, (unsigned long long)ls->member); \ 326 } 327 328 #define PRINT_TIME(member) \ 329 static void lock_stat_key_print_ ## member(struct lock_key *key, \ 330 struct lock_stat *ls) \ 331 { \ 332 lock_stat_key_print_time((unsigned long long)ls->member, key->len); \ 333 } 334 335 PRINT_KEY(nr_acquired) 336 PRINT_KEY(nr_contended) 337 PRINT_TIME(avg_wait_time) 338 PRINT_TIME(wait_time_total) 339 PRINT_TIME(wait_time_max) 340 341 static void lock_stat_key_print_wait_time_min(struct lock_key *key, 342 struct lock_stat *ls) 343 { 344 u64 wait_time = ls->wait_time_min; 345 346 if (wait_time == ULLONG_MAX) 347 wait_time = 0; 348 349 lock_stat_key_print_time(wait_time, key->len); 350 } 351 352 353 static const char *sort_key = "acquired"; 354 355 static int (*compare)(struct lock_stat *, struct lock_stat *); 356 357 static struct rb_root sorted; /* place to store intermediate data */ 358 static struct rb_root result; /* place to store sorted data */ 359 360 static LIST_HEAD(lock_keys); 361 static const char *output_fields; 362 363 #define DEF_KEY_LOCK(name, header, fn_suffix, len) \ 364 { #name, header, len, lock_stat_key_ ## fn_suffix, lock_stat_key_print_ ## fn_suffix, {} } 365 static struct lock_key report_keys[] = { 366 DEF_KEY_LOCK(acquired, "acquired", nr_acquired, 10), 367 DEF_KEY_LOCK(contended, "contended", nr_contended, 10), 368 DEF_KEY_LOCK(avg_wait, "avg wait", avg_wait_time, 12), 369 DEF_KEY_LOCK(wait_total, "total wait", wait_time_total, 12), 370 DEF_KEY_LOCK(wait_max, "max wait", wait_time_max, 12), 371 DEF_KEY_LOCK(wait_min, "min wait", wait_time_min, 12), 372 373 /* extra comparisons much complicated should be here */ 374 { } 375 }; 376 377 static struct lock_key contention_keys[] = { 378 DEF_KEY_LOCK(contended, "contended", nr_contended, 10), 379 DEF_KEY_LOCK(wait_total, "total wait", wait_time_total, 12), 380 DEF_KEY_LOCK(wait_max, "max wait", wait_time_max, 12), 381 DEF_KEY_LOCK(wait_min, "min wait", wait_time_min, 12), 382 DEF_KEY_LOCK(avg_wait, "avg wait", avg_wait_time, 12), 383 384 /* extra comparisons much complicated should be here */ 385 { } 386 }; 387 388 static int select_key(bool contention) 389 { 390 int i; 391 struct lock_key *keys = report_keys; 392 393 if (contention) 394 keys = contention_keys; 395 396 for (i = 0; keys[i].name; i++) { 397 if (!strcmp(keys[i].name, sort_key)) { 398 compare = keys[i].key; 399 400 /* selected key should be in the output fields */ 401 if (list_empty(&keys[i].list)) 402 list_add_tail(&keys[i].list, &lock_keys); 403 404 return 0; 405 } 406 } 407 408 pr_err("Unknown compare key: %s\n", sort_key); 409 return -1; 410 } 411 412 static int add_output_field(bool contention, char *name) 413 { 414 int i; 415 struct lock_key *keys = report_keys; 416 417 if (contention) 418 keys = contention_keys; 419 420 for (i = 0; keys[i].name; i++) { 421 if (strcmp(keys[i].name, name)) 422 continue; 423 424 /* prevent double link */ 425 if (list_empty(&keys[i].list)) 426 list_add_tail(&keys[i].list, &lock_keys); 427 428 return 0; 429 } 430 431 pr_err("Unknown output field: %s\n", name); 432 return -1; 433 } 434 435 static int setup_output_field(bool contention, const char *str) 436 { 437 char *tok, *tmp, *orig; 438 int i, ret = 0; 439 struct lock_key *keys = report_keys; 440 441 if (contention) 442 keys = contention_keys; 443 444 /* no output field given: use all of them */ 445 if (str == NULL) { 446 for (i = 0; keys[i].name; i++) 447 list_add_tail(&keys[i].list, &lock_keys); 448 return 0; 449 } 450 451 for (i = 0; keys[i].name; i++) 452 INIT_LIST_HEAD(&keys[i].list); 453 454 orig = tmp = strdup(str); 455 if (orig == NULL) 456 return -ENOMEM; 457 458 while ((tok = strsep(&tmp, ",")) != NULL){ 459 ret = add_output_field(contention, tok); 460 if (ret < 0) 461 break; 462 } 463 free(orig); 464 465 return ret; 466 } 467 468 static void combine_lock_stats(struct lock_stat *st) 469 { 470 struct rb_node **rb = &sorted.rb_node; 471 struct rb_node *parent = NULL; 472 struct lock_stat *p; 473 int ret; 474 475 while (*rb) { 476 p = container_of(*rb, struct lock_stat, rb); 477 parent = *rb; 478 479 if (st->name && p->name) 480 ret = strcmp(st->name, p->name); 481 else 482 ret = !!st->name - !!p->name; 483 484 if (ret == 0) { 485 p->nr_acquired += st->nr_acquired; 486 p->nr_contended += st->nr_contended; 487 p->wait_time_total += st->wait_time_total; 488 489 if (p->nr_contended) 490 p->avg_wait_time = p->wait_time_total / p->nr_contended; 491 492 if (p->wait_time_min > st->wait_time_min) 493 p->wait_time_min = st->wait_time_min; 494 if (p->wait_time_max < st->wait_time_max) 495 p->wait_time_max = st->wait_time_max; 496 497 p->broken |= st->broken; 498 st->combined = 1; 499 return; 500 } 501 502 if (ret < 0) 503 rb = &(*rb)->rb_left; 504 else 505 rb = &(*rb)->rb_right; 506 } 507 508 rb_link_node(&st->rb, parent, rb); 509 rb_insert_color(&st->rb, &sorted); 510 } 511 512 static void insert_to_result(struct lock_stat *st, 513 int (*bigger)(struct lock_stat *, struct lock_stat *)) 514 { 515 struct rb_node **rb = &result.rb_node; 516 struct rb_node *parent = NULL; 517 struct lock_stat *p; 518 519 if (combine_locks && st->combined) 520 return; 521 522 while (*rb) { 523 p = container_of(*rb, struct lock_stat, rb); 524 parent = *rb; 525 526 if (bigger(st, p)) 527 rb = &(*rb)->rb_left; 528 else 529 rb = &(*rb)->rb_right; 530 } 531 532 rb_link_node(&st->rb, parent, rb); 533 rb_insert_color(&st->rb, &result); 534 } 535 536 /* returns left most element of result, and erase it */ 537 static struct lock_stat *pop_from_result(void) 538 { 539 struct rb_node *node = result.rb_node; 540 541 if (!node) 542 return NULL; 543 544 while (node->rb_left) 545 node = node->rb_left; 546 547 rb_erase(node, &result); 548 return container_of(node, struct lock_stat, rb); 549 } 550 551 static struct lock_stat *lock_stat_find(u64 addr) 552 { 553 struct hlist_head *entry = lockhashentry(addr); 554 struct lock_stat *ret; 555 556 hlist_for_each_entry(ret, entry, hash_entry) { 557 if (ret->addr == addr) 558 return ret; 559 } 560 return NULL; 561 } 562 563 static struct lock_stat *lock_stat_findnew(u64 addr, const char *name, int flags) 564 { 565 struct hlist_head *entry = lockhashentry(addr); 566 struct lock_stat *ret, *new; 567 568 hlist_for_each_entry(ret, entry, hash_entry) { 569 if (ret->addr == addr) 570 return ret; 571 } 572 573 new = zalloc(sizeof(struct lock_stat)); 574 if (!new) 575 goto alloc_failed; 576 577 new->addr = addr; 578 new->name = strdup(name); 579 if (!new->name) { 580 free(new); 581 goto alloc_failed; 582 } 583 584 new->flags = flags; 585 new->wait_time_min = ULLONG_MAX; 586 587 hlist_add_head(&new->hash_entry, entry); 588 return new; 589 590 alloc_failed: 591 pr_err("memory allocation failed\n"); 592 return NULL; 593 } 594 595 struct trace_lock_handler { 596 /* it's used on CONFIG_LOCKDEP */ 597 int (*acquire_event)(struct evsel *evsel, 598 struct perf_sample *sample); 599 600 /* it's used on CONFIG_LOCKDEP && CONFIG_LOCK_STAT */ 601 int (*acquired_event)(struct evsel *evsel, 602 struct perf_sample *sample); 603 604 /* it's used on CONFIG_LOCKDEP && CONFIG_LOCK_STAT */ 605 int (*contended_event)(struct evsel *evsel, 606 struct perf_sample *sample); 607 608 /* it's used on CONFIG_LOCKDEP */ 609 int (*release_event)(struct evsel *evsel, 610 struct perf_sample *sample); 611 612 /* it's used when CONFIG_LOCKDEP is off */ 613 int (*contention_begin_event)(struct evsel *evsel, 614 struct perf_sample *sample); 615 616 /* it's used when CONFIG_LOCKDEP is off */ 617 int (*contention_end_event)(struct evsel *evsel, 618 struct perf_sample *sample); 619 }; 620 621 static struct lock_seq_stat *get_seq(struct thread_stat *ts, u64 addr) 622 { 623 struct lock_seq_stat *seq; 624 625 list_for_each_entry(seq, &ts->seq_list, list) { 626 if (seq->addr == addr) 627 return seq; 628 } 629 630 seq = zalloc(sizeof(struct lock_seq_stat)); 631 if (!seq) { 632 pr_err("memory allocation failed\n"); 633 return NULL; 634 } 635 seq->state = SEQ_STATE_UNINITIALIZED; 636 seq->addr = addr; 637 638 list_add(&seq->list, &ts->seq_list); 639 return seq; 640 } 641 642 enum broken_state { 643 BROKEN_ACQUIRE, 644 BROKEN_ACQUIRED, 645 BROKEN_CONTENDED, 646 BROKEN_RELEASE, 647 BROKEN_MAX, 648 }; 649 650 static int bad_hist[BROKEN_MAX]; 651 652 enum acquire_flags { 653 TRY_LOCK = 1, 654 READ_LOCK = 2, 655 }; 656 657 static int report_lock_acquire_event(struct evsel *evsel, 658 struct perf_sample *sample) 659 { 660 struct lock_stat *ls; 661 struct thread_stat *ts; 662 struct lock_seq_stat *seq; 663 const char *name = evsel__strval(evsel, sample, "name"); 664 u64 addr = evsel__intval(evsel, sample, "lockdep_addr"); 665 int flag = evsel__intval(evsel, sample, "flags"); 666 u64 key; 667 668 switch (aggr_mode) { 669 case LOCK_AGGR_ADDR: 670 key = addr; 671 break; 672 case LOCK_AGGR_TASK: 673 key = sample->tid; 674 break; 675 case LOCK_AGGR_CALLER: 676 default: 677 pr_err("Invalid aggregation mode: %d\n", aggr_mode); 678 return -EINVAL; 679 } 680 681 ls = lock_stat_findnew(key, name, 0); 682 if (!ls) 683 return -ENOMEM; 684 685 ts = thread_stat_findnew(sample->tid); 686 if (!ts) 687 return -ENOMEM; 688 689 seq = get_seq(ts, addr); 690 if (!seq) 691 return -ENOMEM; 692 693 switch (seq->state) { 694 case SEQ_STATE_UNINITIALIZED: 695 case SEQ_STATE_RELEASED: 696 if (!flag) { 697 seq->state = SEQ_STATE_ACQUIRING; 698 } else { 699 if (flag & TRY_LOCK) 700 ls->nr_trylock++; 701 if (flag & READ_LOCK) 702 ls->nr_readlock++; 703 seq->state = SEQ_STATE_READ_ACQUIRED; 704 seq->read_count = 1; 705 ls->nr_acquired++; 706 } 707 break; 708 case SEQ_STATE_READ_ACQUIRED: 709 if (flag & READ_LOCK) { 710 seq->read_count++; 711 ls->nr_acquired++; 712 goto end; 713 } else { 714 goto broken; 715 } 716 break; 717 case SEQ_STATE_ACQUIRED: 718 case SEQ_STATE_ACQUIRING: 719 case SEQ_STATE_CONTENDED: 720 broken: 721 /* broken lock sequence */ 722 if (!ls->broken) { 723 ls->broken = 1; 724 bad_hist[BROKEN_ACQUIRE]++; 725 } 726 list_del_init(&seq->list); 727 free(seq); 728 goto end; 729 default: 730 BUG_ON("Unknown state of lock sequence found!\n"); 731 break; 732 } 733 734 ls->nr_acquire++; 735 seq->prev_event_time = sample->time; 736 end: 737 return 0; 738 } 739 740 static int report_lock_acquired_event(struct evsel *evsel, 741 struct perf_sample *sample) 742 { 743 struct lock_stat *ls; 744 struct thread_stat *ts; 745 struct lock_seq_stat *seq; 746 u64 contended_term; 747 const char *name = evsel__strval(evsel, sample, "name"); 748 u64 addr = evsel__intval(evsel, sample, "lockdep_addr"); 749 u64 key; 750 751 switch (aggr_mode) { 752 case LOCK_AGGR_ADDR: 753 key = addr; 754 break; 755 case LOCK_AGGR_TASK: 756 key = sample->tid; 757 break; 758 case LOCK_AGGR_CALLER: 759 default: 760 pr_err("Invalid aggregation mode: %d\n", aggr_mode); 761 return -EINVAL; 762 } 763 764 ls = lock_stat_findnew(key, name, 0); 765 if (!ls) 766 return -ENOMEM; 767 768 ts = thread_stat_findnew(sample->tid); 769 if (!ts) 770 return -ENOMEM; 771 772 seq = get_seq(ts, addr); 773 if (!seq) 774 return -ENOMEM; 775 776 switch (seq->state) { 777 case SEQ_STATE_UNINITIALIZED: 778 /* orphan event, do nothing */ 779 return 0; 780 case SEQ_STATE_ACQUIRING: 781 break; 782 case SEQ_STATE_CONTENDED: 783 contended_term = sample->time - seq->prev_event_time; 784 ls->wait_time_total += contended_term; 785 if (contended_term < ls->wait_time_min) 786 ls->wait_time_min = contended_term; 787 if (ls->wait_time_max < contended_term) 788 ls->wait_time_max = contended_term; 789 break; 790 case SEQ_STATE_RELEASED: 791 case SEQ_STATE_ACQUIRED: 792 case SEQ_STATE_READ_ACQUIRED: 793 /* broken lock sequence */ 794 if (!ls->broken) { 795 ls->broken = 1; 796 bad_hist[BROKEN_ACQUIRED]++; 797 } 798 list_del_init(&seq->list); 799 free(seq); 800 goto end; 801 default: 802 BUG_ON("Unknown state of lock sequence found!\n"); 803 break; 804 } 805 806 seq->state = SEQ_STATE_ACQUIRED; 807 ls->nr_acquired++; 808 ls->avg_wait_time = ls->nr_contended ? ls->wait_time_total/ls->nr_contended : 0; 809 seq->prev_event_time = sample->time; 810 end: 811 return 0; 812 } 813 814 static int report_lock_contended_event(struct evsel *evsel, 815 struct perf_sample *sample) 816 { 817 struct lock_stat *ls; 818 struct thread_stat *ts; 819 struct lock_seq_stat *seq; 820 const char *name = evsel__strval(evsel, sample, "name"); 821 u64 addr = evsel__intval(evsel, sample, "lockdep_addr"); 822 u64 key; 823 824 switch (aggr_mode) { 825 case LOCK_AGGR_ADDR: 826 key = addr; 827 break; 828 case LOCK_AGGR_TASK: 829 key = sample->tid; 830 break; 831 case LOCK_AGGR_CALLER: 832 default: 833 pr_err("Invalid aggregation mode: %d\n", aggr_mode); 834 return -EINVAL; 835 } 836 837 ls = lock_stat_findnew(key, name, 0); 838 if (!ls) 839 return -ENOMEM; 840 841 ts = thread_stat_findnew(sample->tid); 842 if (!ts) 843 return -ENOMEM; 844 845 seq = get_seq(ts, addr); 846 if (!seq) 847 return -ENOMEM; 848 849 switch (seq->state) { 850 case SEQ_STATE_UNINITIALIZED: 851 /* orphan event, do nothing */ 852 return 0; 853 case SEQ_STATE_ACQUIRING: 854 break; 855 case SEQ_STATE_RELEASED: 856 case SEQ_STATE_ACQUIRED: 857 case SEQ_STATE_READ_ACQUIRED: 858 case SEQ_STATE_CONTENDED: 859 /* broken lock sequence */ 860 if (!ls->broken) { 861 ls->broken = 1; 862 bad_hist[BROKEN_CONTENDED]++; 863 } 864 list_del_init(&seq->list); 865 free(seq); 866 goto end; 867 default: 868 BUG_ON("Unknown state of lock sequence found!\n"); 869 break; 870 } 871 872 seq->state = SEQ_STATE_CONTENDED; 873 ls->nr_contended++; 874 ls->avg_wait_time = ls->wait_time_total/ls->nr_contended; 875 seq->prev_event_time = sample->time; 876 end: 877 return 0; 878 } 879 880 static int report_lock_release_event(struct evsel *evsel, 881 struct perf_sample *sample) 882 { 883 struct lock_stat *ls; 884 struct thread_stat *ts; 885 struct lock_seq_stat *seq; 886 const char *name = evsel__strval(evsel, sample, "name"); 887 u64 addr = evsel__intval(evsel, sample, "lockdep_addr"); 888 u64 key; 889 890 switch (aggr_mode) { 891 case LOCK_AGGR_ADDR: 892 key = addr; 893 break; 894 case LOCK_AGGR_TASK: 895 key = sample->tid; 896 break; 897 case LOCK_AGGR_CALLER: 898 default: 899 pr_err("Invalid aggregation mode: %d\n", aggr_mode); 900 return -EINVAL; 901 } 902 903 ls = lock_stat_findnew(key, name, 0); 904 if (!ls) 905 return -ENOMEM; 906 907 ts = thread_stat_findnew(sample->tid); 908 if (!ts) 909 return -ENOMEM; 910 911 seq = get_seq(ts, addr); 912 if (!seq) 913 return -ENOMEM; 914 915 switch (seq->state) { 916 case SEQ_STATE_UNINITIALIZED: 917 goto end; 918 case SEQ_STATE_ACQUIRED: 919 break; 920 case SEQ_STATE_READ_ACQUIRED: 921 seq->read_count--; 922 BUG_ON(seq->read_count < 0); 923 if (seq->read_count) { 924 ls->nr_release++; 925 goto end; 926 } 927 break; 928 case SEQ_STATE_ACQUIRING: 929 case SEQ_STATE_CONTENDED: 930 case SEQ_STATE_RELEASED: 931 /* broken lock sequence */ 932 if (!ls->broken) { 933 ls->broken = 1; 934 bad_hist[BROKEN_RELEASE]++; 935 } 936 goto free_seq; 937 default: 938 BUG_ON("Unknown state of lock sequence found!\n"); 939 break; 940 } 941 942 ls->nr_release++; 943 free_seq: 944 list_del_init(&seq->list); 945 free(seq); 946 end: 947 return 0; 948 } 949 950 static bool is_lock_function(u64 addr) 951 { 952 if (!sched_text_start) { 953 struct machine *machine = &session->machines.host; 954 struct map *kmap; 955 struct symbol *sym; 956 957 sym = machine__find_kernel_symbol_by_name(machine, 958 "__sched_text_start", 959 &kmap); 960 if (!sym) { 961 /* to avoid retry */ 962 sched_text_start = 1; 963 return false; 964 } 965 966 sched_text_start = kmap->unmap_ip(kmap, sym->start); 967 968 /* should not fail from here */ 969 sym = machine__find_kernel_symbol_by_name(machine, 970 "__sched_text_end", 971 &kmap); 972 sched_text_end = kmap->unmap_ip(kmap, sym->start); 973 974 sym = machine__find_kernel_symbol_by_name(machine, 975 "__lock_text_start", 976 &kmap); 977 lock_text_start = kmap->unmap_ip(kmap, sym->start); 978 979 sym = machine__find_kernel_symbol_by_name(machine, 980 "__lock_text_end", 981 &kmap); 982 lock_text_end = kmap->unmap_ip(kmap, sym->start); 983 } 984 985 /* failed to get kernel symbols */ 986 if (sched_text_start == 1) 987 return false; 988 989 /* mutex and rwsem functions are in sched text section */ 990 if (sched_text_start <= addr && addr < sched_text_end) 991 return true; 992 993 /* spinlock functions are in lock text section */ 994 if (lock_text_start <= addr && addr < lock_text_end) 995 return true; 996 997 return false; 998 } 999 1000 static int lock_contention_caller(struct evsel *evsel, struct perf_sample *sample, 1001 char *buf, int size) 1002 { 1003 struct thread *thread; 1004 struct callchain_cursor *cursor = &callchain_cursor; 1005 struct symbol *sym; 1006 int skip = 0; 1007 int ret; 1008 1009 /* lock names will be replaced to task name later */ 1010 if (show_thread_stats) 1011 return -1; 1012 1013 thread = machine__findnew_thread(&session->machines.host, 1014 -1, sample->pid); 1015 if (thread == NULL) 1016 return -1; 1017 1018 /* use caller function name from the callchain */ 1019 ret = thread__resolve_callchain(thread, cursor, evsel, sample, 1020 NULL, NULL, CONTENTION_STACK_DEPTH); 1021 if (ret != 0) { 1022 thread__put(thread); 1023 return -1; 1024 } 1025 1026 callchain_cursor_commit(cursor); 1027 thread__put(thread); 1028 1029 while (true) { 1030 struct callchain_cursor_node *node; 1031 1032 node = callchain_cursor_current(cursor); 1033 if (node == NULL) 1034 break; 1035 1036 /* skip first few entries - for lock functions */ 1037 if (++skip <= CONTENTION_STACK_SKIP) 1038 goto next; 1039 1040 sym = node->ms.sym; 1041 if (sym && !is_lock_function(node->ip)) { 1042 struct map *map = node->ms.map; 1043 u64 offset; 1044 1045 offset = map->map_ip(map, node->ip) - sym->start; 1046 1047 if (offset) 1048 scnprintf(buf, size, "%s+%#lx", sym->name, offset); 1049 else 1050 strlcpy(buf, sym->name, size); 1051 return 0; 1052 } 1053 1054 next: 1055 callchain_cursor_advance(cursor); 1056 } 1057 return -1; 1058 } 1059 1060 static u64 callchain_id(struct evsel *evsel, struct perf_sample *sample) 1061 { 1062 struct callchain_cursor *cursor = &callchain_cursor; 1063 struct thread *thread; 1064 u64 hash = 0; 1065 int skip = 0; 1066 int ret; 1067 1068 thread = machine__findnew_thread(&session->machines.host, 1069 -1, sample->pid); 1070 if (thread == NULL) 1071 return -1; 1072 1073 /* use caller function name from the callchain */ 1074 ret = thread__resolve_callchain(thread, cursor, evsel, sample, 1075 NULL, NULL, CONTENTION_STACK_DEPTH); 1076 thread__put(thread); 1077 1078 if (ret != 0) 1079 return -1; 1080 1081 callchain_cursor_commit(cursor); 1082 1083 while (true) { 1084 struct callchain_cursor_node *node; 1085 1086 node = callchain_cursor_current(cursor); 1087 if (node == NULL) 1088 break; 1089 1090 /* skip first few entries - for lock functions */ 1091 if (++skip <= CONTENTION_STACK_SKIP) 1092 goto next; 1093 1094 if (node->ms.sym && is_lock_function(node->ip)) 1095 goto next; 1096 1097 hash ^= hash_long((unsigned long)node->ip, 64); 1098 1099 next: 1100 callchain_cursor_advance(cursor); 1101 } 1102 return hash; 1103 } 1104 1105 static int report_lock_contention_begin_event(struct evsel *evsel, 1106 struct perf_sample *sample) 1107 { 1108 struct lock_stat *ls; 1109 struct thread_stat *ts; 1110 struct lock_seq_stat *seq; 1111 u64 addr = evsel__intval(evsel, sample, "lock_addr"); 1112 u64 key; 1113 1114 switch (aggr_mode) { 1115 case LOCK_AGGR_ADDR: 1116 key = addr; 1117 break; 1118 case LOCK_AGGR_TASK: 1119 key = sample->tid; 1120 break; 1121 case LOCK_AGGR_CALLER: 1122 key = callchain_id(evsel, sample); 1123 break; 1124 default: 1125 pr_err("Invalid aggregation mode: %d\n", aggr_mode); 1126 return -EINVAL; 1127 } 1128 1129 ls = lock_stat_find(key); 1130 if (!ls) { 1131 char buf[128]; 1132 const char *caller = buf; 1133 unsigned int flags = evsel__intval(evsel, sample, "flags"); 1134 1135 if (lock_contention_caller(evsel, sample, buf, sizeof(buf)) < 0) 1136 caller = "Unknown"; 1137 1138 ls = lock_stat_findnew(key, caller, flags); 1139 if (!ls) 1140 return -ENOMEM; 1141 } 1142 1143 ts = thread_stat_findnew(sample->tid); 1144 if (!ts) 1145 return -ENOMEM; 1146 1147 seq = get_seq(ts, addr); 1148 if (!seq) 1149 return -ENOMEM; 1150 1151 switch (seq->state) { 1152 case SEQ_STATE_UNINITIALIZED: 1153 case SEQ_STATE_ACQUIRED: 1154 break; 1155 case SEQ_STATE_CONTENDED: 1156 /* 1157 * It can have nested contention begin with mutex spinning, 1158 * then we would use the original contention begin event and 1159 * ignore the second one. 1160 */ 1161 goto end; 1162 case SEQ_STATE_ACQUIRING: 1163 case SEQ_STATE_READ_ACQUIRED: 1164 case SEQ_STATE_RELEASED: 1165 /* broken lock sequence */ 1166 if (!ls->broken) { 1167 ls->broken = 1; 1168 bad_hist[BROKEN_CONTENDED]++; 1169 } 1170 list_del_init(&seq->list); 1171 free(seq); 1172 goto end; 1173 default: 1174 BUG_ON("Unknown state of lock sequence found!\n"); 1175 break; 1176 } 1177 1178 if (seq->state != SEQ_STATE_CONTENDED) { 1179 seq->state = SEQ_STATE_CONTENDED; 1180 seq->prev_event_time = sample->time; 1181 ls->nr_contended++; 1182 } 1183 end: 1184 return 0; 1185 } 1186 1187 static int report_lock_contention_end_event(struct evsel *evsel, 1188 struct perf_sample *sample) 1189 { 1190 struct lock_stat *ls; 1191 struct thread_stat *ts; 1192 struct lock_seq_stat *seq; 1193 u64 contended_term; 1194 u64 addr = evsel__intval(evsel, sample, "lock_addr"); 1195 u64 key; 1196 1197 switch (aggr_mode) { 1198 case LOCK_AGGR_ADDR: 1199 key = addr; 1200 break; 1201 case LOCK_AGGR_TASK: 1202 key = sample->tid; 1203 break; 1204 case LOCK_AGGR_CALLER: 1205 key = callchain_id(evsel, sample); 1206 break; 1207 default: 1208 pr_err("Invalid aggregation mode: %d\n", aggr_mode); 1209 return -EINVAL; 1210 } 1211 1212 ls = lock_stat_find(key); 1213 if (!ls) 1214 return 0; 1215 1216 ts = thread_stat_find(sample->tid); 1217 if (!ts) 1218 return 0; 1219 1220 seq = get_seq(ts, addr); 1221 if (!seq) 1222 return -ENOMEM; 1223 1224 switch (seq->state) { 1225 case SEQ_STATE_UNINITIALIZED: 1226 goto end; 1227 case SEQ_STATE_CONTENDED: 1228 contended_term = sample->time - seq->prev_event_time; 1229 ls->wait_time_total += contended_term; 1230 if (contended_term < ls->wait_time_min) 1231 ls->wait_time_min = contended_term; 1232 if (ls->wait_time_max < contended_term) 1233 ls->wait_time_max = contended_term; 1234 break; 1235 case SEQ_STATE_ACQUIRING: 1236 case SEQ_STATE_ACQUIRED: 1237 case SEQ_STATE_READ_ACQUIRED: 1238 case SEQ_STATE_RELEASED: 1239 /* broken lock sequence */ 1240 if (!ls->broken) { 1241 ls->broken = 1; 1242 bad_hist[BROKEN_ACQUIRED]++; 1243 } 1244 list_del_init(&seq->list); 1245 free(seq); 1246 goto end; 1247 default: 1248 BUG_ON("Unknown state of lock sequence found!\n"); 1249 break; 1250 } 1251 1252 seq->state = SEQ_STATE_ACQUIRED; 1253 ls->nr_acquired++; 1254 ls->avg_wait_time = ls->wait_time_total/ls->nr_acquired; 1255 end: 1256 return 0; 1257 } 1258 1259 /* lock oriented handlers */ 1260 /* TODO: handlers for CPU oriented, thread oriented */ 1261 static struct trace_lock_handler report_lock_ops = { 1262 .acquire_event = report_lock_acquire_event, 1263 .acquired_event = report_lock_acquired_event, 1264 .contended_event = report_lock_contended_event, 1265 .release_event = report_lock_release_event, 1266 .contention_begin_event = report_lock_contention_begin_event, 1267 .contention_end_event = report_lock_contention_end_event, 1268 }; 1269 1270 static struct trace_lock_handler contention_lock_ops = { 1271 .contention_begin_event = report_lock_contention_begin_event, 1272 .contention_end_event = report_lock_contention_end_event, 1273 }; 1274 1275 1276 static struct trace_lock_handler *trace_handler; 1277 1278 static int evsel__process_lock_acquire(struct evsel *evsel, struct perf_sample *sample) 1279 { 1280 if (trace_handler->acquire_event) 1281 return trace_handler->acquire_event(evsel, sample); 1282 return 0; 1283 } 1284 1285 static int evsel__process_lock_acquired(struct evsel *evsel, struct perf_sample *sample) 1286 { 1287 if (trace_handler->acquired_event) 1288 return trace_handler->acquired_event(evsel, sample); 1289 return 0; 1290 } 1291 1292 static int evsel__process_lock_contended(struct evsel *evsel, struct perf_sample *sample) 1293 { 1294 if (trace_handler->contended_event) 1295 return trace_handler->contended_event(evsel, sample); 1296 return 0; 1297 } 1298 1299 static int evsel__process_lock_release(struct evsel *evsel, struct perf_sample *sample) 1300 { 1301 if (trace_handler->release_event) 1302 return trace_handler->release_event(evsel, sample); 1303 return 0; 1304 } 1305 1306 static int evsel__process_contention_begin(struct evsel *evsel, struct perf_sample *sample) 1307 { 1308 if (trace_handler->contention_begin_event) 1309 return trace_handler->contention_begin_event(evsel, sample); 1310 return 0; 1311 } 1312 1313 static int evsel__process_contention_end(struct evsel *evsel, struct perf_sample *sample) 1314 { 1315 if (trace_handler->contention_end_event) 1316 return trace_handler->contention_end_event(evsel, sample); 1317 return 0; 1318 } 1319 1320 static void print_bad_events(int bad, int total) 1321 { 1322 /* Output for debug, this have to be removed */ 1323 int i; 1324 int broken = 0; 1325 const char *name[4] = 1326 { "acquire", "acquired", "contended", "release" }; 1327 1328 for (i = 0; i < BROKEN_MAX; i++) 1329 broken += bad_hist[i]; 1330 1331 if (broken == 0 && !verbose) 1332 return; 1333 1334 pr_info("\n=== output for debug===\n\n"); 1335 pr_info("bad: %d, total: %d\n", bad, total); 1336 pr_info("bad rate: %.2f %%\n", (double)bad / (double)total * 100); 1337 pr_info("histogram of events caused bad sequence\n"); 1338 for (i = 0; i < BROKEN_MAX; i++) 1339 pr_info(" %10s: %d\n", name[i], bad_hist[i]); 1340 } 1341 1342 /* TODO: various way to print, coloring, nano or milli sec */ 1343 static void print_result(void) 1344 { 1345 struct lock_stat *st; 1346 struct lock_key *key; 1347 char cut_name[20]; 1348 int bad, total; 1349 1350 pr_info("%20s ", "Name"); 1351 list_for_each_entry(key, &lock_keys, list) 1352 pr_info("%*s ", key->len, key->header); 1353 pr_info("\n\n"); 1354 1355 bad = total = 0; 1356 while ((st = pop_from_result())) { 1357 total++; 1358 if (st->broken) 1359 bad++; 1360 if (!st->nr_acquired) 1361 continue; 1362 1363 bzero(cut_name, 20); 1364 1365 if (strlen(st->name) < 20) { 1366 /* output raw name */ 1367 const char *name = st->name; 1368 1369 if (show_thread_stats) { 1370 struct thread *t; 1371 1372 /* st->addr contains tid of thread */ 1373 t = perf_session__findnew(session, st->addr); 1374 name = thread__comm_str(t); 1375 } 1376 1377 pr_info("%20s ", name); 1378 } else { 1379 strncpy(cut_name, st->name, 16); 1380 cut_name[16] = '.'; 1381 cut_name[17] = '.'; 1382 cut_name[18] = '.'; 1383 cut_name[19] = '\0'; 1384 /* cut off name for saving output style */ 1385 pr_info("%20s ", cut_name); 1386 } 1387 1388 list_for_each_entry(key, &lock_keys, list) { 1389 key->print(key, st); 1390 pr_info(" "); 1391 } 1392 pr_info("\n"); 1393 } 1394 1395 print_bad_events(bad, total); 1396 } 1397 1398 static bool info_threads, info_map; 1399 1400 static void dump_threads(void) 1401 { 1402 struct thread_stat *st; 1403 struct rb_node *node; 1404 struct thread *t; 1405 1406 pr_info("%10s: comm\n", "Thread ID"); 1407 1408 node = rb_first(&thread_stats); 1409 while (node) { 1410 st = container_of(node, struct thread_stat, rb); 1411 t = perf_session__findnew(session, st->tid); 1412 pr_info("%10d: %s\n", st->tid, thread__comm_str(t)); 1413 node = rb_next(node); 1414 thread__put(t); 1415 } 1416 } 1417 1418 static int compare_maps(struct lock_stat *a, struct lock_stat *b) 1419 { 1420 int ret; 1421 1422 if (a->name && b->name) 1423 ret = strcmp(a->name, b->name); 1424 else 1425 ret = !!a->name - !!b->name; 1426 1427 if (!ret) 1428 return a->addr < b->addr; 1429 else 1430 return ret < 0; 1431 } 1432 1433 static void dump_map(void) 1434 { 1435 unsigned int i; 1436 struct lock_stat *st; 1437 1438 pr_info("Address of instance: name of class\n"); 1439 for (i = 0; i < LOCKHASH_SIZE; i++) { 1440 hlist_for_each_entry(st, &lockhash_table[i], hash_entry) { 1441 insert_to_result(st, compare_maps); 1442 } 1443 } 1444 1445 while ((st = pop_from_result())) 1446 pr_info(" %#llx: %s\n", (unsigned long long)st->addr, st->name); 1447 } 1448 1449 static int dump_info(void) 1450 { 1451 int rc = 0; 1452 1453 if (info_threads) 1454 dump_threads(); 1455 else if (info_map) 1456 dump_map(); 1457 else { 1458 rc = -1; 1459 pr_err("Unknown type of information\n"); 1460 } 1461 1462 return rc; 1463 } 1464 1465 typedef int (*tracepoint_handler)(struct evsel *evsel, 1466 struct perf_sample *sample); 1467 1468 static int process_sample_event(struct perf_tool *tool __maybe_unused, 1469 union perf_event *event, 1470 struct perf_sample *sample, 1471 struct evsel *evsel, 1472 struct machine *machine) 1473 { 1474 int err = 0; 1475 struct thread *thread = machine__findnew_thread(machine, sample->pid, 1476 sample->tid); 1477 1478 if (thread == NULL) { 1479 pr_debug("problem processing %d event, skipping it.\n", 1480 event->header.type); 1481 return -1; 1482 } 1483 1484 if (evsel->handler != NULL) { 1485 tracepoint_handler f = evsel->handler; 1486 err = f(evsel, sample); 1487 } 1488 1489 thread__put(thread); 1490 1491 return err; 1492 } 1493 1494 static void combine_result(void) 1495 { 1496 unsigned int i; 1497 struct lock_stat *st; 1498 1499 if (!combine_locks) 1500 return; 1501 1502 for (i = 0; i < LOCKHASH_SIZE; i++) { 1503 hlist_for_each_entry(st, &lockhash_table[i], hash_entry) { 1504 combine_lock_stats(st); 1505 } 1506 } 1507 } 1508 1509 static void sort_result(void) 1510 { 1511 unsigned int i; 1512 struct lock_stat *st; 1513 1514 for (i = 0; i < LOCKHASH_SIZE; i++) { 1515 hlist_for_each_entry(st, &lockhash_table[i], hash_entry) { 1516 insert_to_result(st, compare); 1517 } 1518 } 1519 } 1520 1521 static const char *get_type_str(struct lock_stat *st) 1522 { 1523 static const struct { 1524 unsigned int flags; 1525 const char *name; 1526 } table[] = { 1527 { 0, "semaphore" }, 1528 { LCB_F_SPIN, "spinlock" }, 1529 { LCB_F_SPIN | LCB_F_READ, "rwlock:R" }, 1530 { LCB_F_SPIN | LCB_F_WRITE, "rwlock:W"}, 1531 { LCB_F_READ, "rwsem:R" }, 1532 { LCB_F_WRITE, "rwsem:W" }, 1533 { LCB_F_RT, "rtmutex" }, 1534 { LCB_F_RT | LCB_F_READ, "rwlock-rt:R" }, 1535 { LCB_F_RT | LCB_F_WRITE, "rwlock-rt:W"}, 1536 { LCB_F_PERCPU | LCB_F_READ, "pcpu-sem:R" }, 1537 { LCB_F_PERCPU | LCB_F_WRITE, "pcpu-sem:W" }, 1538 { LCB_F_MUTEX, "mutex" }, 1539 { LCB_F_MUTEX | LCB_F_SPIN, "mutex" }, 1540 }; 1541 1542 for (unsigned int i = 0; i < ARRAY_SIZE(table); i++) { 1543 if (table[i].flags == st->flags) 1544 return table[i].name; 1545 } 1546 return "unknown"; 1547 } 1548 1549 static void sort_contention_result(void) 1550 { 1551 sort_result(); 1552 } 1553 1554 static void print_contention_result(void) 1555 { 1556 struct lock_stat *st; 1557 struct lock_key *key; 1558 int bad, total; 1559 1560 list_for_each_entry(key, &lock_keys, list) 1561 pr_info("%*s ", key->len, key->header); 1562 1563 if (show_thread_stats) 1564 pr_info(" %10s %s\n\n", "pid", "comm"); 1565 else 1566 pr_info(" %10s %s\n\n", "type", "caller"); 1567 1568 bad = total = 0; 1569 while ((st = pop_from_result())) { 1570 total++; 1571 if (st->broken) 1572 bad++; 1573 1574 list_for_each_entry(key, &lock_keys, list) { 1575 key->print(key, st); 1576 pr_info(" "); 1577 } 1578 1579 if (show_thread_stats) { 1580 struct thread *t; 1581 int pid = st->addr; 1582 1583 /* st->addr contains tid of thread */ 1584 t = perf_session__findnew(session, pid); 1585 pr_info(" %10d %s\n", pid, thread__comm_str(t)); 1586 continue; 1587 } 1588 1589 pr_info(" %10s %s\n", get_type_str(st), st->name); 1590 } 1591 1592 print_bad_events(bad, total); 1593 } 1594 1595 static const struct evsel_str_handler lock_tracepoints[] = { 1596 { "lock:lock_acquire", evsel__process_lock_acquire, }, /* CONFIG_LOCKDEP */ 1597 { "lock:lock_acquired", evsel__process_lock_acquired, }, /* CONFIG_LOCKDEP, CONFIG_LOCK_STAT */ 1598 { "lock:lock_contended", evsel__process_lock_contended, }, /* CONFIG_LOCKDEP, CONFIG_LOCK_STAT */ 1599 { "lock:lock_release", evsel__process_lock_release, }, /* CONFIG_LOCKDEP */ 1600 }; 1601 1602 static const struct evsel_str_handler contention_tracepoints[] = { 1603 { "lock:contention_begin", evsel__process_contention_begin, }, 1604 { "lock:contention_end", evsel__process_contention_end, }, 1605 }; 1606 1607 static bool force; 1608 1609 static int __cmd_report(bool display_info) 1610 { 1611 int err = -EINVAL; 1612 struct perf_tool eops = { 1613 .sample = process_sample_event, 1614 .comm = perf_event__process_comm, 1615 .mmap = perf_event__process_mmap, 1616 .namespaces = perf_event__process_namespaces, 1617 .ordered_events = true, 1618 }; 1619 struct perf_data data = { 1620 .path = input_name, 1621 .mode = PERF_DATA_MODE_READ, 1622 .force = force, 1623 }; 1624 1625 session = perf_session__new(&data, &eops); 1626 if (IS_ERR(session)) { 1627 pr_err("Initializing perf session failed\n"); 1628 return PTR_ERR(session); 1629 } 1630 1631 /* for lock function check */ 1632 symbol_conf.sort_by_name = true; 1633 symbol__init(&session->header.env); 1634 1635 if (!perf_session__has_traces(session, "lock record")) 1636 goto out_delete; 1637 1638 if (perf_session__set_tracepoints_handlers(session, lock_tracepoints)) { 1639 pr_err("Initializing perf session tracepoint handlers failed\n"); 1640 goto out_delete; 1641 } 1642 1643 if (perf_session__set_tracepoints_handlers(session, contention_tracepoints)) { 1644 pr_err("Initializing perf session tracepoint handlers failed\n"); 1645 goto out_delete; 1646 } 1647 1648 if (setup_output_field(false, output_fields)) 1649 goto out_delete; 1650 1651 if (select_key(false)) 1652 goto out_delete; 1653 1654 if (show_thread_stats) 1655 aggr_mode = LOCK_AGGR_TASK; 1656 1657 err = perf_session__process_events(session); 1658 if (err) 1659 goto out_delete; 1660 1661 setup_pager(); 1662 if (display_info) /* used for info subcommand */ 1663 err = dump_info(); 1664 else { 1665 combine_result(); 1666 sort_result(); 1667 print_result(); 1668 } 1669 1670 out_delete: 1671 perf_session__delete(session); 1672 return err; 1673 } 1674 1675 static int __cmd_contention(void) 1676 { 1677 int err = -EINVAL; 1678 struct perf_tool eops = { 1679 .sample = process_sample_event, 1680 .comm = perf_event__process_comm, 1681 .mmap = perf_event__process_mmap, 1682 .ordered_events = true, 1683 }; 1684 struct perf_data data = { 1685 .path = input_name, 1686 .mode = PERF_DATA_MODE_READ, 1687 .force = force, 1688 }; 1689 1690 session = perf_session__new(&data, &eops); 1691 if (IS_ERR(session)) { 1692 pr_err("Initializing perf session failed\n"); 1693 return PTR_ERR(session); 1694 } 1695 1696 /* for lock function check */ 1697 symbol_conf.sort_by_name = true; 1698 symbol__init(&session->header.env); 1699 1700 if (!perf_session__has_traces(session, "lock record")) 1701 goto out_delete; 1702 1703 if (!evlist__find_evsel_by_str(session->evlist, "lock:contention_begin")) { 1704 pr_err("lock contention evsel not found\n"); 1705 goto out_delete; 1706 } 1707 1708 if (perf_session__set_tracepoints_handlers(session, contention_tracepoints)) { 1709 pr_err("Initializing perf session tracepoint handlers failed\n"); 1710 goto out_delete; 1711 } 1712 1713 if (setup_output_field(true, output_fields)) 1714 goto out_delete; 1715 1716 if (select_key(true)) 1717 goto out_delete; 1718 1719 if (show_thread_stats) 1720 aggr_mode = LOCK_AGGR_TASK; 1721 else 1722 aggr_mode = LOCK_AGGR_CALLER; 1723 1724 err = perf_session__process_events(session); 1725 if (err) 1726 goto out_delete; 1727 1728 setup_pager(); 1729 1730 sort_contention_result(); 1731 print_contention_result(); 1732 1733 out_delete: 1734 perf_session__delete(session); 1735 return err; 1736 } 1737 1738 1739 static int __cmd_record(int argc, const char **argv) 1740 { 1741 const char *record_args[] = { 1742 "record", "-R", "-m", "1024", "-c", "1", "--synth", "task", 1743 }; 1744 const char *callgraph_args[] = { 1745 "--call-graph", "fp," __stringify(CONTENTION_STACK_DEPTH), 1746 }; 1747 unsigned int rec_argc, i, j, ret; 1748 unsigned int nr_tracepoints; 1749 unsigned int nr_callgraph_args = 0; 1750 const char **rec_argv; 1751 bool has_lock_stat = true; 1752 1753 for (i = 0; i < ARRAY_SIZE(lock_tracepoints); i++) { 1754 if (!is_valid_tracepoint(lock_tracepoints[i].name)) { 1755 pr_debug("tracepoint %s is not enabled. " 1756 "Are CONFIG_LOCKDEP and CONFIG_LOCK_STAT enabled?\n", 1757 lock_tracepoints[i].name); 1758 has_lock_stat = false; 1759 break; 1760 } 1761 } 1762 1763 if (has_lock_stat) 1764 goto setup_args; 1765 1766 for (i = 0; i < ARRAY_SIZE(contention_tracepoints); i++) { 1767 if (!is_valid_tracepoint(contention_tracepoints[i].name)) { 1768 pr_err("tracepoint %s is not enabled.\n", 1769 contention_tracepoints[i].name); 1770 return 1; 1771 } 1772 } 1773 1774 nr_callgraph_args = ARRAY_SIZE(callgraph_args); 1775 1776 setup_args: 1777 rec_argc = ARRAY_SIZE(record_args) + nr_callgraph_args + argc - 1; 1778 1779 if (has_lock_stat) 1780 nr_tracepoints = ARRAY_SIZE(lock_tracepoints); 1781 else 1782 nr_tracepoints = ARRAY_SIZE(contention_tracepoints); 1783 1784 /* factor of 2 is for -e in front of each tracepoint */ 1785 rec_argc += 2 * nr_tracepoints; 1786 1787 rec_argv = calloc(rec_argc + 1, sizeof(char *)); 1788 if (!rec_argv) 1789 return -ENOMEM; 1790 1791 for (i = 0; i < ARRAY_SIZE(record_args); i++) 1792 rec_argv[i] = strdup(record_args[i]); 1793 1794 for (j = 0; j < nr_tracepoints; j++) { 1795 const char *ev_name; 1796 1797 if (has_lock_stat) 1798 ev_name = strdup(lock_tracepoints[j].name); 1799 else 1800 ev_name = strdup(contention_tracepoints[j].name); 1801 1802 if (!ev_name) 1803 return -ENOMEM; 1804 1805 rec_argv[i++] = "-e"; 1806 rec_argv[i++] = ev_name; 1807 } 1808 1809 for (j = 0; j < nr_callgraph_args; j++, i++) 1810 rec_argv[i] = callgraph_args[j]; 1811 1812 for (j = 1; j < (unsigned int)argc; j++, i++) 1813 rec_argv[i] = argv[j]; 1814 1815 BUG_ON(i != rec_argc); 1816 1817 ret = cmd_record(i, rec_argv); 1818 free(rec_argv); 1819 return ret; 1820 } 1821 1822 int cmd_lock(int argc, const char **argv) 1823 { 1824 const struct option lock_options[] = { 1825 OPT_STRING('i', "input", &input_name, "file", "input file name"), 1826 OPT_INCR('v', "verbose", &verbose, "be more verbose (show symbol address, etc)"), 1827 OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace, "dump raw trace in ASCII"), 1828 OPT_BOOLEAN('f', "force", &force, "don't complain, do it"), 1829 OPT_STRING(0, "vmlinux", &symbol_conf.vmlinux_name, 1830 "file", "vmlinux pathname"), 1831 OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name, 1832 "file", "kallsyms pathname"), 1833 OPT_END() 1834 }; 1835 1836 const struct option info_options[] = { 1837 OPT_BOOLEAN('t', "threads", &info_threads, 1838 "dump thread list in perf.data"), 1839 OPT_BOOLEAN('m', "map", &info_map, 1840 "map of lock instances (address:name table)"), 1841 OPT_PARENT(lock_options) 1842 }; 1843 1844 const struct option report_options[] = { 1845 OPT_STRING('k', "key", &sort_key, "acquired", 1846 "key for sorting (acquired / contended / avg_wait / wait_total / wait_max / wait_min)"), 1847 OPT_STRING('F', "field", &output_fields, NULL, 1848 "output fields (acquired / contended / avg_wait / wait_total / wait_max / wait_min)"), 1849 /* TODO: type */ 1850 OPT_BOOLEAN('c', "combine-locks", &combine_locks, 1851 "combine locks in the same class"), 1852 OPT_BOOLEAN('t', "threads", &show_thread_stats, 1853 "show per-thread lock stats"), 1854 OPT_PARENT(lock_options) 1855 }; 1856 1857 const struct option contention_options[] = { 1858 OPT_STRING('k', "key", &sort_key, "wait_total", 1859 "key for sorting (contended / wait_total / wait_max / wait_min / avg_wait)"), 1860 OPT_STRING('F', "field", &output_fields, "contended,wait_total,wait_max,avg_wait", 1861 "output fields (contended / wait_total / wait_max / wait_min / avg_wait)"), 1862 OPT_BOOLEAN('t', "threads", &show_thread_stats, 1863 "show per-thread lock stats"), 1864 OPT_PARENT(lock_options) 1865 }; 1866 1867 const char * const info_usage[] = { 1868 "perf lock info [<options>]", 1869 NULL 1870 }; 1871 const char *const lock_subcommands[] = { "record", "report", "script", 1872 "info", "contention", 1873 "contention", NULL }; 1874 const char *lock_usage[] = { 1875 NULL, 1876 NULL 1877 }; 1878 const char * const report_usage[] = { 1879 "perf lock report [<options>]", 1880 NULL 1881 }; 1882 const char * const contention_usage[] = { 1883 "perf lock contention [<options>]", 1884 NULL 1885 }; 1886 unsigned int i; 1887 int rc = 0; 1888 1889 for (i = 0; i < LOCKHASH_SIZE; i++) 1890 INIT_HLIST_HEAD(lockhash_table + i); 1891 1892 argc = parse_options_subcommand(argc, argv, lock_options, lock_subcommands, 1893 lock_usage, PARSE_OPT_STOP_AT_NON_OPTION); 1894 if (!argc) 1895 usage_with_options(lock_usage, lock_options); 1896 1897 if (strlen(argv[0]) > 2 && strstarts("record", argv[0])) { 1898 return __cmd_record(argc, argv); 1899 } else if (strlen(argv[0]) > 2 && strstarts("report", argv[0])) { 1900 trace_handler = &report_lock_ops; 1901 if (argc) { 1902 argc = parse_options(argc, argv, 1903 report_options, report_usage, 0); 1904 if (argc) 1905 usage_with_options(report_usage, report_options); 1906 } 1907 rc = __cmd_report(false); 1908 } else if (!strcmp(argv[0], "script")) { 1909 /* Aliased to 'perf script' */ 1910 return cmd_script(argc, argv); 1911 } else if (!strcmp(argv[0], "info")) { 1912 if (argc) { 1913 argc = parse_options(argc, argv, 1914 info_options, info_usage, 0); 1915 if (argc) 1916 usage_with_options(info_usage, info_options); 1917 } 1918 /* recycling report_lock_ops */ 1919 trace_handler = &report_lock_ops; 1920 rc = __cmd_report(true); 1921 } else if (strlen(argv[0]) > 2 && strstarts("contention", argv[0])) { 1922 trace_handler = &contention_lock_ops; 1923 sort_key = "wait_total"; 1924 output_fields = "contended,wait_total,wait_max,avg_wait"; 1925 1926 if (argc) { 1927 argc = parse_options(argc, argv, contention_options, 1928 contention_usage, 0); 1929 if (argc) { 1930 usage_with_options(contention_usage, 1931 contention_options); 1932 } 1933 } 1934 rc = __cmd_contention(); 1935 } else { 1936 usage_with_options(lock_usage, lock_options); 1937 } 1938 1939 return rc; 1940 } 1941