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