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