SAFE public projects git trees. - safe/jmp/linux-2.6/blob - 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         /* FIXME: raw_field_value() returns unsigned long long,
  43          * so address of lockdep_map should be dealed as 64bit.
  44          * Is there more better solution? */
  45         void *addr;            /* address of lockdep_map, used as ID */
  46         char *name;            /* for strcpy(), we cannot use const */
  47         char *file;
  48         unsigned int line;
  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 static int (*compare)(struct lock_stat *, struct lock_stat *);
  90
  91 #define DEF_KEY_LOCK(name, fn_suffix)   \
  92         { #name, lock_stat_key_ ## fn_suffix }
  93 struct lock_key keys[] = {
  94         DEF_KEY_LOCK(acquired, nr_acquired),
  95         DEF_KEY_LOCK(contended, nr_contended),
  96         DEF_KEY_LOCK(wait_total, wait_time_total),
  97         DEF_KEY_LOCK(wait_min, wait_time_min),
  98         DEF_KEY_LOCK(wait_max, wait_time_max),
  99
 100         /* extra comparisons much complicated should be here */
 101
 102         { NULL, NULL }
 103 };
 104
 105 static void select_key(void)
 106 {
 107         int i;
 108
 109         for (i = 0; keys[i].name; i++) {
 110                 if (!strcmp(keys[i].name, sort_key)) {
 111                         compare = keys[i].key;
 112                         return;
 113                 }
 114         }
 115
 116         die("Unknown compare key:%s\n", sort_key);
 117 }
 118
 119 static struct rb_root result;   /* place to store sorted data */
 120
 121 static void insert_to_result(struct lock_stat *st,
 122                              int (*bigger)(struct lock_stat *,
 123                                            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                                            const char *file, unsigned int line)
 160 {
 161         struct list_head *entry = lockhashentry(addr);
 162         struct lock_stat *ret, *new;
 163
 164         list_for_each_entry(ret, entry, hash_entry) {
 165                 if (ret->addr == addr)
 166                         return ret;
 167         }
 168
 169         new = zalloc(sizeof(struct lock_stat));
 170         if (!new)
 171                 goto alloc_failed;
 172
 173         new->addr = addr;
 174         new->name = zalloc(sizeof(char) * strlen(name) + 1);
 175         if (!new->name)
 176                 goto alloc_failed;
 177         strcpy(new->name, name);
 178         new->file = zalloc(sizeof(char) * strlen(file) + 1);
 179         if (!new->file)
 180                 goto alloc_failed;
 181         strcpy(new->file, file);
 182         new->line = line;
 183
 184         /* LOCK_STATE_UNLOCKED == 0 isn't guaranteed forever */
 185         new->state = LOCK_STATE_UNLOCKED;
 186         new->wait_time_min = ULLONG_MAX;
 187
 188         list_add(&new->hash_entry, entry);
 189         return new;
 190
 191 alloc_failed:
 192         die("memory allocation failed\n");
 193 }
 194
 195 static char                     const *input_name = "perf.data";
 196
 197 static int                      profile_cpu = -1;
 198
 199 struct raw_event_sample {
 200         u32 size;
 201         char data[0];
 202 };
 203
 204 struct trace_acquire_event {
 205         void *addr;
 206         const char *name;
 207         const char *file;
 208         unsigned int line;
 209 };
 210
 211 struct trace_acquired_event {
 212         void *addr;
 213         const char *name;
 214         const char *file;
 215         unsigned int line;
 216 };
 217
 218 struct trace_contended_event {
 219         void *addr;
 220         const char *name;
 221         const char *file;
 222         unsigned int line;
 223 };
 224
 225 struct trace_release_event {
 226         void *addr;
 227         const char *name;
 228         const char *file;
 229         unsigned int line;
 230 };
 231
 232 struct trace_lock_handler {
 233         void (*acquire_event)(struct trace_acquire_event *,
 234                               struct event *,
 235                               int cpu,
 236                               u64 timestamp,
 237                               struct thread *thread);
 238
 239         void (*acquired_event)(struct trace_acquired_event *,
 240                                struct event *,
 241                                int cpu,
 242                                u64 timestamp,
 243                                struct thread *thread);
 244
 245         void (*contended_event)(struct trace_contended_event *,
 246                                 struct event *,
 247                                 int cpu,
 248                                 u64 timestamp,
 249                                 struct thread *thread);
 250
 251         void (*release_event)(struct trace_release_event *,
 252                               struct event *,
 253                               int cpu,
 254                               u64 timestamp,
 255                               struct thread *thread);
 256 };
 257
 258 static void prof_lock_acquire_event(struct trace_acquire_event *acquire_event,
 259                         struct event *__event __used,
 260                         int cpu __used,
 261                         u64 timestamp,
 262                         struct thread *thread __used)
 263 {
 264         struct lock_stat *st;
 265
 266         st = lock_stat_findnew(acquire_event->addr, acquire_event->name,
 267                                acquire_event->file, acquire_event->line);
 268
 269         switch (st->state) {
 270         case LOCK_STATE_UNLOCKED:
 271                 break;
 272         case LOCK_STATE_LOCKED:
 273                 break;
 274         default:
 275                 BUG_ON(1);
 276                 break;
 277         }
 278
 279         st->prev_event_time = timestamp;
 280 }
 281
 282 static void prof_lock_acquired_event(struct trace_acquired_event *acquired_event,
 283                          struct event *__event __used,
 284                          int cpu __used,
 285                          u64 timestamp,
 286                          struct thread *thread __used)
 287 {
 288         struct lock_stat *st;
 289
 290         st = lock_stat_findnew(acquired_event->addr, acquired_event->name,
 291                                acquired_event->file, acquired_event->line);
 292
 293         switch (st->state) {
 294         case LOCK_STATE_UNLOCKED:
 295                 st->state = LOCK_STATE_LOCKED;
 296                 st->nr_acquired++;
 297                 break;
 298         case LOCK_STATE_LOCKED:
 299                 break;
 300         default:
 301                 BUG_ON(1);
 302                 break;
 303         }
 304
 305         st->prev_event_time = timestamp;
 306 }
 307
 308 static void prof_lock_contended_event(struct trace_contended_event *contended_event,
 309                           struct event *__event __used,
 310                           int cpu __used,
 311                           u64 timestamp,
 312                           struct thread *thread __used)
 313 {
 314         struct lock_stat *st;
 315
 316         st = lock_stat_findnew(contended_event->addr, contended_event->name,
 317                                contended_event->file, contended_event->line);
 318
 319         switch (st->state) {
 320         case LOCK_STATE_UNLOCKED:
 321                 break;
 322         case LOCK_STATE_LOCKED:
 323                 st->nr_contended++;
 324                 break;
 325         default:
 326                 BUG_ON(1);
 327                 break;
 328         }
 329
 330         st->prev_event_time = timestamp;
 331 }
 332
 333 static void prof_lock_release_event(struct trace_release_event *release_event,
 334                         struct event *__event __used,
 335                         int cpu __used,
 336                         u64 timestamp,
 337                         struct thread *thread __used)
 338 {
 339         struct lock_stat *st;
 340         u64 hold_time;
 341
 342         st = lock_stat_findnew(release_event->addr, release_event->name,
 343                                release_event->file, release_event->line);
 344
 345         switch (st->state) {
 346         case LOCK_STATE_UNLOCKED:
 347                 break;
 348         case LOCK_STATE_LOCKED:
 349                 st->state = LOCK_STATE_UNLOCKED;
 350                 hold_time = timestamp - st->prev_event_time;
 351
 352                 if (timestamp < st->prev_event_time) {
 353                         /* terribly, this can happen... */
 354                         goto end;
 355                 }
 356
 357                 if (st->wait_time_min > hold_time)
 358                         st->wait_time_min = hold_time;
 359                 if (st->wait_time_max < hold_time)
 360                         st->wait_time_max = hold_time;
 361                 st->wait_time_total += hold_time;
 362
 363                 st->nr_release++;
 364                 break;
 365         default:
 366                 BUG_ON(1);
 367                 break;
 368         }
 369
 370 end:
 371         st->prev_event_time = timestamp;
 372 }
 373
 374 /* lock oriented handlers */
 375 /* TODO: handlers for CPU oriented, thread oriented */
 376 static struct trace_lock_handler prof_lock_ops  = {
 377         .acquire_event          = prof_lock_acquire_event,
 378         .acquired_event         = prof_lock_acquired_event,
 379         .contended_event        = prof_lock_contended_event,
 380         .release_event          = prof_lock_release_event,
 381 };
 382
 383 static struct trace_lock_handler *trace_handler;
 384
 385 static void
 386 process_lock_acquire_event(void *data,
 387                            struct event *event __used,
 388                            int cpu __used,
 389                            u64 timestamp __used,
 390                            struct thread *thread __used)
 391 {
 392         struct trace_acquire_event acquire_event;
 393         u64 tmp;                /* this is required for casting... */
 394
 395         tmp = raw_field_value(event, "lockdep_addr", data);
 396         memcpy(&acquire_event.addr, &tmp, sizeof(void *));
 397         acquire_event.name = (char *)raw_field_ptr(event, "name", data);
 398         acquire_event.file = (char *)raw_field_ptr(event, "file", data);
 399         acquire_event.line =
 400                 (unsigned int)raw_field_value(event, "line", data);
 401
 402         if (trace_handler->acquire_event) {
 403                 trace_handler->acquire_event(&acquire_event,
 404                                              event, cpu, timestamp, thread);
 405         }
 406 }
 407
 408 static void
 409 process_lock_acquired_event(void *data,
 410                             struct event *event __used,
 411                             int cpu __used,
 412                             u64 timestamp __used,
 413                             struct thread *thread __used)
 414 {
 415         struct trace_acquired_event acquired_event;
 416         u64 tmp;                /* this is required for casting... */
 417
 418         tmp = raw_field_value(event, "lockdep_addr", data);
 419         memcpy(&acquired_event.addr, &tmp, sizeof(void *));
 420         acquired_event.name = (char *)raw_field_ptr(event, "name", data);
 421         acquired_event.file = (char *)raw_field_ptr(event, "file", data);
 422         acquired_event.line =
 423                 (unsigned int)raw_field_value(event, "line", data);
 424
 425         if (trace_handler->acquire_event) {
 426                 trace_handler->acquired_event(&acquired_event,
 427                                              event, cpu, timestamp, thread);
 428         }
 429 }
 430
 431 static void
 432 process_lock_contended_event(void *data,
 433                              struct event *event __used,
 434                              int cpu __used,
 435                              u64 timestamp __used,
 436                              struct thread *thread __used)
 437 {
 438         struct trace_contended_event contended_event;
 439         u64 tmp;                /* this is required for casting... */
 440
 441         tmp = raw_field_value(event, "lockdep_addr", data);
 442         memcpy(&contended_event.addr, &tmp, sizeof(void *));
 443         contended_event.name = (char *)raw_field_ptr(event, "name", data);
 444         contended_event.file = (char *)raw_field_ptr(event, "file", data);
 445         contended_event.line =
 446                 (unsigned int)raw_field_value(event, "line", data);
 447
 448         if (trace_handler->acquire_event) {
 449                 trace_handler->contended_event(&contended_event,
 450                                              event, cpu, timestamp, thread);
 451         }
 452 }
 453
 454 static void
 455 process_lock_release_event(void *data,
 456                            struct event *event __used,
 457                            int cpu __used,
 458                            u64 timestamp __used,
 459                            struct thread *thread __used)
 460 {
 461         struct trace_release_event release_event;
 462         u64 tmp;                /* this is required for casting... */
 463
 464         tmp = raw_field_value(event, "lockdep_addr", data);
 465         memcpy(&release_event.addr, &tmp, sizeof(void *));
 466         release_event.name = (char *)raw_field_ptr(event, "name", data);
 467         release_event.file = (char *)raw_field_ptr(event, "file", data);
 468         release_event.line =
 469                 (unsigned int)raw_field_value(event, "line", data);
 470
 471         if (trace_handler->acquire_event) {
 472                 trace_handler->release_event(&release_event,
 473                                              event, cpu, timestamp, thread);
 474         }
 475 }
 476
 477 static void
 478 process_raw_event(void *data, int cpu,
 479                   u64 timestamp, struct thread *thread)
 480 {
 481         struct event *event;
 482         int type;
 483
 484         type = trace_parse_common_type(data);
 485         event = trace_find_event(type);
 486
 487         if (!strcmp(event->name, "lock_acquire"))
 488                 process_lock_acquire_event(data, event, cpu, timestamp, thread);
 489         if (!strcmp(event->name, "lock_acquired"))
 490                 process_lock_acquired_event(data, event, cpu, timestamp, thread);
 491         if (!strcmp(event->name, "lock_contended"))
 492                 process_lock_contended_event(data, event, cpu, timestamp, thread);
 493         if (!strcmp(event->name, "lock_release"))
 494                 process_lock_release_event(data, event, cpu, timestamp, thread);
 495 }
 496
 497 static int process_sample_event(event_t *event, struct perf_session *session)
 498 {
 499         struct thread *thread;
 500         struct sample_data data;
 501
 502         bzero(&data, sizeof(struct sample_data));
 503         event__parse_sample(event, session->sample_type, &data);
 504         thread = perf_session__findnew(session, data.pid);
 505
 506         /*
 507          * FIXME: this causes warn on 32bit environment
 508          * because of (void *)data.ip (type of data.ip is u64)
 509          */
 510 /*      dump_printf("(IP, %d): %d/%d: %p period: %llu\n", */
 511 /*                  event->header.misc, */
 512 /*                  data.pid, data.tid, (void *)data.ip, data.period); */
 513
 514         if (thread == NULL) {
 515                 pr_debug("problem processing %d event, skipping it.\n",
 516                          event->header.type);
 517                 return -1;
 518         }
 519
 520         dump_printf(" ... thread: %s:%d\n", thread->comm, thread->pid);
 521
 522         if (profile_cpu != -1 && profile_cpu != (int) data.cpu)
 523                 return 0;
 524
 525         process_raw_event(data.raw_data, data.cpu, data.time, thread);
 526
 527         return 0;
 528 }
 529
 530 /* TODO: various way to print, coloring, nano or milli sec */
 531 static void print_result(void)
 532 {
 533         struct lock_stat *st;
 534         char cut_name[20];
 535
 536         printf("%18s ", "ID");
 537         printf("%20s ", "Name");
 538         printf("%10s ", "acquired");
 539         printf("%10s ", "contended");
 540
 541         printf("%15s ", "total wait (ns)");
 542         printf("%15s ", "max wait (ns)");
 543         printf("%15s ", "min wait (ns)");
 544
 545         printf("\n\n");
 546
 547         while ((st = pop_from_result())) {
 548                 bzero(cut_name, 20);
 549
 550                 printf("%p ", st->addr);
 551
 552                 if (strlen(st->name) < 16) {
 553                         /* output raw name */
 554                         printf("%20s ", st->name);
 555                 } else {
 556                         strncpy(cut_name, st->name, 16);
 557                         cut_name[16] = '.';
 558                         cut_name[17] = '.';
 559                         cut_name[18] = '.';
 560                         cut_name[19] = '\0';
 561                         /* cut off name for saving output style */
 562                         printf("%20s ", cut_name);
 563                 }
 564
 565                 printf("%10u ", st->nr_acquired);
 566                 printf("%10u ", st->nr_contended);
 567
 568                 printf("%15llu ", st->wait_time_total);
 569                 printf("%15llu ", st->wait_time_max);
 570                 printf("%15llu ", st->wait_time_min == ULLONG_MAX ?
 571                        0 : st->wait_time_min);
 572                 printf("\n");
 573         }
 574 }
 575
 576 static void dump_map(void)
 577 {
 578         unsigned int i;
 579         struct lock_stat *st;
 580
 581         for (i = 0; i < LOCKHASH_SIZE; i++) {
 582                 list_for_each_entry(st, &lockhash_table[i], hash_entry) {
 583                         printf("%p: %s (src: %s, line: %u)\n",
 584                                st->addr, st->name, st->file, st->line);
 585                 }
 586         }
 587 }
 588
 589 static struct perf_event_ops eops = {
 590         .sample = process_sample_event,
 591         .comm   = event__process_comm,
 592 };
 593
 594 static struct perf_session *session;
 595
 596 static int read_events(void)
 597 {
 598         session = perf_session__new(input_name, O_RDONLY, 0);
 599         if (!session)
 600                 die("Initializing perf session failed\n");
 601
 602         return perf_session__process_events(session, &eops);
 603 }
 604
 605 static void sort_result(void)
 606 {
 607         unsigned int i;
 608         struct lock_stat *st;
 609
 610         for (i = 0; i < LOCKHASH_SIZE; i++) {
 611                 list_for_each_entry(st, &lockhash_table[i], hash_entry) {
 612                         insert_to_result(st, compare);
 613                 }
 614         }
 615 }
 616
 617 static void __cmd_prof(void)
 618 {
 619         setup_pager();
 620         select_key();
 621         read_events();
 622         sort_result();
 623         print_result();
 624 }
 625
 626 static const char * const prof_usage[] = {
 627         "perf sched prof [<options>]",
 628         NULL
 629 };
 630
 631 static const struct option prof_options[] = {
 632         OPT_STRING('k', "key", &sort_key, "acquired",
 633                     "key for sorting"),
 634         /* TODO: type */
 635         OPT_END()
 636 };
 637
 638 static const char * const lock_usage[] = {
 639         "perf lock [<options>] {record|trace|prof}",
 640         NULL
 641 };
 642
 643 static const struct option lock_options[] = {
 644         OPT_STRING('i', "input", &input_name, "file",
 645                     "input file name"),
 646         OPT_BOOLEAN('v', "verbose", &verbose,
 647                     "be more verbose (show symbol address, etc)"),
 648         OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
 649                     "dump raw trace in ASCII"),
 650         OPT_END()
 651 };
 652
 653 static const char *record_args[] = {
 654         "record",
 655         "-a",
 656         "-R",
 657         "-M",
 658         "-f",
 659         "-m", "1024",
 660         "-c", "1",
 661         "-e", "lock:lock_acquire:r",
 662         "-e", "lock:lock_acquired:r",
 663         "-e", "lock:lock_contended:r",
 664         "-e", "lock:lock_release:r",
 665 };
 666
 667 static int __cmd_record(int argc, const char **argv)
 668 {
 669         unsigned int rec_argc, i, j;
 670         const char **rec_argv;
 671
 672         rec_argc = ARRAY_SIZE(record_args) + argc - 1;
 673         rec_argv = calloc(rec_argc + 1, sizeof(char *));
 674
 675         for (i = 0; i < ARRAY_SIZE(record_args); i++)
 676                 rec_argv[i] = strdup(record_args[i]);
 677
 678         for (j = 1; j < (unsigned int)argc; j++, i++)
 679                 rec_argv[i] = argv[j];
 680
 681         BUG_ON(i != rec_argc);
 682
 683         return cmd_record(i, rec_argv, NULL);
 684 }
 685
 686 int cmd_lock(int argc, const char **argv, const char *prefix __used)
 687 {
 688         unsigned int i;
 689
 690         symbol__init();
 691         for (i = 0; i < LOCKHASH_SIZE; i++)
 692                 INIT_LIST_HEAD(lockhash_table + i);
 693
 694         argc = parse_options(argc, argv, lock_options, lock_usage,
 695                              PARSE_OPT_STOP_AT_NON_OPTION);
 696         if (!argc)
 697                 usage_with_options(lock_usage, lock_options);
 698
 699         if (!strncmp(argv[0], "rec", 3)) {
 700                 return __cmd_record(argc, argv);
 701         } else if (!strncmp(argv[0], "prof", 4)) {
 702                 trace_handler = &prof_lock_ops;
 703                 if (argc) {
 704                         argc = parse_options(argc, argv,
 705                                              prof_options, prof_usage, 0);
 706                         if (argc)
 707                                 usage_with_options(prof_usage, prof_options);
 708                 }
 709                 __cmd_prof();
 710         } else if (!strcmp(argv[0], "trace")) {
 711                 /* Aliased to 'perf trace' */
 712                 return cmd_trace(argc, argv, prefix);
 713         } else if (!strcmp(argv[0], "map")) {
 714                 /* recycling prof_lock_ops */
 715                 trace_handler = &prof_lock_ops;
 716                 setup_pager();
 717                 read_events();
 718                 dump_map();
 719         } else {
 720                 usage_with_options(lock_usage, lock_options);
 721         }
 722
 723         return 0;
 724 }