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