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 13 #include <subcmd/pager.h> 14 #include <subcmd/parse-options.h> 15 #include "util/trace-event.h" 16 17 #include "util/debug.h" 18 #include "util/session.h" 19 #include "util/tool.h" 20 #include "util/data.h" 21 #include "util/string2.h" 22 23 #include <sys/types.h> 24 #include <sys/prctl.h> 25 #include <semaphore.h> 26 #include <pthread.h> 27 #include <math.h> 28 #include <limits.h> 29 30 #include <linux/list.h> 31 #include <linux/hash.h> 32 #include <linux/kernel.h> 33 #include <linux/zalloc.h> 34 #include <linux/err.h> 35 36 static struct perf_session *session; 37 38 /* based on kernel/lockdep.c */ 39 #define LOCKHASH_BITS 12 40 #define LOCKHASH_SIZE (1UL << LOCKHASH_BITS) 41 42 static struct hlist_head lockhash_table[LOCKHASH_SIZE]; 43 44 #define __lockhashfn(key) hash_long((unsigned long)key, LOCKHASH_BITS) 45 #define lockhashentry(key) (lockhash_table + __lockhashfn((key))) 46 47 struct lock_stat { 48 struct hlist_node hash_entry; 49 struct rb_node rb; /* used for sorting */ 50 51 u64 addr; /* address of lockdep_map, used as ID */ 52 char *name; /* for strcpy(), we cannot use const */ 53 54 unsigned int nr_acquire; 55 unsigned int nr_acquired; 56 unsigned int nr_contended; 57 unsigned int nr_release; 58 59 unsigned int nr_readlock; 60 unsigned int nr_trylock; 61 62 /* these times are in nano sec. */ 63 u64 avg_wait_time; 64 u64 wait_time_total; 65 u64 wait_time_min; 66 u64 wait_time_max; 67 68 int broken; /* flag of blacklist */ 69 int combined; 70 }; 71 72 /* 73 * States of lock_seq_stat 74 * 75 * UNINITIALIZED is required for detecting first event of acquire. 76 * As the nature of lock events, there is no guarantee 77 * that the first event for the locks are acquire, 78 * it can be acquired, contended or release. 79 */ 80 #define SEQ_STATE_UNINITIALIZED 0 /* initial state */ 81 #define SEQ_STATE_RELEASED 1 82 #define SEQ_STATE_ACQUIRING 2 83 #define SEQ_STATE_ACQUIRED 3 84 #define SEQ_STATE_READ_ACQUIRED 4 85 #define SEQ_STATE_CONTENDED 5 86 87 /* 88 * MAX_LOCK_DEPTH 89 * Imported from include/linux/sched.h. 90 * Should this be synchronized? 91 */ 92 #define MAX_LOCK_DEPTH 48 93 94 /* 95 * struct lock_seq_stat: 96 * Place to put on state of one lock sequence 97 * 1) acquire -> acquired -> release 98 * 2) acquire -> contended -> acquired -> release 99 * 3) acquire (with read or try) -> release 100 * 4) Are there other patterns? 101 */ 102 struct lock_seq_stat { 103 struct list_head list; 104 int state; 105 u64 prev_event_time; 106 u64 addr; 107 108 int read_count; 109 }; 110 111 struct thread_stat { 112 struct rb_node rb; 113 114 u32 tid; 115 struct list_head seq_list; 116 }; 117 118 static struct rb_root thread_stats; 119 120 static bool combine_locks; 121 static bool show_thread_stats; 122 123 static struct thread_stat *thread_stat_find(u32 tid) 124 { 125 struct rb_node *node; 126 struct thread_stat *st; 127 128 node = thread_stats.rb_node; 129 while (node) { 130 st = container_of(node, struct thread_stat, rb); 131 if (st->tid == tid) 132 return st; 133 else if (tid < st->tid) 134 node = node->rb_left; 135 else 136 node = node->rb_right; 137 } 138 139 return NULL; 140 } 141 142 static void thread_stat_insert(struct thread_stat *new) 143 { 144 struct rb_node **rb = &thread_stats.rb_node; 145 struct rb_node *parent = NULL; 146 struct thread_stat *p; 147 148 while (*rb) { 149 p = container_of(*rb, struct thread_stat, rb); 150 parent = *rb; 151 152 if (new->tid < p->tid) 153 rb = &(*rb)->rb_left; 154 else if (new->tid > p->tid) 155 rb = &(*rb)->rb_right; 156 else 157 BUG_ON("inserting invalid thread_stat\n"); 158 } 159 160 rb_link_node(&new->rb, parent, rb); 161 rb_insert_color(&new->rb, &thread_stats); 162 } 163 164 static struct thread_stat *thread_stat_findnew_after_first(u32 tid) 165 { 166 struct thread_stat *st; 167 168 st = thread_stat_find(tid); 169 if (st) 170 return st; 171 172 st = zalloc(sizeof(struct thread_stat)); 173 if (!st) { 174 pr_err("memory allocation failed\n"); 175 return NULL; 176 } 177 178 st->tid = tid; 179 INIT_LIST_HEAD(&st->seq_list); 180 181 thread_stat_insert(st); 182 183 return st; 184 } 185 186 static struct thread_stat *thread_stat_findnew_first(u32 tid); 187 static struct thread_stat *(*thread_stat_findnew)(u32 tid) = 188 thread_stat_findnew_first; 189 190 static struct thread_stat *thread_stat_findnew_first(u32 tid) 191 { 192 struct thread_stat *st; 193 194 st = zalloc(sizeof(struct thread_stat)); 195 if (!st) { 196 pr_err("memory allocation failed\n"); 197 return NULL; 198 } 199 st->tid = tid; 200 INIT_LIST_HEAD(&st->seq_list); 201 202 rb_link_node(&st->rb, NULL, &thread_stats.rb_node); 203 rb_insert_color(&st->rb, &thread_stats); 204 205 thread_stat_findnew = thread_stat_findnew_after_first; 206 return st; 207 } 208 209 /* build simple key function one is bigger than two */ 210 #define SINGLE_KEY(member) \ 211 static int lock_stat_key_ ## member(struct lock_stat *one, \ 212 struct lock_stat *two) \ 213 { \ 214 return one->member > two->member; \ 215 } 216 217 SINGLE_KEY(nr_acquired) 218 SINGLE_KEY(nr_contended) 219 SINGLE_KEY(avg_wait_time) 220 SINGLE_KEY(wait_time_total) 221 SINGLE_KEY(wait_time_max) 222 223 static int lock_stat_key_wait_time_min(struct lock_stat *one, 224 struct lock_stat *two) 225 { 226 u64 s1 = one->wait_time_min; 227 u64 s2 = two->wait_time_min; 228 if (s1 == ULLONG_MAX) 229 s1 = 0; 230 if (s2 == ULLONG_MAX) 231 s2 = 0; 232 return s1 > s2; 233 } 234 235 struct lock_key { 236 /* 237 * name: the value for specify by user 238 * this should be simpler than raw name of member 239 * e.g. nr_acquired -> acquired, wait_time_total -> wait_total 240 */ 241 const char *name; 242 /* header: the string printed on the header line */ 243 const char *header; 244 /* len: the printing width of the field */ 245 int len; 246 /* key: a pointer to function to compare two lock stats for sorting */ 247 int (*key)(struct lock_stat*, struct lock_stat*); 248 /* print: a pointer to function to print a given lock stats */ 249 void (*print)(struct lock_key*, struct lock_stat*); 250 /* list: list entry to link this */ 251 struct list_head list; 252 }; 253 254 #define PRINT_KEY(member) \ 255 static void lock_stat_key_print_ ## member(struct lock_key *key, \ 256 struct lock_stat *ls) \ 257 { \ 258 pr_info("%*llu", key->len, (unsigned long long)ls->member); \ 259 } 260 261 PRINT_KEY(nr_acquired) 262 PRINT_KEY(nr_contended) 263 PRINT_KEY(avg_wait_time) 264 PRINT_KEY(wait_time_total) 265 PRINT_KEY(wait_time_max) 266 267 static void lock_stat_key_print_wait_time_min(struct lock_key *key, 268 struct lock_stat *ls) 269 { 270 u64 wait_time = ls->wait_time_min; 271 272 if (wait_time == ULLONG_MAX) 273 wait_time = 0; 274 275 pr_info("%*"PRIu64, key->len, wait_time); 276 } 277 278 279 static const char *sort_key = "acquired"; 280 281 static int (*compare)(struct lock_stat *, struct lock_stat *); 282 283 static struct rb_root sorted; /* place to store intermediate data */ 284 static struct rb_root result; /* place to store sorted data */ 285 286 static LIST_HEAD(lock_keys); 287 static const char *output_fields; 288 289 #define DEF_KEY_LOCK(name, header, fn_suffix, len) \ 290 { #name, header, len, lock_stat_key_ ## fn_suffix, lock_stat_key_print_ ## fn_suffix, {} } 291 struct lock_key keys[] = { 292 DEF_KEY_LOCK(acquired, "acquired", nr_acquired, 10), 293 DEF_KEY_LOCK(contended, "contended", nr_contended, 10), 294 DEF_KEY_LOCK(avg_wait, "avg wait (ns)", avg_wait_time, 15), 295 DEF_KEY_LOCK(wait_total, "total wait (ns)", wait_time_total, 15), 296 DEF_KEY_LOCK(wait_max, "max wait (ns)", wait_time_max, 15), 297 DEF_KEY_LOCK(wait_min, "min wait (ns)", wait_time_min, 15), 298 299 /* extra comparisons much complicated should be here */ 300 { } 301 }; 302 303 static int select_key(void) 304 { 305 int i; 306 307 for (i = 0; keys[i].name; i++) { 308 if (!strcmp(keys[i].name, sort_key)) { 309 compare = keys[i].key; 310 311 /* selected key should be in the output fields */ 312 if (list_empty(&keys[i].list)) 313 list_add_tail(&keys[i].list, &lock_keys); 314 315 return 0; 316 } 317 } 318 319 pr_err("Unknown compare key: %s\n", sort_key); 320 return -1; 321 } 322 323 static int add_output_field(struct list_head *head, char *name) 324 { 325 int i; 326 327 for (i = 0; keys[i].name; i++) { 328 if (strcmp(keys[i].name, name)) 329 continue; 330 331 /* prevent double link */ 332 if (list_empty(&keys[i].list)) 333 list_add_tail(&keys[i].list, head); 334 335 return 0; 336 } 337 338 pr_err("Unknown output field: %s\n", name); 339 return -1; 340 } 341 342 static int setup_output_field(const char *str) 343 { 344 char *tok, *tmp, *orig; 345 int i, ret = 0; 346 347 /* no output field given: use all of them */ 348 if (str == NULL) { 349 for (i = 0; keys[i].name; i++) 350 list_add_tail(&keys[i].list, &lock_keys); 351 return 0; 352 } 353 354 for (i = 0; keys[i].name; i++) 355 INIT_LIST_HEAD(&keys[i].list); 356 357 orig = tmp = strdup(str); 358 if (orig == NULL) 359 return -ENOMEM; 360 361 while ((tok = strsep(&tmp, ",")) != NULL){ 362 ret = add_output_field(&lock_keys, tok); 363 if (ret < 0) 364 break; 365 } 366 free(orig); 367 368 return ret; 369 } 370 371 static void combine_lock_stats(struct lock_stat *st) 372 { 373 struct rb_node **rb = &sorted.rb_node; 374 struct rb_node *parent = NULL; 375 struct lock_stat *p; 376 int ret; 377 378 while (*rb) { 379 p = container_of(*rb, struct lock_stat, rb); 380 parent = *rb; 381 382 if (st->name && p->name) 383 ret = strcmp(st->name, p->name); 384 else 385 ret = !!st->name - !!p->name; 386 387 if (ret == 0) { 388 p->nr_acquired += st->nr_acquired; 389 p->nr_contended += st->nr_contended; 390 p->wait_time_total += st->wait_time_total; 391 392 if (p->nr_contended) 393 p->avg_wait_time = p->wait_time_total / p->nr_contended; 394 395 if (p->wait_time_min > st->wait_time_min) 396 p->wait_time_min = st->wait_time_min; 397 if (p->wait_time_max < st->wait_time_max) 398 p->wait_time_max = st->wait_time_max; 399 400 p->broken |= st->broken; 401 st->combined = 1; 402 return; 403 } 404 405 if (ret < 0) 406 rb = &(*rb)->rb_left; 407 else 408 rb = &(*rb)->rb_right; 409 } 410 411 rb_link_node(&st->rb, parent, rb); 412 rb_insert_color(&st->rb, &sorted); 413 } 414 415 static void insert_to_result(struct lock_stat *st, 416 int (*bigger)(struct lock_stat *, struct lock_stat *)) 417 { 418 struct rb_node **rb = &result.rb_node; 419 struct rb_node *parent = NULL; 420 struct lock_stat *p; 421 422 if (combine_locks && st->combined) 423 return; 424 425 while (*rb) { 426 p = container_of(*rb, struct lock_stat, rb); 427 parent = *rb; 428 429 if (bigger(st, p)) 430 rb = &(*rb)->rb_left; 431 else 432 rb = &(*rb)->rb_right; 433 } 434 435 rb_link_node(&st->rb, parent, rb); 436 rb_insert_color(&st->rb, &result); 437 } 438 439 /* returns left most element of result, and erase it */ 440 static struct lock_stat *pop_from_result(void) 441 { 442 struct rb_node *node = result.rb_node; 443 444 if (!node) 445 return NULL; 446 447 while (node->rb_left) 448 node = node->rb_left; 449 450 rb_erase(node, &result); 451 return container_of(node, struct lock_stat, rb); 452 } 453 454 static struct lock_stat *lock_stat_findnew(u64 addr, const char *name) 455 { 456 struct hlist_head *entry = lockhashentry(addr); 457 struct lock_stat *ret, *new; 458 459 hlist_for_each_entry(ret, entry, hash_entry) { 460 if (ret->addr == addr) 461 return ret; 462 } 463 464 new = zalloc(sizeof(struct lock_stat)); 465 if (!new) 466 goto alloc_failed; 467 468 new->addr = addr; 469 new->name = zalloc(sizeof(char) * strlen(name) + 1); 470 if (!new->name) { 471 free(new); 472 goto alloc_failed; 473 } 474 475 strcpy(new->name, name); 476 new->wait_time_min = ULLONG_MAX; 477 478 hlist_add_head(&new->hash_entry, entry); 479 return new; 480 481 alloc_failed: 482 pr_err("memory allocation failed\n"); 483 return NULL; 484 } 485 486 struct trace_lock_handler { 487 int (*acquire_event)(struct evsel *evsel, 488 struct perf_sample *sample); 489 490 int (*acquired_event)(struct evsel *evsel, 491 struct perf_sample *sample); 492 493 int (*contended_event)(struct evsel *evsel, 494 struct perf_sample *sample); 495 496 int (*release_event)(struct evsel *evsel, 497 struct perf_sample *sample); 498 }; 499 500 static struct lock_seq_stat *get_seq(struct thread_stat *ts, u64 addr) 501 { 502 struct lock_seq_stat *seq; 503 504 list_for_each_entry(seq, &ts->seq_list, list) { 505 if (seq->addr == addr) 506 return seq; 507 } 508 509 seq = zalloc(sizeof(struct lock_seq_stat)); 510 if (!seq) { 511 pr_err("memory allocation failed\n"); 512 return NULL; 513 } 514 seq->state = SEQ_STATE_UNINITIALIZED; 515 seq->addr = addr; 516 517 list_add(&seq->list, &ts->seq_list); 518 return seq; 519 } 520 521 enum broken_state { 522 BROKEN_ACQUIRE, 523 BROKEN_ACQUIRED, 524 BROKEN_CONTENDED, 525 BROKEN_RELEASE, 526 BROKEN_MAX, 527 }; 528 529 static int bad_hist[BROKEN_MAX]; 530 531 enum acquire_flags { 532 TRY_LOCK = 1, 533 READ_LOCK = 2, 534 }; 535 536 static int report_lock_acquire_event(struct evsel *evsel, 537 struct perf_sample *sample) 538 { 539 struct lock_stat *ls; 540 struct thread_stat *ts; 541 struct lock_seq_stat *seq; 542 const char *name = evsel__strval(evsel, sample, "name"); 543 u64 addr = evsel__intval(evsel, sample, "lockdep_addr"); 544 int flag = evsel__intval(evsel, sample, "flags"); 545 546 /* abuse ls->addr for tid */ 547 if (show_thread_stats) 548 addr = sample->tid; 549 550 ls = lock_stat_findnew(addr, name); 551 if (!ls) 552 return -ENOMEM; 553 554 ts = thread_stat_findnew(sample->tid); 555 if (!ts) 556 return -ENOMEM; 557 558 seq = get_seq(ts, addr); 559 if (!seq) 560 return -ENOMEM; 561 562 switch (seq->state) { 563 case SEQ_STATE_UNINITIALIZED: 564 case SEQ_STATE_RELEASED: 565 if (!flag) { 566 seq->state = SEQ_STATE_ACQUIRING; 567 } else { 568 if (flag & TRY_LOCK) 569 ls->nr_trylock++; 570 if (flag & READ_LOCK) 571 ls->nr_readlock++; 572 seq->state = SEQ_STATE_READ_ACQUIRED; 573 seq->read_count = 1; 574 ls->nr_acquired++; 575 } 576 break; 577 case SEQ_STATE_READ_ACQUIRED: 578 if (flag & READ_LOCK) { 579 seq->read_count++; 580 ls->nr_acquired++; 581 goto end; 582 } else { 583 goto broken; 584 } 585 break; 586 case SEQ_STATE_ACQUIRED: 587 case SEQ_STATE_ACQUIRING: 588 case SEQ_STATE_CONTENDED: 589 broken: 590 /* broken lock sequence */ 591 if (!ls->broken) { 592 ls->broken = 1; 593 bad_hist[BROKEN_ACQUIRE]++; 594 } 595 list_del_init(&seq->list); 596 free(seq); 597 goto end; 598 default: 599 BUG_ON("Unknown state of lock sequence found!\n"); 600 break; 601 } 602 603 ls->nr_acquire++; 604 seq->prev_event_time = sample->time; 605 end: 606 return 0; 607 } 608 609 static int report_lock_acquired_event(struct evsel *evsel, 610 struct perf_sample *sample) 611 { 612 struct lock_stat *ls; 613 struct thread_stat *ts; 614 struct lock_seq_stat *seq; 615 u64 contended_term; 616 const char *name = evsel__strval(evsel, sample, "name"); 617 u64 addr = evsel__intval(evsel, sample, "lockdep_addr"); 618 619 if (show_thread_stats) 620 addr = sample->tid; 621 622 ls = lock_stat_findnew(addr, name); 623 if (!ls) 624 return -ENOMEM; 625 626 ts = thread_stat_findnew(sample->tid); 627 if (!ts) 628 return -ENOMEM; 629 630 seq = get_seq(ts, addr); 631 if (!seq) 632 return -ENOMEM; 633 634 switch (seq->state) { 635 case SEQ_STATE_UNINITIALIZED: 636 /* orphan event, do nothing */ 637 return 0; 638 case SEQ_STATE_ACQUIRING: 639 break; 640 case SEQ_STATE_CONTENDED: 641 contended_term = sample->time - seq->prev_event_time; 642 ls->wait_time_total += contended_term; 643 if (contended_term < ls->wait_time_min) 644 ls->wait_time_min = contended_term; 645 if (ls->wait_time_max < contended_term) 646 ls->wait_time_max = contended_term; 647 break; 648 case SEQ_STATE_RELEASED: 649 case SEQ_STATE_ACQUIRED: 650 case SEQ_STATE_READ_ACQUIRED: 651 /* broken lock sequence */ 652 if (!ls->broken) { 653 ls->broken = 1; 654 bad_hist[BROKEN_ACQUIRED]++; 655 } 656 list_del_init(&seq->list); 657 free(seq); 658 goto end; 659 default: 660 BUG_ON("Unknown state of lock sequence found!\n"); 661 break; 662 } 663 664 seq->state = SEQ_STATE_ACQUIRED; 665 ls->nr_acquired++; 666 ls->avg_wait_time = ls->nr_contended ? ls->wait_time_total/ls->nr_contended : 0; 667 seq->prev_event_time = sample->time; 668 end: 669 return 0; 670 } 671 672 static int report_lock_contended_event(struct evsel *evsel, 673 struct perf_sample *sample) 674 { 675 struct lock_stat *ls; 676 struct thread_stat *ts; 677 struct lock_seq_stat *seq; 678 const char *name = evsel__strval(evsel, sample, "name"); 679 u64 addr = evsel__intval(evsel, sample, "lockdep_addr"); 680 681 if (show_thread_stats) 682 addr = sample->tid; 683 684 ls = lock_stat_findnew(addr, name); 685 if (!ls) 686 return -ENOMEM; 687 688 ts = thread_stat_findnew(sample->tid); 689 if (!ts) 690 return -ENOMEM; 691 692 seq = get_seq(ts, addr); 693 if (!seq) 694 return -ENOMEM; 695 696 switch (seq->state) { 697 case SEQ_STATE_UNINITIALIZED: 698 /* orphan event, do nothing */ 699 return 0; 700 case SEQ_STATE_ACQUIRING: 701 break; 702 case SEQ_STATE_RELEASED: 703 case SEQ_STATE_ACQUIRED: 704 case SEQ_STATE_READ_ACQUIRED: 705 case SEQ_STATE_CONTENDED: 706 /* broken lock sequence */ 707 if (!ls->broken) { 708 ls->broken = 1; 709 bad_hist[BROKEN_CONTENDED]++; 710 } 711 list_del_init(&seq->list); 712 free(seq); 713 goto end; 714 default: 715 BUG_ON("Unknown state of lock sequence found!\n"); 716 break; 717 } 718 719 seq->state = SEQ_STATE_CONTENDED; 720 ls->nr_contended++; 721 ls->avg_wait_time = ls->wait_time_total/ls->nr_contended; 722 seq->prev_event_time = sample->time; 723 end: 724 return 0; 725 } 726 727 static int report_lock_release_event(struct evsel *evsel, 728 struct perf_sample *sample) 729 { 730 struct lock_stat *ls; 731 struct thread_stat *ts; 732 struct lock_seq_stat *seq; 733 const char *name = evsel__strval(evsel, sample, "name"); 734 u64 addr = evsel__intval(evsel, sample, "lockdep_addr"); 735 736 if (show_thread_stats) 737 addr = sample->tid; 738 739 ls = lock_stat_findnew(addr, name); 740 if (!ls) 741 return -ENOMEM; 742 743 ts = thread_stat_findnew(sample->tid); 744 if (!ts) 745 return -ENOMEM; 746 747 seq = get_seq(ts, addr); 748 if (!seq) 749 return -ENOMEM; 750 751 switch (seq->state) { 752 case SEQ_STATE_UNINITIALIZED: 753 goto end; 754 case SEQ_STATE_ACQUIRED: 755 break; 756 case SEQ_STATE_READ_ACQUIRED: 757 seq->read_count--; 758 BUG_ON(seq->read_count < 0); 759 if (seq->read_count) { 760 ls->nr_release++; 761 goto end; 762 } 763 break; 764 case SEQ_STATE_ACQUIRING: 765 case SEQ_STATE_CONTENDED: 766 case SEQ_STATE_RELEASED: 767 /* broken lock sequence */ 768 if (!ls->broken) { 769 ls->broken = 1; 770 bad_hist[BROKEN_RELEASE]++; 771 } 772 goto free_seq; 773 default: 774 BUG_ON("Unknown state of lock sequence found!\n"); 775 break; 776 } 777 778 ls->nr_release++; 779 free_seq: 780 list_del_init(&seq->list); 781 free(seq); 782 end: 783 return 0; 784 } 785 786 /* lock oriented handlers */ 787 /* TODO: handlers for CPU oriented, thread oriented */ 788 static struct trace_lock_handler report_lock_ops = { 789 .acquire_event = report_lock_acquire_event, 790 .acquired_event = report_lock_acquired_event, 791 .contended_event = report_lock_contended_event, 792 .release_event = report_lock_release_event, 793 }; 794 795 static struct trace_lock_handler *trace_handler; 796 797 static int evsel__process_lock_acquire(struct evsel *evsel, struct perf_sample *sample) 798 { 799 if (trace_handler->acquire_event) 800 return trace_handler->acquire_event(evsel, sample); 801 return 0; 802 } 803 804 static int evsel__process_lock_acquired(struct evsel *evsel, struct perf_sample *sample) 805 { 806 if (trace_handler->acquired_event) 807 return trace_handler->acquired_event(evsel, sample); 808 return 0; 809 } 810 811 static int evsel__process_lock_contended(struct evsel *evsel, struct perf_sample *sample) 812 { 813 if (trace_handler->contended_event) 814 return trace_handler->contended_event(evsel, sample); 815 return 0; 816 } 817 818 static int evsel__process_lock_release(struct evsel *evsel, struct perf_sample *sample) 819 { 820 if (trace_handler->release_event) 821 return trace_handler->release_event(evsel, sample); 822 return 0; 823 } 824 825 static void print_bad_events(int bad, int total) 826 { 827 /* Output for debug, this have to be removed */ 828 int i; 829 const char *name[4] = 830 { "acquire", "acquired", "contended", "release" }; 831 832 pr_info("\n=== output for debug===\n\n"); 833 pr_info("bad: %d, total: %d\n", bad, total); 834 pr_info("bad rate: %.2f %%\n", (double)bad / (double)total * 100); 835 pr_info("histogram of events caused bad sequence\n"); 836 for (i = 0; i < BROKEN_MAX; i++) 837 pr_info(" %10s: %d\n", name[i], bad_hist[i]); 838 } 839 840 /* TODO: various way to print, coloring, nano or milli sec */ 841 static void print_result(void) 842 { 843 struct lock_stat *st; 844 struct lock_key *key; 845 char cut_name[20]; 846 int bad, total; 847 848 pr_info("%20s ", "Name"); 849 list_for_each_entry(key, &lock_keys, list) 850 pr_info("%*s ", key->len, key->header); 851 pr_info("\n\n"); 852 853 bad = total = 0; 854 while ((st = pop_from_result())) { 855 total++; 856 if (st->broken) 857 bad++; 858 if (!st->nr_acquired) 859 continue; 860 861 bzero(cut_name, 20); 862 863 if (strlen(st->name) < 20) { 864 /* output raw name */ 865 const char *name = st->name; 866 867 if (show_thread_stats) { 868 struct thread *t; 869 870 /* st->addr contains tid of thread */ 871 t = perf_session__findnew(session, st->addr); 872 name = thread__comm_str(t); 873 } 874 875 pr_info("%20s ", name); 876 } else { 877 strncpy(cut_name, st->name, 16); 878 cut_name[16] = '.'; 879 cut_name[17] = '.'; 880 cut_name[18] = '.'; 881 cut_name[19] = '\0'; 882 /* cut off name for saving output style */ 883 pr_info("%20s ", cut_name); 884 } 885 886 list_for_each_entry(key, &lock_keys, list) { 887 key->print(key, st); 888 pr_info(" "); 889 } 890 pr_info("\n"); 891 } 892 893 print_bad_events(bad, total); 894 } 895 896 static bool info_threads, info_map; 897 898 static void dump_threads(void) 899 { 900 struct thread_stat *st; 901 struct rb_node *node; 902 struct thread *t; 903 904 pr_info("%10s: comm\n", "Thread ID"); 905 906 node = rb_first(&thread_stats); 907 while (node) { 908 st = container_of(node, struct thread_stat, rb); 909 t = perf_session__findnew(session, st->tid); 910 pr_info("%10d: %s\n", st->tid, thread__comm_str(t)); 911 node = rb_next(node); 912 thread__put(t); 913 } 914 } 915 916 static int compare_maps(struct lock_stat *a, struct lock_stat *b) 917 { 918 int ret; 919 920 if (a->name && b->name) 921 ret = strcmp(a->name, b->name); 922 else 923 ret = !!a->name - !!b->name; 924 925 if (!ret) 926 return a->addr < b->addr; 927 else 928 return ret < 0; 929 } 930 931 static void dump_map(void) 932 { 933 unsigned int i; 934 struct lock_stat *st; 935 936 pr_info("Address of instance: name of class\n"); 937 for (i = 0; i < LOCKHASH_SIZE; i++) { 938 hlist_for_each_entry(st, &lockhash_table[i], hash_entry) { 939 insert_to_result(st, compare_maps); 940 } 941 } 942 943 while ((st = pop_from_result())) 944 pr_info(" %#llx: %s\n", (unsigned long long)st->addr, st->name); 945 } 946 947 static int dump_info(void) 948 { 949 int rc = 0; 950 951 if (info_threads) 952 dump_threads(); 953 else if (info_map) 954 dump_map(); 955 else { 956 rc = -1; 957 pr_err("Unknown type of information\n"); 958 } 959 960 return rc; 961 } 962 963 typedef int (*tracepoint_handler)(struct evsel *evsel, 964 struct perf_sample *sample); 965 966 static int process_sample_event(struct perf_tool *tool __maybe_unused, 967 union perf_event *event, 968 struct perf_sample *sample, 969 struct evsel *evsel, 970 struct machine *machine) 971 { 972 int err = 0; 973 struct thread *thread = machine__findnew_thread(machine, sample->pid, 974 sample->tid); 975 976 if (thread == NULL) { 977 pr_debug("problem processing %d event, skipping it.\n", 978 event->header.type); 979 return -1; 980 } 981 982 if (evsel->handler != NULL) { 983 tracepoint_handler f = evsel->handler; 984 err = f(evsel, sample); 985 } 986 987 thread__put(thread); 988 989 return err; 990 } 991 992 static void combine_result(void) 993 { 994 unsigned int i; 995 struct lock_stat *st; 996 997 if (!combine_locks) 998 return; 999 1000 for (i = 0; i < LOCKHASH_SIZE; i++) { 1001 hlist_for_each_entry(st, &lockhash_table[i], hash_entry) { 1002 combine_lock_stats(st); 1003 } 1004 } 1005 } 1006 1007 static void sort_result(void) 1008 { 1009 unsigned int i; 1010 struct lock_stat *st; 1011 1012 for (i = 0; i < LOCKHASH_SIZE; i++) { 1013 hlist_for_each_entry(st, &lockhash_table[i], hash_entry) { 1014 insert_to_result(st, compare); 1015 } 1016 } 1017 } 1018 1019 static const struct evsel_str_handler lock_tracepoints[] = { 1020 { "lock:lock_acquire", evsel__process_lock_acquire, }, /* CONFIG_LOCKDEP */ 1021 { "lock:lock_acquired", evsel__process_lock_acquired, }, /* CONFIG_LOCKDEP, CONFIG_LOCK_STAT */ 1022 { "lock:lock_contended", evsel__process_lock_contended, }, /* CONFIG_LOCKDEP, CONFIG_LOCK_STAT */ 1023 { "lock:lock_release", evsel__process_lock_release, }, /* CONFIG_LOCKDEP */ 1024 }; 1025 1026 static bool force; 1027 1028 static int __cmd_report(bool display_info) 1029 { 1030 int err = -EINVAL; 1031 struct perf_tool eops = { 1032 .sample = process_sample_event, 1033 .comm = perf_event__process_comm, 1034 .namespaces = perf_event__process_namespaces, 1035 .ordered_events = true, 1036 }; 1037 struct perf_data data = { 1038 .path = input_name, 1039 .mode = PERF_DATA_MODE_READ, 1040 .force = force, 1041 }; 1042 1043 session = perf_session__new(&data, &eops); 1044 if (IS_ERR(session)) { 1045 pr_err("Initializing perf session failed\n"); 1046 return PTR_ERR(session); 1047 } 1048 1049 symbol__init(&session->header.env); 1050 1051 if (!perf_session__has_traces(session, "lock record")) 1052 goto out_delete; 1053 1054 if (perf_session__set_tracepoints_handlers(session, lock_tracepoints)) { 1055 pr_err("Initializing perf session tracepoint handlers failed\n"); 1056 goto out_delete; 1057 } 1058 1059 if (setup_output_field(output_fields)) 1060 goto out_delete; 1061 1062 if (select_key()) 1063 goto out_delete; 1064 1065 err = perf_session__process_events(session); 1066 if (err) 1067 goto out_delete; 1068 1069 setup_pager(); 1070 if (display_info) /* used for info subcommand */ 1071 err = dump_info(); 1072 else { 1073 combine_result(); 1074 sort_result(); 1075 print_result(); 1076 } 1077 1078 out_delete: 1079 perf_session__delete(session); 1080 return err; 1081 } 1082 1083 static int __cmd_record(int argc, const char **argv) 1084 { 1085 const char *record_args[] = { 1086 "record", "-R", "-m", "1024", "-c", "1", "--synth", "task", 1087 }; 1088 unsigned int rec_argc, i, j, ret; 1089 const char **rec_argv; 1090 1091 for (i = 0; i < ARRAY_SIZE(lock_tracepoints); i++) { 1092 if (!is_valid_tracepoint(lock_tracepoints[i].name)) { 1093 pr_err("tracepoint %s is not enabled. " 1094 "Are CONFIG_LOCKDEP and CONFIG_LOCK_STAT enabled?\n", 1095 lock_tracepoints[i].name); 1096 return 1; 1097 } 1098 } 1099 1100 rec_argc = ARRAY_SIZE(record_args) + argc - 1; 1101 /* factor of 2 is for -e in front of each tracepoint */ 1102 rec_argc += 2 * ARRAY_SIZE(lock_tracepoints); 1103 1104 rec_argv = calloc(rec_argc + 1, sizeof(char *)); 1105 if (!rec_argv) 1106 return -ENOMEM; 1107 1108 for (i = 0; i < ARRAY_SIZE(record_args); i++) 1109 rec_argv[i] = strdup(record_args[i]); 1110 1111 for (j = 0; j < ARRAY_SIZE(lock_tracepoints); j++) { 1112 rec_argv[i++] = "-e"; 1113 rec_argv[i++] = strdup(lock_tracepoints[j].name); 1114 } 1115 1116 for (j = 1; j < (unsigned int)argc; j++, i++) 1117 rec_argv[i] = argv[j]; 1118 1119 BUG_ON(i != rec_argc); 1120 1121 ret = cmd_record(i, rec_argv); 1122 free(rec_argv); 1123 return ret; 1124 } 1125 1126 int cmd_lock(int argc, const char **argv) 1127 { 1128 const struct option lock_options[] = { 1129 OPT_STRING('i', "input", &input_name, "file", "input file name"), 1130 OPT_INCR('v', "verbose", &verbose, "be more verbose (show symbol address, etc)"), 1131 OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace, "dump raw trace in ASCII"), 1132 OPT_BOOLEAN('f', "force", &force, "don't complain, do it"), 1133 OPT_END() 1134 }; 1135 1136 const struct option info_options[] = { 1137 OPT_BOOLEAN('t', "threads", &info_threads, 1138 "dump thread list in perf.data"), 1139 OPT_BOOLEAN('m', "map", &info_map, 1140 "map of lock instances (address:name table)"), 1141 OPT_PARENT(lock_options) 1142 }; 1143 1144 const struct option report_options[] = { 1145 OPT_STRING('k', "key", &sort_key, "acquired", 1146 "key for sorting (acquired / contended / avg_wait / wait_total / wait_max / wait_min)"), 1147 OPT_STRING('F', "field", &output_fields, NULL, 1148 "output fields (acquired / contended / avg_wait / wait_total / wait_max / wait_min)"), 1149 /* TODO: type */ 1150 OPT_BOOLEAN('c', "combine-locks", &combine_locks, 1151 "combine locks in the same class"), 1152 OPT_BOOLEAN('t', "threads", &show_thread_stats, 1153 "show per-thread lock stats"), 1154 OPT_PARENT(lock_options) 1155 }; 1156 1157 const char * const info_usage[] = { 1158 "perf lock info [<options>]", 1159 NULL 1160 }; 1161 const char *const lock_subcommands[] = { "record", "report", "script", 1162 "info", NULL }; 1163 const char *lock_usage[] = { 1164 NULL, 1165 NULL 1166 }; 1167 const char * const report_usage[] = { 1168 "perf lock report [<options>]", 1169 NULL 1170 }; 1171 unsigned int i; 1172 int rc = 0; 1173 1174 for (i = 0; i < LOCKHASH_SIZE; i++) 1175 INIT_HLIST_HEAD(lockhash_table + i); 1176 1177 argc = parse_options_subcommand(argc, argv, lock_options, lock_subcommands, 1178 lock_usage, PARSE_OPT_STOP_AT_NON_OPTION); 1179 if (!argc) 1180 usage_with_options(lock_usage, lock_options); 1181 1182 if (strlen(argv[0]) > 2 && strstarts("record", argv[0])) { 1183 return __cmd_record(argc, argv); 1184 } else if (strlen(argv[0]) > 2 && strstarts("report", argv[0])) { 1185 trace_handler = &report_lock_ops; 1186 if (argc) { 1187 argc = parse_options(argc, argv, 1188 report_options, report_usage, 0); 1189 if (argc) 1190 usage_with_options(report_usage, report_options); 1191 } 1192 rc = __cmd_report(false); 1193 } else if (!strcmp(argv[0], "script")) { 1194 /* Aliased to 'perf script' */ 1195 return cmd_script(argc, argv); 1196 } else if (!strcmp(argv[0], "info")) { 1197 if (argc) { 1198 argc = parse_options(argc, argv, 1199 info_options, info_usage, 0); 1200 if (argc) 1201 usage_with_options(info_usage, info_options); 1202 } 1203 /* recycling report_lock_ops */ 1204 trace_handler = &report_lock_ops; 1205 rc = __cmd_report(true); 1206 } else { 1207 usage_with_options(lock_usage, lock_options); 1208 } 1209 1210 return rc; 1211 } 1212