tools/perf/builtin-trace.c

   1 #include <traceevent/event-parse.h>
   2 #include "builtin.h"
   3 #include "util/color.h"
   4 #include "util/debug.h"
   5 #include "util/evlist.h"
   6 #include "util/machine.h"
   7 #include "util/thread.h"
   8 #include "util/parse-options.h"
   9 #include "util/strlist.h"
  10 #include "util/thread_map.h"
  11
  12 #include <libaudit.h>
  13 #include <stdlib.h>
  14 #include <sys/mman.h>
  15
  16 static size_t syscall_arg__scnprintf_hex(char *bf, size_t size, unsigned long arg)
  17 {
  18         return scnprintf(bf, size, "%#lx", arg);
  19 }
  20
  21 #define SCA_HEX syscall_arg__scnprintf_hex
  22
  23 static size_t syscall_arg__scnprintf_mmap_prot(char *bf, size_t size, unsigned long arg)
  24 {
  25         int printed = 0, prot = arg;
  26
  27         if (prot == PROT_NONE)
  28                 return scnprintf(bf, size, "NONE");
  29 #define P_MMAP_PROT(n) \
  30         if (prot & PROT_##n) { \
  31                 printed += scnprintf(bf + printed, size - printed, "%s%s", printed ? "|" : "", #n); \
  32                 prot &= ~PROT_##n; \
  33         }
  34
  35         P_MMAP_PROT(EXEC);
  36         P_MMAP_PROT(READ);
  37         P_MMAP_PROT(WRITE);
  38 #ifdef PROT_SEM
  39         P_MMAP_PROT(SEM);
  40 #endif
  41         P_MMAP_PROT(GROWSDOWN);
  42         P_MMAP_PROT(GROWSUP);
  43 #undef P_MMAP_PROT
  44
  45         if (prot)
  46                 printed += scnprintf(bf + printed, size - printed, "%s%#x", printed ? "|" : "", prot);
  47
  48         return printed;
  49 }
  50
  51 #define SCA_MMAP_PROT syscall_arg__scnprintf_mmap_prot
  52
  53 static struct syscall_fmt {
  54         const char *name;
  55         const char *alias;
  56         size_t     (*arg_scnprintf[6])(char *bf, size_t size, unsigned long arg);
  57         bool       errmsg;
  58         bool       timeout;
  59         bool       hexret;
  60 } syscall_fmts[] = {
  61         { .name     = "access",     .errmsg = true, },
  62         { .name     = "arch_prctl", .errmsg = true, .alias = "prctl", },
  63         { .name     = "brk",        .hexret = true,
  64           .arg_scnprintf = { [0] = SCA_HEX, /* brk */ }, },
  65         { .name     = "mmap",       .hexret = true, },
  66         { .name     = "connect",    .errmsg = true, },
  67         { .name     = "fstat",      .errmsg = true, .alias = "newfstat", },
  68         { .name     = "fstatat",    .errmsg = true, .alias = "newfstatat", },
  69         { .name     = "futex",      .errmsg = true, },
  70         { .name     = "ioctl",      .errmsg = true,
  71           .arg_scnprintf = { [2] = SCA_HEX, /* arg */ }, },
  72         { .name     = "lstat",      .errmsg = true, .alias = "newlstat", },
  73         { .name     = "mmap",       .hexret = true,
  74           .arg_scnprintf = { [0] = SCA_HEX,       /* addr */
  75                              [2] = SCA_MMAP_PROT, /* prot */ }, },
  76         { .name     = "mprotect",   .errmsg = true,
  77           .arg_scnprintf = { [0] = SCA_HEX, /* start */
  78                              [2] = SCA_MMAP_PROT, /* prot */ }, },
  79         { .name     = "mremap",     .hexret = true,
  80           .arg_scnprintf = { [0] = SCA_HEX, /* addr */
  81                              [4] = SCA_HEX, /* new_addr */ }, },
  82         { .name     = "munmap",     .errmsg = true,
  83           .arg_scnprintf = { [0] = SCA_HEX, /* addr */ }, },
  84         { .name     = "open",       .errmsg = true, },
  85         { .name     = "poll",       .errmsg = true, .timeout = true, },
  86         { .name     = "ppoll",      .errmsg = true, .timeout = true, },
  87         { .name     = "pread",      .errmsg = true, .alias = "pread64", },
  88         { .name     = "pwrite",     .errmsg = true, .alias = "pwrite64", },
  89         { .name     = "read",       .errmsg = true, },
  90         { .name     = "recvfrom",   .errmsg = true, },
  91         { .name     = "select",     .errmsg = true, .timeout = true, },
  92         { .name     = "socket",     .errmsg = true, },
  93         { .name     = "stat",       .errmsg = true, .alias = "newstat", },
  94         { .name     = "uname",      .errmsg = true, .alias = "newuname", },
  95 };
  96
  97 static int syscall_fmt__cmp(const void *name, const void *fmtp)
  98 {
  99         const struct syscall_fmt *fmt = fmtp;
 100         return strcmp(name, fmt->name);
 101 }
 102
 103 static struct syscall_fmt *syscall_fmt__find(const char *name)
 104 {
 105         const int nmemb = ARRAY_SIZE(syscall_fmts);
 106         return bsearch(name, syscall_fmts, nmemb, sizeof(struct syscall_fmt), syscall_fmt__cmp);
 107 }
 108
 109 struct syscall {
 110         struct event_format *tp_format;
 111         const char          *name;
 112         bool                filtered;
 113         struct syscall_fmt  *fmt;
 114         size_t              (**arg_scnprintf)(char *bf, size_t size, unsigned long arg);
 115 };
 116
 117 static size_t fprintf_duration(unsigned long t, FILE *fp)
 118 {
 119         double duration = (double)t / NSEC_PER_MSEC;
 120         size_t printed = fprintf(fp, "(");
 121
 122         if (duration >= 1.0)
 123                 printed += color_fprintf(fp, PERF_COLOR_RED, "%6.3f ms", duration);
 124         else if (duration >= 0.01)
 125                 printed += color_fprintf(fp, PERF_COLOR_YELLOW, "%6.3f ms", duration);
 126         else
 127                 printed += color_fprintf(fp, PERF_COLOR_NORMAL, "%6.3f ms", duration);
 128         return printed + fprintf(fp, "): ");
 129 }
 130
 131 struct thread_trace {
 132         u64               entry_time;
 133         u64               exit_time;
 134         bool              entry_pending;
 135         unsigned long     nr_events;
 136         char              *entry_str;
 137         double            runtime_ms;
 138 };
 139
 140 static struct thread_trace *thread_trace__new(void)
 141 {
 142         return zalloc(sizeof(struct thread_trace));
 143 }
 144
 145 static struct thread_trace *thread__trace(struct thread *thread, FILE *fp)
 146 {
 147         struct thread_trace *ttrace;
 148
 149         if (thread == NULL)
 150                 goto fail;
 151
 152         if (thread->priv == NULL)
 153                 thread->priv = thread_trace__new();
 154
 155         if (thread->priv == NULL)
 156                 goto fail;
 157
 158         ttrace = thread->priv;
 159         ++ttrace->nr_events;
 160
 161         return ttrace;
 162 fail:
 163         color_fprintf(fp, PERF_COLOR_RED,
 164                       "WARNING: not enough memory, dropping samples!\n");
 165         return NULL;
 166 }
 167
 168 struct trace {
 169         struct perf_tool        tool;
 170         int                     audit_machine;
 171         struct {
 172                 int             max;
 173                 struct syscall  *table;
 174         } syscalls;
 175         struct perf_record_opts opts;
 176         struct machine          host;
 177         u64                     base_time;
 178         FILE                    *output;
 179         unsigned long           nr_events;
 180         struct strlist          *ev_qualifier;
 181         bool                    not_ev_qualifier;
 182         bool                    sched;
 183         bool                    multiple_threads;
 184         double                  duration_filter;
 185         double                  runtime_ms;
 186 };
 187
 188 static bool trace__filter_duration(struct trace *trace, double t)
 189 {
 190         return t < (trace->duration_filter * NSEC_PER_MSEC);
 191 }
 192
 193 static size_t trace__fprintf_tstamp(struct trace *trace, u64 tstamp, FILE *fp)
 194 {
 195         double ts = (double)(tstamp - trace->base_time) / NSEC_PER_MSEC;
 196
 197         return fprintf(fp, "%10.3f ", ts);
 198 }
 199
 200 static bool done = false;
 201
 202 static void sig_handler(int sig __maybe_unused)
 203 {
 204         done = true;
 205 }
 206
 207 static size_t trace__fprintf_entry_head(struct trace *trace, struct thread *thread,
 208                                         u64 duration, u64 tstamp, FILE *fp)
 209 {
 210         size_t printed = trace__fprintf_tstamp(trace, tstamp, fp);
 211         printed += fprintf_duration(duration, fp);
 212
 213         if (trace->multiple_threads)
 214                 printed += fprintf(fp, "%d ", thread->tid);
 215
 216         return printed;
 217 }
 218
 219 static int trace__process_event(struct trace *trace, struct machine *machine,
 220                                 union perf_event *event)
 221 {
 222         int ret = 0;
 223
 224         switch (event->header.type) {
 225         case PERF_RECORD_LOST:
 226                 color_fprintf(trace->output, PERF_COLOR_RED,
 227                               "LOST %" PRIu64 " events!\n", event->lost.lost);
 228                 ret = machine__process_lost_event(machine, event);
 229         default:
 230                 ret = machine__process_event(machine, event);
 231                 break;
 232         }
 233
 234         return ret;
 235 }
 236
 237 static int trace__tool_process(struct perf_tool *tool,
 238                                union perf_event *event,
 239                                struct perf_sample *sample __maybe_unused,
 240                                struct machine *machine)
 241 {
 242         struct trace *trace = container_of(tool, struct trace, tool);
 243         return trace__process_event(trace, machine, event);
 244 }
 245
 246 static int trace__symbols_init(struct trace *trace, struct perf_evlist *evlist)
 247 {
 248         int err = symbol__init();
 249
 250         if (err)
 251                 return err;
 252
 253         machine__init(&trace->host, "", HOST_KERNEL_ID);
 254         machine__create_kernel_maps(&trace->host);
 255
 256         if (perf_target__has_task(&trace->opts.target)) {
 257                 err = perf_event__synthesize_thread_map(&trace->tool, evlist->threads,
 258                                                         trace__tool_process,
 259                                                         &trace->host);
 260         } else {
 261                 err = perf_event__synthesize_threads(&trace->tool, trace__tool_process,
 262                                                      &trace->host);
 263         }
 264
 265         if (err)
 266                 symbol__exit();
 267
 268         return err;
 269 }
 270
 271 static int syscall__set_arg_fmts(struct syscall *sc)
 272 {
 273         struct format_field *field;
 274         int idx = 0;
 275
 276         sc->arg_scnprintf = calloc(sc->tp_format->format.nr_fields - 1, sizeof(void *));
 277         if (sc->arg_scnprintf == NULL)
 278                 return -1;
 279
 280         for (field = sc->tp_format->format.fields->next; field; field = field->next) {
 281                 if (sc->fmt && sc->fmt->arg_scnprintf[idx])
 282                         sc->arg_scnprintf[idx] = sc->fmt->arg_scnprintf[idx];
 283                 else if (field->flags & FIELD_IS_POINTER)
 284                         sc->arg_scnprintf[idx] = syscall_arg__scnprintf_hex;
 285                 ++idx;
 286         }
 287
 288         return 0;
 289 }
 290
 291 static int trace__read_syscall_info(struct trace *trace, int id)
 292 {
 293         char tp_name[128];
 294         struct syscall *sc;
 295         const char *name = audit_syscall_to_name(id, trace->audit_machine);
 296
 297         if (name == NULL)
 298                 return -1;
 299
 300         if (id > trace->syscalls.max) {
 301                 struct syscall *nsyscalls = realloc(trace->syscalls.table, (id + 1) * sizeof(*sc));
 302
 303                 if (nsyscalls == NULL)
 304                         return -1;
 305
 306                 if (trace->syscalls.max != -1) {
 307                         memset(nsyscalls + trace->syscalls.max + 1, 0,
 308                                (id - trace->syscalls.max) * sizeof(*sc));
 309                 } else {
 310                         memset(nsyscalls, 0, (id + 1) * sizeof(*sc));
 311                 }
 312
 313                 trace->syscalls.table = nsyscalls;
 314                 trace->syscalls.max   = id;
 315         }
 316
 317         sc = trace->syscalls.table + id;
 318         sc->name = name;
 319
 320         if (trace->ev_qualifier) {
 321                 bool in = strlist__find(trace->ev_qualifier, name) != NULL;
 322
 323                 if (!(in ^ trace->not_ev_qualifier)) {
 324                         sc->filtered = true;
 325                         /*
 326                          * No need to do read tracepoint information since this will be
 327                          * filtered out.
 328                          */
 329                         return 0;
 330                 }
 331         }
 332
 333         sc->fmt  = syscall_fmt__find(sc->name);
 334
 335         snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->name);
 336         sc->tp_format = event_format__new("syscalls", tp_name);
 337
 338         if (sc->tp_format == NULL && sc->fmt && sc->fmt->alias) {
 339                 snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->fmt->alias);
 340                 sc->tp_format = event_format__new("syscalls", tp_name);
 341         }
 342
 343         if (sc->tp_format == NULL)
 344                 return -1;
 345
 346         return syscall__set_arg_fmts(sc);
 347 }
 348
 349 static size_t syscall__scnprintf_args(struct syscall *sc, char *bf, size_t size,
 350                                       unsigned long *args)
 351 {
 352         int i = 0;
 353         size_t printed = 0;
 354
 355         if (sc->tp_format != NULL) {
 356                 struct format_field *field;
 357
 358                 for (field = sc->tp_format->format.fields->next; field; field = field->next) {
 359                         printed += scnprintf(bf + printed, size - printed,
 360                                              "%s%s: ", printed ? ", " : "", field->name);
 361
 362                         if (sc->arg_scnprintf && sc->arg_scnprintf[i])
 363                                 printed += sc->arg_scnprintf[i](bf + printed, size - printed, args[i]);
 364                         else
 365                                 printed += scnprintf(bf + printed, size - printed,
 366                                                      "%ld", args[i]);
 367                        ++i;
 368                 }
 369         } else {
 370                 while (i < 6) {
 371                         printed += scnprintf(bf + printed, size - printed,
 372                                              "%sarg%d: %ld",
 373                                              printed ? ", " : "", i, args[i]);
 374                         ++i;
 375                 }
 376         }
 377
 378         return printed;
 379 }
 380
 381 typedef int (*tracepoint_handler)(struct trace *trace, struct perf_evsel *evsel,
 382                                   struct perf_sample *sample);
 383
 384 static struct syscall *trace__syscall_info(struct trace *trace,
 385                                            struct perf_evsel *evsel,
 386                                            struct perf_sample *sample)
 387 {
 388         int id = perf_evsel__intval(evsel, sample, "id");
 389
 390         if (id < 0) {
 391
 392                 /*
 393                  * XXX: Noticed on x86_64, reproduced as far back as 3.0.36, haven't tried
 394                  * before that, leaving at a higher verbosity level till that is
 395                  * explained. Reproduced with plain ftrace with:
 396                  *
 397                  * echo 1 > /t/events/raw_syscalls/sys_exit/enable
 398                  * grep "NR -1 " /t/trace_pipe
 399                  *
 400                  * After generating some load on the machine.
 401                  */
 402                 if (verbose > 1) {
 403                         static u64 n;
 404                         fprintf(trace->output, "Invalid syscall %d id, skipping (%s, %" PRIu64 ") ...\n",
 405                                 id, perf_evsel__name(evsel), ++n);
 406                 }
 407                 return NULL;
 408         }
 409
 410         if ((id > trace->syscalls.max || trace->syscalls.table[id].name == NULL) &&
 411             trace__read_syscall_info(trace, id))
 412                 goto out_cant_read;
 413
 414         if ((id > trace->syscalls.max || trace->syscalls.table[id].name == NULL))
 415                 goto out_cant_read;
 416
 417         return &trace->syscalls.table[id];
 418
 419 out_cant_read:
 420         if (verbose) {
 421                 fprintf(trace->output, "Problems reading syscall %d", id);
 422                 if (id <= trace->syscalls.max && trace->syscalls.table[id].name != NULL)
 423                         fprintf(trace->output, "(%s)", trace->syscalls.table[id].name);
 424                 fputs(" information\n", trace->output);
 425         }
 426         return NULL;
 427 }
 428
 429 static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
 430                             struct perf_sample *sample)
 431 {
 432         char *msg;
 433         void *args;
 434         size_t printed = 0;
 435         struct thread *thread;
 436         struct syscall *sc = trace__syscall_info(trace, evsel, sample);
 437         struct thread_trace *ttrace;
 438
 439         if (sc == NULL)
 440                 return -1;
 441
 442         if (sc->filtered)
 443                 return 0;
 444
 445         thread = machine__findnew_thread(&trace->host, sample->tid);
 446         ttrace = thread__trace(thread, trace->output);
 447         if (ttrace == NULL)
 448                 return -1;
 449
 450         args = perf_evsel__rawptr(evsel, sample, "args");
 451         if (args == NULL) {
 452                 fprintf(trace->output, "Problems reading syscall arguments\n");
 453                 return -1;
 454         }
 455
 456         ttrace = thread->priv;
 457
 458         if (ttrace->entry_str == NULL) {
 459                 ttrace->entry_str = malloc(1024);
 460                 if (!ttrace->entry_str)
 461                         return -1;
 462         }
 463
 464         ttrace->entry_time = sample->time;
 465         msg = ttrace->entry_str;
 466         printed += scnprintf(msg + printed, 1024 - printed, "%s(", sc->name);
 467
 468         printed += syscall__scnprintf_args(sc, msg + printed, 1024 - printed,  args);
 469
 470         if (!strcmp(sc->name, "exit_group") || !strcmp(sc->name, "exit")) {
 471                 if (!trace->duration_filter) {
 472                         trace__fprintf_entry_head(trace, thread, 1, sample->time, trace->output);
 473                         fprintf(trace->output, "%-70s\n", ttrace->entry_str);
 474                 }
 475         } else
 476                 ttrace->entry_pending = true;
 477
 478         return 0;
 479 }
 480
 481 static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
 482                            struct perf_sample *sample)
 483 {
 484         int ret;
 485         u64 duration = 0;
 486         struct thread *thread;
 487         struct syscall *sc = trace__syscall_info(trace, evsel, sample);
 488         struct thread_trace *ttrace;
 489
 490         if (sc == NULL)
 491                 return -1;
 492
 493         if (sc->filtered)
 494                 return 0;
 495
 496         thread = machine__findnew_thread(&trace->host, sample->tid);
 497         ttrace = thread__trace(thread, trace->output);
 498         if (ttrace == NULL)
 499                 return -1;
 500
 501         ret = perf_evsel__intval(evsel, sample, "ret");
 502
 503         ttrace = thread->priv;
 504
 505         ttrace->exit_time = sample->time;
 506
 507         if (ttrace->entry_time) {
 508                 duration = sample->time - ttrace->entry_time;
 509                 if (trace__filter_duration(trace, duration))
 510                         goto out;
 511         } else if (trace->duration_filter)
 512                 goto out;
 513
 514         trace__fprintf_entry_head(trace, thread, duration, sample->time, trace->output);
 515
 516         if (ttrace->entry_pending) {
 517                 fprintf(trace->output, "%-70s", ttrace->entry_str);
 518         } else {
 519                 fprintf(trace->output, " ... [");
 520                 color_fprintf(trace->output, PERF_COLOR_YELLOW, "continued");
 521                 fprintf(trace->output, "]: %s()", sc->name);
 522         }
 523
 524         if (sc->fmt == NULL) {
 525 signed_print:
 526                 fprintf(trace->output, ") = %d", ret);
 527         } else if (ret < 0 && sc->fmt->errmsg) {
 528                 char bf[256];
 529                 const char *emsg = strerror_r(-ret, bf, sizeof(bf)),
 530                            *e = audit_errno_to_name(-ret);
 531
 532                 fprintf(trace->output, ") = -1 %s %s", e, emsg);
 533         } else if (ret == 0 && sc->fmt->timeout)
 534                 fprintf(trace->output, ") = 0 Timeout");
 535         else if (sc->fmt->hexret)
 536                 fprintf(trace->output, ") = %#x", ret);
 537         else
 538                 goto signed_print;
 539
 540         fputc('\n', trace->output);
 541 out:
 542         ttrace->entry_pending = false;
 543
 544         return 0;
 545 }
 546
 547 static int trace__sched_stat_runtime(struct trace *trace, struct perf_evsel *evsel,
 548                                      struct perf_sample *sample)
 549 {
 550         u64 runtime = perf_evsel__intval(evsel, sample, "runtime");
 551         double runtime_ms = (double)runtime / NSEC_PER_MSEC;
 552         struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
 553         struct thread_trace *ttrace = thread__trace(thread, trace->output);
 554
 555         if (ttrace == NULL)
 556                 goto out_dump;
 557
 558         ttrace->runtime_ms += runtime_ms;
 559         trace->runtime_ms += runtime_ms;
 560         return 0;
 561
 562 out_dump:
 563         fprintf(trace->output, "%s: comm=%s,pid=%u,runtime=%" PRIu64 ",vruntime=%" PRIu64 ")\n",
 564                evsel->name,
 565                perf_evsel__strval(evsel, sample, "comm"),
 566                (pid_t)perf_evsel__intval(evsel, sample, "pid"),
 567                runtime,
 568                perf_evsel__intval(evsel, sample, "vruntime"));
 569         return 0;
 570 }
 571
 572 static int trace__run(struct trace *trace, int argc, const char **argv)
 573 {
 574         struct perf_evlist *evlist = perf_evlist__new();
 575         struct perf_evsel *evsel;
 576         int err = -1, i;
 577         unsigned long before;
 578         const bool forks = argc > 0;
 579
 580         if (evlist == NULL) {
 581                 fprintf(trace->output, "Not enough memory to run!\n");
 582                 goto out;
 583         }
 584
 585         if (perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_enter", trace__sys_enter) ||
 586             perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_exit", trace__sys_exit)) {
 587                 fprintf(trace->output, "Couldn't read the raw_syscalls tracepoints information!\n");
 588                 goto out_delete_evlist;
 589         }
 590
 591         if (trace->sched &&
 592             perf_evlist__add_newtp(evlist, "sched", "sched_stat_runtime",
 593                                    trace__sched_stat_runtime)) {
 594                 fprintf(trace->output, "Couldn't read the sched_stat_runtime tracepoint information!\n");
 595                 goto out_delete_evlist;
 596         }
 597
 598         err = perf_evlist__create_maps(evlist, &trace->opts.target);
 599         if (err < 0) {
 600                 fprintf(trace->output, "Problems parsing the target to trace, check your options!\n");
 601                 goto out_delete_evlist;
 602         }
 603
 604         err = trace__symbols_init(trace, evlist);
 605         if (err < 0) {
 606                 fprintf(trace->output, "Problems initializing symbol libraries!\n");
 607                 goto out_delete_maps;
 608         }
 609
 610         perf_evlist__config(evlist, &trace->opts);
 611
 612         signal(SIGCHLD, sig_handler);
 613         signal(SIGINT, sig_handler);
 614
 615         if (forks) {
 616                 err = perf_evlist__prepare_workload(evlist, &trace->opts.target,
 617                                                     argv, false, false);
 618                 if (err < 0) {
 619                         fprintf(trace->output, "Couldn't run the workload!\n");
 620                         goto out_delete_maps;
 621                 }
 622         }
 623
 624         err = perf_evlist__open(evlist);
 625         if (err < 0) {
 626                 fprintf(trace->output, "Couldn't create the events: %s\n", strerror(errno));
 627                 goto out_delete_maps;
 628         }
 629
 630         err = perf_evlist__mmap(evlist, UINT_MAX, false);
 631         if (err < 0) {
 632                 fprintf(trace->output, "Couldn't mmap the events: %s\n", strerror(errno));
 633                 goto out_close_evlist;
 634         }
 635
 636         perf_evlist__enable(evlist);
 637
 638         if (forks)
 639                 perf_evlist__start_workload(evlist);
 640
 641         trace->multiple_threads = evlist->threads->map[0] == -1 || evlist->threads->nr > 1;
 642 again:
 643         before = trace->nr_events;
 644
 645         for (i = 0; i < evlist->nr_mmaps; i++) {
 646                 union perf_event *event;
 647
 648                 while ((event = perf_evlist__mmap_read(evlist, i)) != NULL) {
 649                         const u32 type = event->header.type;
 650                         tracepoint_handler handler;
 651                         struct perf_sample sample;
 652
 653                         ++trace->nr_events;
 654
 655                         err = perf_evlist__parse_sample(evlist, event, &sample);
 656                         if (err) {
 657                                 fprintf(trace->output, "Can't parse sample, err = %d, skipping...\n", err);
 658                                 continue;
 659                         }
 660
 661                         if (trace->base_time == 0)
 662                                 trace->base_time = sample.time;
 663
 664                         if (type != PERF_RECORD_SAMPLE) {
 665                                 trace__process_event(trace, &trace->host, event);
 666                                 continue;
 667                         }
 668
 669                         evsel = perf_evlist__id2evsel(evlist, sample.id);
 670                         if (evsel == NULL) {
 671                                 fprintf(trace->output, "Unknown tp ID %" PRIu64 ", skipping...\n", sample.id);
 672                                 continue;
 673                         }
 674
 675                         if (sample.raw_data == NULL) {
 676                                 fprintf(trace->output, "%s sample with no payload for tid: %d, cpu %d, raw_size=%d, skipping...\n",
 677                                        perf_evsel__name(evsel), sample.tid,
 678                                        sample.cpu, sample.raw_size);
 679                                 continue;
 680                         }
 681
 682                         handler = evsel->handler.func;
 683                         handler(trace, evsel, &sample);
 684                 }
 685         }
 686
 687         if (trace->nr_events == before) {
 688                 if (done)
 689                         goto out_unmap_evlist;
 690
 691                 poll(evlist->pollfd, evlist->nr_fds, -1);
 692         }
 693
 694         if (done)
 695                 perf_evlist__disable(evlist);
 696
 697         goto again;
 698
 699 out_unmap_evlist:
 700         perf_evlist__munmap(evlist);
 701 out_close_evlist:
 702         perf_evlist__close(evlist);
 703 out_delete_maps:
 704         perf_evlist__delete_maps(evlist);
 705 out_delete_evlist:
 706         perf_evlist__delete(evlist);
 707 out:
 708         return err;
 709 }
 710
 711 static size_t trace__fprintf_threads_header(FILE *fp)
 712 {
 713         size_t printed;
 714
 715         printed  = fprintf(fp, "\n _____________________________________________________________________\n");
 716         printed += fprintf(fp," __)    Summary of events    (__\n\n");
 717         printed += fprintf(fp,"              [ task - pid ]     [ events ] [ ratio ]  [ runtime ]\n");
 718         printed += fprintf(fp," _____________________________________________________________________\n\n");
 719
 720         return printed;
 721 }
 722
 723 static size_t trace__fprintf_thread_summary(struct trace *trace, FILE *fp)
 724 {
 725         size_t printed = trace__fprintf_threads_header(fp);
 726         struct rb_node *nd;
 727
 728         for (nd = rb_first(&trace->host.threads); nd; nd = rb_next(nd)) {
 729                 struct thread *thread = rb_entry(nd, struct thread, rb_node);
 730                 struct thread_trace *ttrace = thread->priv;
 731                 const char *color;
 732                 double ratio;
 733
 734                 if (ttrace == NULL)
 735                         continue;
 736
 737                 ratio = (double)ttrace->nr_events / trace->nr_events * 100.0;
 738
 739                 color = PERF_COLOR_NORMAL;
 740                 if (ratio > 50.0)
 741                         color = PERF_COLOR_RED;
 742                 else if (ratio > 25.0)
 743                         color = PERF_COLOR_GREEN;
 744                 else if (ratio > 5.0)
 745                         color = PERF_COLOR_YELLOW;
 746
 747                 printed += color_fprintf(fp, color, "%20s", thread->comm);
 748                 printed += fprintf(fp, " - %-5d :%11lu   [", thread->tid, ttrace->nr_events);
 749                 printed += color_fprintf(fp, color, "%5.1f%%", ratio);
 750                 printed += fprintf(fp, " ] %10.3f ms\n", ttrace->runtime_ms);
 751         }
 752
 753         return printed;
 754 }
 755
 756 static int trace__set_duration(const struct option *opt, const char *str,
 757                                int unset __maybe_unused)
 758 {
 759         struct trace *trace = opt->value;
 760
 761         trace->duration_filter = atof(str);
 762         return 0;
 763 }
 764
 765 static int trace__open_output(struct trace *trace, const char *filename)
 766 {
 767         struct stat st;
 768
 769         if (!stat(filename, &st) && st.st_size) {
 770                 char oldname[PATH_MAX];
 771
 772                 scnprintf(oldname, sizeof(oldname), "%s.old", filename);
 773                 unlink(oldname);
 774                 rename(filename, oldname);
 775         }
 776
 777         trace->output = fopen(filename, "w");
 778
 779         return trace->output == NULL ? -errno : 0;
 780 }
 781
 782 int cmd_trace(int argc, const char **argv, const char *prefix __maybe_unused)
 783 {
 784         const char * const trace_usage[] = {
 785                 "perf trace [<options>] [<command>]",
 786                 "perf trace [<options>] -- <command> [<options>]",
 787                 NULL
 788         };
 789         struct trace trace = {
 790                 .audit_machine = audit_detect_machine(),
 791                 .syscalls = {
 792                         . max = -1,
 793                 },
 794                 .opts = {
 795                         .target = {
 796                                 .uid       = UINT_MAX,
 797                                 .uses_mmap = true,
 798                         },
 799                         .user_freq     = UINT_MAX,
 800                         .user_interval = ULLONG_MAX,
 801                         .no_delay      = true,
 802                         .mmap_pages    = 1024,
 803                 },
 804                 .output = stdout,
 805         };
 806         const char *output_name = NULL;
 807         const char *ev_qualifier_str = NULL;
 808         const struct option trace_options[] = {
 809         OPT_STRING('e', "expr", &ev_qualifier_str, "expr",
 810                     "list of events to trace"),
 811         OPT_STRING('o', "output", &output_name, "file", "output file name"),
 812         OPT_STRING('p', "pid", &trace.opts.target.pid, "pid",
 813                     "trace events on existing process id"),
 814         OPT_STRING('t', "tid", &trace.opts.target.tid, "tid",
 815                     "trace events on existing thread id"),
 816         OPT_BOOLEAN('a', "all-cpus", &trace.opts.target.system_wide,
 817                     "system-wide collection from all CPUs"),
 818         OPT_STRING('C', "cpu", &trace.opts.target.cpu_list, "cpu",
 819                     "list of cpus to monitor"),
 820         OPT_BOOLEAN('i', "no-inherit", &trace.opts.no_inherit,
 821                     "child tasks do not inherit counters"),
 822         OPT_UINTEGER('m', "mmap-pages", &trace.opts.mmap_pages,
 823                      "number of mmap data pages"),
 824         OPT_STRING('u', "uid", &trace.opts.target.uid_str, "user",
 825                    "user to profile"),
 826         OPT_CALLBACK(0, "duration", &trace, "float",
 827                      "show only events with duration > N.M ms",
 828                      trace__set_duration),
 829         OPT_BOOLEAN(0, "sched", &trace.sched, "show blocking scheduler events"),
 830         OPT_INCR('v', "verbose", &verbose, "be more verbose"),
 831         OPT_END()
 832         };
 833         int err;
 834         char bf[BUFSIZ];
 835
 836         argc = parse_options(argc, argv, trace_options, trace_usage, 0);
 837
 838         if (output_name != NULL) {
 839                 err = trace__open_output(&trace, output_name);
 840                 if (err < 0) {
 841                         perror("failed to create output file");
 842                         goto out;
 843                 }
 844         }
 845
 846         if (ev_qualifier_str != NULL) {
 847                 const char *s = ev_qualifier_str;
 848
 849                 trace.not_ev_qualifier = *s == '!';
 850                 if (trace.not_ev_qualifier)
 851                         ++s;
 852                 trace.ev_qualifier = strlist__new(true, s);
 853                 if (trace.ev_qualifier == NULL) {
 854                         fputs("Not enough memory to parse event qualifier",
 855                               trace.output);
 856                         err = -ENOMEM;
 857                         goto out_close;
 858                 }
 859         }
 860
 861         err = perf_target__validate(&trace.opts.target);
 862         if (err) {
 863                 perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
 864                 fprintf(trace.output, "%s", bf);
 865                 goto out_close;
 866         }
 867
 868         err = perf_target__parse_uid(&trace.opts.target);
 869         if (err) {
 870                 perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
 871                 fprintf(trace.output, "%s", bf);
 872                 goto out_close;
 873         }
 874
 875         if (!argc && perf_target__none(&trace.opts.target))
 876                 trace.opts.target.system_wide = true;
 877
 878         err = trace__run(&trace, argc, argv);
 879
 880         if (trace.sched && !err)
 881                 trace__fprintf_thread_summary(&trace, trace.output);
 882
 883 out_close:
 884         if (output_name != NULL)
 885                 fclose(trace.output);
 886 out:
 887         return err;
 888 }