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