tools/perf/builtin-lock.c

   1 #include "builtin.h"
   2 #include "perf.h"
   3
   4 #include "util/util.h"
   5 #include "util/cache.h"
   6 #include "util/symbol.h"
   7 #include "util/thread.h"
   8 #include "util/header.h"
   9
  10 #include "util/parse-options.h"
  11 #include "util/trace-event.h"
  12
  13 #include "util/debug.h"
  14 #include "util/session.h"
  15
  16 #include <sys/types.h>
  17 #include <sys/prctl.h>
  18 #include <semaphore.h>
  19 #include <pthread.h>
  20 #include <math.h>
  21 #include <limits.h>
  22
  23 #include <linux/list.h>
  24 #include <linux/hash.h>
  25
  26 /* based on kernel/lockdep.c */
  27 #define LOCKHASH_BITS           12
  28 #define LOCKHASH_SIZE           (1UL << LOCKHASH_BITS)
  29
  30 static struct list_head lockhash_table[LOCKHASH_SIZE];
  31
  32 #define __lockhashfn(key)       hash_long((unsigned long)key, LOCKHASH_BITS)
  33 #define lockhashentry(key)      (lockhash_table + __lockhashfn((key)))
  34
  35 #define LOCK_STATE_UNLOCKED     0              /* initial state */
  36 #define LOCK_STATE_LOCKED       1
  37
  38 struct lock_stat {
  39         struct list_head        hash_entry;
  40         struct rb_node          rb;             /* used for sorting */
  41
  42         /*
  43          * FIXME: raw_field_value() returns unsigned long long,
  44          * so address of lockdep_map should be dealed as 64bit.
  45          * Is there more better solution?
  46          */
  47         void                    *addr;          /* address of lockdep_map, used as ID */
  48         char                    *name;          /* for strcpy(), we cannot use const */
  49
  50         int                     state;
  51         u64                     prev_event_time; /* timestamp of previous event */
  52
  53         unsigned int            nr_acquired;
  54         unsigned int            nr_acquire;
  55         unsigned int            nr_contended;
  56         unsigned int            nr_release;
  57
  58         /* these times are in nano sec. */
  59         u64                     wait_time_total;
  60         u64                     wait_time_min;
  61         u64                     wait_time_max;
  62 };
  63
  64 /* build simple key function one is bigger than two */
  65 #define SINGLE_KEY(member)                                              \
  66         static int lock_stat_key_ ## member(struct lock_stat *one,      \
  67                                          struct lock_stat *two)         \
  68         {                                                               \
  69                 return one->member > two->member;                       \
  70         }
  71
  72 SINGLE_KEY(nr_acquired)
  73 SINGLE_KEY(nr_contended)
  74 SINGLE_KEY(wait_time_total)
  75 SINGLE_KEY(wait_time_min)
  76 SINGLE_KEY(wait_time_max)
  77
  78 struct lock_key {
  79         /*
  80          * name: the value for specify by user
  81          * this should be simpler than raw name of member
  82          * e.g. nr_acquired -> acquired, wait_time_total -> wait_total
  83          */
  84         const char              *name;
  85         int                     (*key)(struct lock_stat*, struct lock_stat*);
  86 };
  87
  88 static const char               *sort_key = "acquired";
  89
  90 static int                      (*compare)(struct lock_stat *, struct lock_stat *);
  91
  92 static struct rb_root           result; /* place to store sorted data */
  93
  94 #define DEF_KEY_LOCK(name, fn_suffix)   \
  95         { #name, lock_stat_key_ ## fn_suffix }
  96 struct lock_key keys[] = {
  97         DEF_KEY_LOCK(acquired, nr_acquired),
  98         DEF_KEY_LOCK(contended, nr_contended),
  99         DEF_KEY_LOCK(wait_total, wait_time_total),
 100         DEF_KEY_LOCK(wait_min, wait_time_min),
 101         DEF_KEY_LOCK(wait_max, wait_time_max),
 102
 103         /* extra comparisons much complicated should be here */
 104
 105         { NULL, NULL }
 106 };
 107
 108 static void select_key(void)
 109 {
 110         int i;
 111
 112         for (i = 0; keys[i].name; i++) {
 113                 if (!strcmp(keys[i].name, sort_key)) {
 114                         compare = keys[i].key;
 115                         return;
 116                 }
 117         }
 118
 119         die("Unknown compare key:%s\n", sort_key);
 120 }
 121
 122 static void insert_to_result(struct lock_stat *st,
 123                              int (*bigger)(struct lock_stat *, struct lock_stat *))
 124 {
 125         struct rb_node **rb = &result.rb_node;
 126         struct rb_node *parent = NULL;
 127         struct lock_stat *p;
 128
 129         while (*rb) {
 130                 p = container_of(*rb, struct lock_stat, rb);
 131                 parent = *rb;
 132
 133                 if (bigger(st, p))
 134                         rb = &(*rb)->rb_left;
 135                 else
 136                         rb = &(*rb)->rb_right;
 137         }
 138
 139         rb_link_node(&st->rb, parent, rb);
 140         rb_insert_color(&st->rb, &result);
 141 }
 142
 143 /* returns left most element of result, and erase it */
 144 static struct lock_stat *pop_from_result(void)
 145 {
 146         struct rb_node *node = result.rb_node;
 147
 148         if (!node)
 149                 return NULL;
 150
 151         while (node->rb_left)
 152                 node = node->rb_left;
 153
 154         rb_erase(node, &result);
 155         return container_of(node, struct lock_stat, rb);
 156 }
 157
 158 static struct lock_stat *lock_stat_findnew(void *addr, const char *name)
 159 {
 160         struct list_head *entry = lockhashentry(addr);
 161         struct lock_stat *ret, *new;
 162
 163         list_for_each_entry(ret, entry, hash_entry) {
 164                 if (ret->addr == addr)
 165                         return ret;
 166         }
 167
 168         new = zalloc(sizeof(struct lock_stat));
 169         if (!new)
 170                 goto alloc_failed;
 171
 172         new->addr = addr;
 173         new->name = zalloc(sizeof(char) * strlen(name) + 1);
 174         if (!new->name)
 175                 goto alloc_failed;
 176         strcpy(new->name, name);
 177
 178         /* LOCK_STATE_UNLOCKED == 0 isn't guaranteed forever */
 179         new->state = LOCK_STATE_UNLOCKED;
 180         new->wait_time_min = ULLONG_MAX;
 181
 182         list_add(&new->hash_entry, entry);
 183         return new;
 184
 185 alloc_failed:
 186         die("memory allocation failed\n");
 187 }
 188
 189 static char                     const *input_name = "perf.data";
 190
 191 static int                      profile_cpu = -1;
 192
 193 struct raw_event_sample {
 194         u32                     size;
 195         char                    data[0];
 196 };
 197
 198 struct trace_acquire_event {
 199         void                    *addr;
 200         const char              *name;
 201 };
 202
 203 struct trace_acquired_event {
 204         void                    *addr;
 205         const char              *name;
 206 };
 207
 208 struct trace_contended_event {
 209         void                    *addr;
 210         const char              *name;
 211 };
 212
 213 struct trace_release_event {
 214         void                    *addr;
 215         const char              *name;
 216 };
 217
 218 struct trace_lock_handler {
 219         void (*acquire_event)(struct trace_acquire_event *,
 220                               struct event *,
 221                               int cpu,
 222                               u64 timestamp,
 223                               struct thread *thread);
 224
 225         void (*acquired_event)(struct trace_acquired_event *,
 226                                struct event *,
 227                                int cpu,
 228                                u64 timestamp,
 229                                struct thread *thread);
 230
 231         void (*contended_event)(struct trace_contended_event *,
 232                                 struct event *,
 233                                 int cpu,
 234                                 u64 timestamp,
 235                                 struct thread *thread);
 236
 237         void (*release_event)(struct trace_release_event *,
 238                               struct event *,
 239                               int cpu,
 240                               u64 timestamp,
 241                               struct thread *thread);
 242 };
 243
 244 static void
 245 report_lock_acquire_event(struct trace_acquire_event *acquire_event,
 246                         struct event *__event __used,
 247                         int cpu __used,
 248                         u64 timestamp,
 249                         struct thread *thread __used)
 250 {
 251         struct lock_stat *st;
 252
 253         st = lock_stat_findnew(acquire_event->addr, acquire_event->name);
 254
 255         switch (st->state) {
 256         case LOCK_STATE_UNLOCKED:
 257                 break;
 258         case LOCK_STATE_LOCKED:
 259                 break;
 260         default:
 261                 BUG_ON(1);
 262                 break;
 263         }
 264
 265         st->prev_event_time = timestamp;
 266 }
 267
 268 static void
 269 report_lock_acquired_event(struct trace_acquired_event *acquired_event,
 270                          struct event *__event __used,
 271                          int cpu __used,
 272                          u64 timestamp,
 273                          struct thread *thread __used)
 274 {
 275         struct lock_stat *st;
 276
 277         st = lock_stat_findnew(acquired_event->addr, acquired_event->name);
 278
 279         switch (st->state) {
 280         case LOCK_STATE_UNLOCKED:
 281                 st->state = LOCK_STATE_LOCKED;
 282                 st->nr_acquired++;
 283                 break;
 284         case LOCK_STATE_LOCKED:
 285                 break;
 286         default:
 287                 BUG_ON(1);
 288                 break;
 289         }
 290
 291         st->prev_event_time = timestamp;
 292 }
 293
 294 static void
 295 report_lock_contended_event(struct trace_contended_event *contended_event,
 296                           struct event *__event __used,
 297                           int cpu __used,
 298                           u64 timestamp,
 299                           struct thread *thread __used)
 300 {
 301         struct lock_stat *st;
 302
 303         st = lock_stat_findnew(contended_event->addr, contended_event->name);
 304
 305         switch (st->state) {
 306         case LOCK_STATE_UNLOCKED:
 307                 break;
 308         case LOCK_STATE_LOCKED:
 309                 st->nr_contended++;
 310                 break;
 311         default:
 312                 BUG_ON(1);
 313                 break;
 314         }
 315
 316         st->prev_event_time = timestamp;
 317 }
 318
 319 static void
 320 report_lock_release_event(struct trace_release_event *release_event,
 321                         struct event *__event __used,
 322                         int cpu __used,
 323                         u64 timestamp,
 324                         struct thread *thread __used)
 325 {
 326         struct lock_stat *st;
 327         u64 hold_time;
 328
 329         st = lock_stat_findnew(release_event->addr, release_event->name);
 330
 331         switch (st->state) {
 332         case LOCK_STATE_UNLOCKED:
 333                 break;
 334         case LOCK_STATE_LOCKED:
 335                 st->state = LOCK_STATE_UNLOCKED;
 336                 hold_time = timestamp - st->prev_event_time;
 337
 338                 if (timestamp < st->prev_event_time) {
 339                         /* terribly, this can happen... */
 340                         goto end;
 341                 }
 342
 343                 if (st->wait_time_min > hold_time)
 344                         st->wait_time_min = hold_time;
 345                 if (st->wait_time_max < hold_time)
 346                         st->wait_time_max = hold_time;
 347                 st->wait_time_total += hold_time;
 348
 349                 st->nr_release++;
 350                 break;
 351         default:
 352                 BUG_ON(1);
 353                 break;
 354         }
 355
 356 end:
 357         st->prev_event_time = timestamp;
 358 }
 359
 360 /* lock oriented handlers */
 361 /* TODO: handlers for CPU oriented, thread oriented */
 362 static struct trace_lock_handler report_lock_ops  = {
 363         .acquire_event          = report_lock_acquire_event,
 364         .acquired_event         = report_lock_acquired_event,
 365         .contended_event        = report_lock_contended_event,
 366         .release_event          = report_lock_release_event,
 367 };
 368
 369 static struct trace_lock_handler *trace_handler;
 370
 371 static void
 372 process_lock_acquire_event(void *data,
 373                            struct event *event __used,
 374                            int cpu __used,
 375                            u64 timestamp __used,
 376                            struct thread *thread __used)
 377 {
 378         struct trace_acquire_event acquire_event;
 379         u64 tmp;                /* this is required for casting... */
 380
 381         tmp = raw_field_value(event, "lockdep_addr", data);
 382         memcpy(&acquire_event.addr, &tmp, sizeof(void *));
 383         acquire_event.name = (char *)raw_field_ptr(event, "name", data);
 384
 385         if (trace_handler->acquire_event)
 386                 trace_handler->acquire_event(&acquire_event, event, cpu, timestamp, thread);
 387 }
 388
 389 static void
 390 process_lock_acquired_event(void *data,
 391                             struct event *event __used,
 392                             int cpu __used,
 393                             u64 timestamp __used,
 394                             struct thread *thread __used)
 395 {
 396         struct trace_acquired_event acquired_event;
 397         u64 tmp;                /* this is required for casting... */
 398
 399         tmp = raw_field_value(event, "lockdep_addr", data);
 400         memcpy(&acquired_event.addr, &tmp, sizeof(void *));
 401         acquired_event.name = (char *)raw_field_ptr(event, "name", data);
 402
 403         if (trace_handler->acquire_event)
 404                 trace_handler->acquired_event(&acquired_event, event, cpu, timestamp, thread);
 405 }
 406
 407 static void
 408 process_lock_contended_event(void *data,
 409                              struct event *event __used,
 410                              int cpu __used,
 411                              u64 timestamp __used,
 412                              struct thread *thread __used)
 413 {
 414         struct trace_contended_event contended_event;
 415         u64 tmp;                /* this is required for casting... */
 416
 417         tmp = raw_field_value(event, "lockdep_addr", data);
 418         memcpy(&contended_event.addr, &tmp, sizeof(void *));
 419         contended_event.name = (char *)raw_field_ptr(event, "name", data);
 420
 421         if (trace_handler->acquire_event)
 422                 trace_handler->contended_event(&contended_event, event, cpu, timestamp, thread);
 423 }
 424
 425 static void
 426 process_lock_release_event(void *data,
 427                            struct event *event __used,
 428                            int cpu __used,
 429                            u64 timestamp __used,
 430                            struct thread *thread __used)
 431 {
 432         struct trace_release_event release_event;
 433         u64 tmp;                /* this is required for casting... */
 434
 435         tmp = raw_field_value(event, "lockdep_addr", data);
 436         memcpy(&release_event.addr, &tmp, sizeof(void *));
 437         release_event.name = (char *)raw_field_ptr(event, "name", data);
 438
 439         if (trace_handler->acquire_event)
 440                 trace_handler->release_event(&release_event, event, cpu, timestamp, thread);
 441 }
 442
 443 static void
 444 process_raw_event(void *data, int cpu,
 445                   u64 timestamp, struct thread *thread)
 446 {
 447         struct event *event;
 448         int type;
 449
 450         type = trace_parse_common_type(data);
 451         event = trace_find_event(type);
 452
 453         if (!strcmp(event->name, "lock_acquire"))
 454                 process_lock_acquire_event(data, event, cpu, timestamp, thread);
 455         if (!strcmp(event->name, "lock_acquired"))
 456                 process_lock_acquired_event(data, event, cpu, timestamp, thread);
 457         if (!strcmp(event->name, "lock_contended"))
 458                 process_lock_contended_event(data, event, cpu, timestamp, thread);
 459         if (!strcmp(event->name, "lock_release"))
 460                 process_lock_release_event(data, event, cpu, timestamp, thread);
 461 }
 462
 463 static int process_sample_event(event_t *event, struct perf_session *session)
 464 {
 465         struct thread *thread;
 466         struct sample_data data;
 467
 468         bzero(&data, sizeof(struct sample_data));
 469         event__parse_sample(event, session->sample_type, &data);
 470         thread = perf_session__findnew(session, data.pid);
 471
 472         if (thread == NULL) {
 473                 pr_debug("problem processing %d event, skipping it.\n",
 474                          event->header.type);
 475                 return -1;
 476         }
 477
 478         dump_printf(" ... thread: %s:%d\n", thread->comm, thread->pid);
 479
 480         if (profile_cpu != -1 && profile_cpu != (int) data.cpu)
 481                 return 0;
 482
 483         process_raw_event(data.raw_data, data.cpu, data.time, thread);
 484
 485         return 0;
 486 }
 487
 488 /* TODO: various way to print, coloring, nano or milli sec */
 489 static void print_result(void)
 490 {
 491         struct lock_stat *st;
 492         char cut_name[20];
 493
 494         printf("%18s ", "ID");
 495         printf("%20s ", "Name");
 496         printf("%10s ", "acquired");
 497         printf("%10s ", "contended");
 498
 499         printf("%15s ", "total wait (ns)");
 500         printf("%15s ", "max wait (ns)");
 501         printf("%15s ", "min wait (ns)");
 502
 503         printf("\n\n");
 504
 505         while ((st = pop_from_result())) {
 506                 bzero(cut_name, 20);
 507
 508                 printf("%p ", st->addr);
 509
 510                 if (strlen(st->name) < 16) {
 511                         /* output raw name */
 512                         printf("%20s ", st->name);
 513                 } else {
 514                         strncpy(cut_name, st->name, 16);
 515                         cut_name[16] = '.';
 516                         cut_name[17] = '.';
 517                         cut_name[18] = '.';
 518                         cut_name[19] = '\0';
 519                         /* cut off name for saving output style */
 520                         printf("%20s ", cut_name);
 521                 }
 522
 523                 printf("%10u ", st->nr_acquired);
 524                 printf("%10u ", st->nr_contended);
 525
 526                 printf("%15llu ", st->wait_time_total);
 527                 printf("%15llu ", st->wait_time_max);
 528                 printf("%15llu ", st->wait_time_min == ULLONG_MAX ?
 529                        0 : st->wait_time_min);
 530                 printf("\n");
 531         }
 532 }
 533
 534 static void dump_map(void)
 535 {
 536         unsigned int i;
 537         struct lock_stat *st;
 538
 539         for (i = 0; i < LOCKHASH_SIZE; i++) {
 540                 list_for_each_entry(st, &lockhash_table[i], hash_entry) {
 541                         printf("%p: %s\n", st->addr, st->name);
 542                 }
 543         }
 544 }
 545
 546 static struct perf_event_ops eops = {
 547         .sample                 = process_sample_event,
 548         .comm                   = event__process_comm,
 549 };
 550
 551 static struct perf_session *session;
 552
 553 static int read_events(void)
 554 {
 555         session = perf_session__new(input_name, O_RDONLY, 0);
 556         if (!session)
 557                 die("Initializing perf session failed\n");
 558
 559         return perf_session__process_events(session, &eops);
 560 }
 561
 562 static void sort_result(void)
 563 {
 564         unsigned int i;
 565         struct lock_stat *st;
 566
 567         for (i = 0; i < LOCKHASH_SIZE; i++) {
 568                 list_for_each_entry(st, &lockhash_table[i], hash_entry) {
 569                         insert_to_result(st, compare);
 570                 }
 571         }
 572 }
 573
 574 static void __cmd_report(void)
 575 {
 576         setup_pager();
 577         select_key();
 578         read_events();
 579         sort_result();
 580         print_result();
 581 }
 582
 583 static const char * const report_usage[] = {
 584         "perf lock report [<options>]",
 585         NULL
 586 };
 587
 588 static const struct option report_options[] = {
 589         OPT_STRING('k', "key", &sort_key, "acquired",
 590                     "key for sorting"),
 591         /* TODO: type */
 592         OPT_END()
 593 };
 594
 595 static const char * const lock_usage[] = {
 596         "perf lock [<options>] {record|trace|report}",
 597         NULL
 598 };
 599
 600 static const struct option lock_options[] = {
 601         OPT_STRING('i', "input", &input_name, "file", "input file name"),
 602         OPT_BOOLEAN('v', "verbose", &verbose, "be more verbose (show symbol address, etc)"),
 603         OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace, "dump raw trace in ASCII"),
 604         OPT_END()
 605 };
 606
 607 static const char *record_args[] = {
 608         "record",
 609         "-a",
 610         "-R",
 611         "-M",
 612         "-f",
 613         "-m", "1024",
 614         "-c", "1",
 615         "-e", "lock:lock_acquire:r",
 616         "-e", "lock:lock_acquired:r",
 617         "-e", "lock:lock_contended:r",
 618         "-e", "lock:lock_release:r",
 619 };
 620
 621 static int __cmd_record(int argc, const char **argv)
 622 {
 623         unsigned int rec_argc, i, j;
 624         const char **rec_argv;
 625
 626         rec_argc = ARRAY_SIZE(record_args) + argc - 1;
 627         rec_argv = calloc(rec_argc + 1, sizeof(char *));
 628
 629         for (i = 0; i < ARRAY_SIZE(record_args); i++)
 630                 rec_argv[i] = strdup(record_args[i]);
 631
 632         for (j = 1; j < (unsigned int)argc; j++, i++)
 633                 rec_argv[i] = argv[j];
 634
 635         BUG_ON(i != rec_argc);
 636
 637         return cmd_record(i, rec_argv, NULL);
 638 }
 639
 640 int cmd_lock(int argc, const char **argv, const char *prefix __used)
 641 {
 642         unsigned int i;
 643
 644         symbol__init();
 645         for (i = 0; i < LOCKHASH_SIZE; i++)
 646                 INIT_LIST_HEAD(lockhash_table + i);
 647
 648         argc = parse_options(argc, argv, lock_options, lock_usage,
 649                              PARSE_OPT_STOP_AT_NON_OPTION);
 650         if (!argc)
 651                 usage_with_options(lock_usage, lock_options);
 652
 653         if (!strncmp(argv[0], "rec", 3)) {
 654                 return __cmd_record(argc, argv);
 655         } else if (!strncmp(argv[0], "report", 6)) {
 656                 trace_handler = &report_lock_ops;
 657                 if (argc) {
 658                         argc = parse_options(argc, argv,
 659                                              report_options, report_usage, 0);
 660                         if (argc)
 661                                 usage_with_options(report_usage, report_options);
 662                 }
 663                 __cmd_report();
 664         } else if (!strcmp(argv[0], "trace")) {
 665                 /* Aliased to 'perf trace' */
 666                 return cmd_trace(argc, argv, prefix);
 667         } else if (!strcmp(argv[0], "map")) {
 668                 /* recycling report_lock_ops */
 669                 trace_handler = &report_lock_ops;
 670                 setup_pager();
 671                 read_events();
 672                 dump_map();
 673         } else {
 674                 usage_with_options(lock_usage, lock_options);
 675         }
 676
 677         return 0;
 678 }