Merge branch 'irq-core-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git...
[firefly-linux-kernel-4.4.55.git] / tools / perf / builtin-trace.c
index aa1e2888c81d024f5a63f19e5d656fa707afd9d7..4e3abba03062f3e84cfbdea5ca2c07adc641b35b 100644 (file)
@@ -1,3 +1,21 @@
+/*
+ * builtin-trace.c
+ *
+ * Builtin 'trace' command:
+ *
+ * Display a continuously updated trace of any workload, CPU, specific PID,
+ * system wide, etc.  Default format is loosely strace like, but any other
+ * event may be specified using --event.
+ *
+ * Copyright (C) 2012, 2013, 2014, 2015 Red Hat Inc, Arnaldo Carvalho de Melo <acme@redhat.com>
+ *
+ * Initially based on the 'trace' prototype by Thomas Gleixner:
+ *
+ * http://lwn.net/Articles/415728/ ("Announcing a new utility: 'trace'")
+ *
+ * Released under the GPL v2. (and only v2, not any later version)
+ */
+
 #include <traceevent/event-parse.h>
 #include "builtin.h"
 #include "util/color.h"
@@ -27,6 +45,7 @@
 
 #ifndef MADV_HWPOISON
 # define MADV_HWPOISON         100
+
 #endif
 
 #ifndef MADV_MERGEABLE
@@ -569,6 +588,15 @@ static DEFINE_STRARRAY_OFFSET(epoll_ctl_ops, 1);
 static const char *itimers[] = { "REAL", "VIRTUAL", "PROF", };
 static DEFINE_STRARRAY(itimers);
 
+static const char *keyctl_options[] = {
+       "GET_KEYRING_ID", "JOIN_SESSION_KEYRING", "UPDATE", "REVOKE", "CHOWN",
+       "SETPERM", "DESCRIBE", "CLEAR", "LINK", "UNLINK", "SEARCH", "READ",
+       "INSTANTIATE", "NEGATE", "SET_REQKEY_KEYRING", "SET_TIMEOUT",
+       "ASSUME_AUTHORITY", "GET_SECURITY", "SESSION_TO_PARENT", "REJECT",
+       "INSTANTIATE_IOV", "INVALIDATE", "GET_PERSISTENT",
+};
+static DEFINE_STRARRAY(keyctl_options);
+
 static const char *whences[] = { "SET", "CUR", "END",
 #ifdef SEEK_DATA
 "DATA",
@@ -599,7 +627,8 @@ static DEFINE_STRARRAY(sighow);
 
 static const char *clockid[] = {
        "REALTIME", "MONOTONIC", "PROCESS_CPUTIME_ID", "THREAD_CPUTIME_ID",
-       "MONOTONIC_RAW", "REALTIME_COARSE", "MONOTONIC_COARSE",
+       "MONOTONIC_RAW", "REALTIME_COARSE", "MONOTONIC_COARSE", "BOOTTIME",
+       "REALTIME_ALARM", "BOOTTIME_ALARM", "SGI_CYCLE", "TAI"
 };
 static DEFINE_STRARRAY(clockid);
 
@@ -744,6 +773,11 @@ static size_t syscall_arg__scnprintf_access_mode(char *bf, size_t size,
 
 #define SCA_ACCMODE syscall_arg__scnprintf_access_mode
 
+static size_t syscall_arg__scnprintf_filename(char *bf, size_t size,
+                                             struct syscall_arg *arg);
+
+#define SCA_FILENAME syscall_arg__scnprintf_filename
+
 static size_t syscall_arg__scnprintf_open_flags(char *bf, size_t size,
                                               struct syscall_arg *arg)
 {
@@ -971,14 +1005,23 @@ static struct syscall_fmt {
        bool       hexret;
 } syscall_fmts[] = {
        { .name     = "access",     .errmsg = true,
-         .arg_scnprintf = { [1] = SCA_ACCMODE, /* mode */ }, },
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */
+                            [1] = SCA_ACCMODE,  /* mode */ }, },
        { .name     = "arch_prctl", .errmsg = true, .alias = "prctl", },
        { .name     = "brk",        .hexret = true,
          .arg_scnprintf = { [0] = SCA_HEX, /* brk */ }, },
+       { .name     = "chdir",      .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */ }, },
+       { .name     = "chmod",      .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */ }, },
+       { .name     = "chroot",     .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */ }, },
        { .name     = "clock_gettime",  .errmsg = true, STRARRAY(0, clk_id, clockid), },
        { .name     = "close",      .errmsg = true,
          .arg_scnprintf = { [0] = SCA_CLOSE_FD, /* fd */ }, },
        { .name     = "connect",    .errmsg = true, },
+       { .name     = "creat",      .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "dup",        .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "dup2",       .errmsg = true,
@@ -989,7 +1032,8 @@ static struct syscall_fmt {
        { .name     = "eventfd2",   .errmsg = true,
          .arg_scnprintf = { [1] = SCA_EFD_FLAGS, /* flags */ }, },
        { .name     = "faccessat",  .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */
+                            [1] = SCA_FILENAME, /* filename */ }, },
        { .name     = "fadvise64",  .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "fallocate",  .errmsg = true,
@@ -999,11 +1043,13 @@ static struct syscall_fmt {
        { .name     = "fchmod",     .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "fchmodat",   .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */
+                            [1] = SCA_FILENAME, /* filename */ }, },
        { .name     = "fchown",     .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "fchownat",   .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */
+                            [1] = SCA_FILENAME, /* filename */ }, },
        { .name     = "fcntl",      .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */
                             [1] = SCA_STRARRAY, /* cmd */ },
@@ -1018,7 +1064,8 @@ static struct syscall_fmt {
        { .name     = "fstat",      .errmsg = true, .alias = "newfstat",
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "fstatat",    .errmsg = true, .alias = "newfstatat",
-         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */
+                            [1] = SCA_FILENAME, /* filename */ }, },
        { .name     = "fstatfs",    .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "fsync",    .errmsg = true,
@@ -1028,13 +1075,18 @@ static struct syscall_fmt {
        { .name     = "futex",      .errmsg = true,
          .arg_scnprintf = { [1] = SCA_FUTEX_OP, /* op */ }, },
        { .name     = "futimesat", .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */
+                            [1] = SCA_FILENAME, /* filename */ }, },
        { .name     = "getdents",   .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "getdents64", .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "getitimer",  .errmsg = true, STRARRAY(0, which, itimers), },
        { .name     = "getrlimit",  .errmsg = true, STRARRAY(0, resource, rlimit_resources), },
+       { .name     = "getxattr",    .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
+       { .name     = "inotify_add_watch",          .errmsg = true,
+         .arg_scnprintf = { [1] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "ioctl",      .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */
 #if defined(__i386__) || defined(__x86_64__)
@@ -1047,22 +1099,44 @@ static struct syscall_fmt {
 #else
                             [2] = SCA_HEX, /* arg */ }, },
 #endif
+       { .name     = "keyctl",     .errmsg = true, STRARRAY(0, option, keyctl_options), },
        { .name     = "kill",       .errmsg = true,
          .arg_scnprintf = { [1] = SCA_SIGNUM, /* sig */ }, },
+       { .name     = "lchown",    .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */ }, },
+       { .name     = "lgetxattr",  .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "linkat",     .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FDAT, /* fd */ }, },
+       { .name     = "listxattr",  .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
+       { .name     = "llistxattr", .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
+       { .name     = "lremovexattr",  .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "lseek",      .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */
                             [2] = SCA_STRARRAY, /* whence */ },
          .arg_parm      = { [2] = &strarray__whences, /* whence */ }, },
-       { .name     = "lstat",      .errmsg = true, .alias = "newlstat", },
+       { .name     = "lsetxattr",  .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
+       { .name     = "lstat",      .errmsg = true, .alias = "newlstat",
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */ }, },
+       { .name     = "lsxattr",    .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "madvise",    .errmsg = true,
          .arg_scnprintf = { [0] = SCA_HEX,      /* start */
                             [2] = SCA_MADV_BHV, /* behavior */ }, },
+       { .name     = "mkdir",    .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "mkdirat",    .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */
+                            [1] = SCA_FILENAME, /* pathname */ }, },
+       { .name     = "mknod",      .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */ }, },
        { .name     = "mknodat",    .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* fd */
+                            [1] = SCA_FILENAME, /* filename */ }, },
        { .name     = "mlock",      .errmsg = true,
          .arg_scnprintf = { [0] = SCA_HEX, /* addr */ }, },
        { .name     = "mlockall",   .errmsg = true,
@@ -1075,6 +1149,8 @@ static struct syscall_fmt {
        { .name     = "mprotect",   .errmsg = true,
          .arg_scnprintf = { [0] = SCA_HEX, /* start */
                             [2] = SCA_MMAP_PROT, /* prot */ }, },
+       { .name     = "mq_unlink", .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* u_name */ }, },
        { .name     = "mremap",     .hexret = true,
          .arg_scnprintf = { [0] = SCA_HEX, /* addr */
                             [3] = SCA_MREMAP_FLAGS, /* flags */
@@ -1086,14 +1162,17 @@ static struct syscall_fmt {
        { .name     = "name_to_handle_at", .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */ }, },
        { .name     = "newfstatat", .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */
+                            [1] = SCA_FILENAME, /* filename */ }, },
        { .name     = "open",       .errmsg = true,
-         .arg_scnprintf = { [1] = SCA_OPEN_FLAGS, /* flags */ }, },
+         .arg_scnprintf = { [0] = SCA_FILENAME,   /* filename */
+                            [1] = SCA_OPEN_FLAGS, /* flags */ }, },
        { .name     = "open_by_handle_at", .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */
                             [2] = SCA_OPEN_FLAGS, /* flags */ }, },
        { .name     = "openat",     .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */
+                            [1] = SCA_FILENAME, /* filename */
                             [2] = SCA_OPEN_FLAGS, /* flags */ }, },
        { .name     = "perf_event_open", .errmsg = true,
          .arg_scnprintf = { [1] = SCA_INT, /* pid */
@@ -1115,18 +1194,28 @@ static struct syscall_fmt {
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "read",       .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
+       { .name     = "readlink",   .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* path */ }, },
        { .name     = "readlinkat", .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */
+                            [1] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "readv",      .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "recvfrom",   .errmsg = true,
-         .arg_scnprintf = { [3] = SCA_MSG_FLAGS, /* flags */ }, },
+         .arg_scnprintf = { [0] = SCA_FD, /* fd */
+                            [3] = SCA_MSG_FLAGS, /* flags */ }, },
        { .name     = "recvmmsg",   .errmsg = true,
-         .arg_scnprintf = { [3] = SCA_MSG_FLAGS, /* flags */ }, },
+         .arg_scnprintf = { [0] = SCA_FD, /* fd */
+                            [3] = SCA_MSG_FLAGS, /* flags */ }, },
        { .name     = "recvmsg",    .errmsg = true,
-         .arg_scnprintf = { [2] = SCA_MSG_FLAGS, /* flags */ }, },
+         .arg_scnprintf = { [0] = SCA_FD, /* fd */
+                            [2] = SCA_MSG_FLAGS, /* flags */ }, },
+       { .name     = "removexattr", .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "renameat",   .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */ }, },
+       { .name     = "rmdir",    .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "rt_sigaction", .errmsg = true,
          .arg_scnprintf = { [0] = SCA_SIGNUM, /* sig */ }, },
        { .name     = "rt_sigprocmask",  .errmsg = true, STRARRAY(0, how, sighow), },
@@ -1136,13 +1225,18 @@ static struct syscall_fmt {
          .arg_scnprintf = { [2] = SCA_SIGNUM, /* sig */ }, },
        { .name     = "select",     .errmsg = true, .timeout = true, },
        { .name     = "sendmmsg",    .errmsg = true,
-         .arg_scnprintf = { [3] = SCA_MSG_FLAGS, /* flags */ }, },
+         .arg_scnprintf = { [0] = SCA_FD, /* fd */
+                            [3] = SCA_MSG_FLAGS, /* flags */ }, },
        { .name     = "sendmsg",    .errmsg = true,
-         .arg_scnprintf = { [2] = SCA_MSG_FLAGS, /* flags */ }, },
+         .arg_scnprintf = { [0] = SCA_FD, /* fd */
+                            [2] = SCA_MSG_FLAGS, /* flags */ }, },
        { .name     = "sendto",     .errmsg = true,
-         .arg_scnprintf = { [3] = SCA_MSG_FLAGS, /* flags */ }, },
+         .arg_scnprintf = { [0] = SCA_FD, /* fd */
+                            [3] = SCA_MSG_FLAGS, /* flags */ }, },
        { .name     = "setitimer",  .errmsg = true, STRARRAY(0, which, itimers), },
        { .name     = "setrlimit",  .errmsg = true, STRARRAY(0, resource, rlimit_resources), },
+       { .name     = "setxattr",   .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
        { .name     = "shutdown",   .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "socket",     .errmsg = true,
@@ -1153,18 +1247,35 @@ static struct syscall_fmt {
          .arg_scnprintf = { [0] = SCA_STRARRAY, /* family */
                             [1] = SCA_SK_TYPE, /* type */ },
          .arg_parm      = { [0] = &strarray__socket_families, /* family */ }, },
-       { .name     = "stat",       .errmsg = true, .alias = "newstat", },
+       { .name     = "stat",       .errmsg = true, .alias = "newstat",
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
+       { .name     = "statfs",     .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* pathname */ }, },
+       { .name     = "swapoff",    .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* specialfile */ }, },
+       { .name     = "swapon",     .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* specialfile */ }, },
        { .name     = "symlinkat",  .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */ }, },
        { .name     = "tgkill",     .errmsg = true,
          .arg_scnprintf = { [2] = SCA_SIGNUM, /* sig */ }, },
        { .name     = "tkill",      .errmsg = true,
          .arg_scnprintf = { [1] = SCA_SIGNUM, /* sig */ }, },
+       { .name     = "truncate",   .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* path */ }, },
        { .name     = "uname",      .errmsg = true, .alias = "newuname", },
        { .name     = "unlinkat",   .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* dfd */
+                            [1] = SCA_FILENAME, /* pathname */ }, },
+       { .name     = "utime",  .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */ }, },
        { .name     = "utimensat",  .errmsg = true,
-         .arg_scnprintf = { [0] = SCA_FDAT, /* dirfd */ }, },
+         .arg_scnprintf = { [0] = SCA_FDAT, /* dirfd */
+                            [1] = SCA_FILENAME, /* filename */ }, },
+       { .name     = "utimes",  .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FILENAME, /* filename */ }, },
+       { .name     = "vmsplice",  .errmsg = true,
+         .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "write",      .errmsg = true,
          .arg_scnprintf = { [0] = SCA_FD, /* fd */ }, },
        { .name     = "writev",     .errmsg = true,
@@ -1208,6 +1319,11 @@ static size_t fprintf_duration(unsigned long t, FILE *fp)
        return printed + fprintf(fp, "): ");
 }
 
+/**
+ * filename.ptr: The filename char pointer that will be vfs_getname'd
+ * filename.entry_str_pos: Where to insert the string translated from
+ *                         filename.ptr by the vfs_getname tracepoint/kprobe.
+ */
 struct thread_trace {
        u64               entry_time;
        u64               exit_time;
@@ -1216,6 +1332,13 @@ struct thread_trace {
        unsigned long     pfmaj, pfmin;
        char              *entry_str;
        double            runtime_ms;
+        struct {
+               unsigned long ptr;
+               short int     entry_str_pos;
+               bool          pending_open;
+               unsigned int  namelen;
+               char          *name;
+       } filename;
        struct {
                int       max;
                char      **table;
@@ -1262,6 +1385,8 @@ fail:
 #define TRACE_PFMAJ            (1 << 0)
 #define TRACE_PFMIN            (1 << 1)
 
+static const size_t trace__entry_str_size = 2048;
+
 struct trace {
        struct perf_tool        tool;
        struct {
@@ -1288,7 +1413,6 @@ struct trace {
                size_t          nr;
                int             *entries;
        }                       ev_qualifier_ids;
-       const char              *last_vfs_getname;
        struct intlist          *tid_list;
        struct intlist          *pid_list;
        struct {
@@ -1416,6 +1540,27 @@ static size_t syscall_arg__scnprintf_close_fd(char *bf, size_t size,
        return printed;
 }
 
+static void thread__set_filename_pos(struct thread *thread, const char *bf,
+                                    unsigned long ptr)
+{
+       struct thread_trace *ttrace = thread__priv(thread);
+
+       ttrace->filename.ptr = ptr;
+       ttrace->filename.entry_str_pos = bf - ttrace->entry_str;
+}
+
+static size_t syscall_arg__scnprintf_filename(char *bf, size_t size,
+                                             struct syscall_arg *arg)
+{
+       unsigned long ptr = arg->val;
+
+       if (!arg->trace->vfs_getname)
+               return scnprintf(bf, size, "%#x", ptr);
+
+       thread__set_filename_pos(arg->thread, bf, ptr);
+       return 0;
+}
+
 static bool trace__filter_duration(struct trace *trace, double t)
 {
        return t < (trace->duration_filter * NSEC_PER_MSEC);
@@ -1822,7 +1967,7 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
        args = perf_evsel__sc_tp_ptr(evsel, args, sample);
 
        if (ttrace->entry_str == NULL) {
-               ttrace->entry_str = malloc(1024);
+               ttrace->entry_str = malloc(trace__entry_str_size);
                if (!ttrace->entry_str)
                        goto out_put;
        }
@@ -1832,9 +1977,9 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
 
        ttrace->entry_time = sample->time;
        msg = ttrace->entry_str;
-       printed += scnprintf(msg + printed, 1024 - printed, "%s(", sc->name);
+       printed += scnprintf(msg + printed, trace__entry_str_size - printed, "%s(", sc->name);
 
-       printed += syscall__scnprintf_args(sc, msg + printed, 1024 - printed,
+       printed += syscall__scnprintf_args(sc, msg + printed, trace__entry_str_size - printed,
                                           args, trace, thread);
 
        if (sc->is_exit) {
@@ -1842,8 +1987,11 @@ static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
                        trace__fprintf_entry_head(trace, thread, 1, sample->time, trace->output);
                        fprintf(trace->output, "%-70s\n", ttrace->entry_str);
                }
-       } else
+       } else {
                ttrace->entry_pending = true;
+               /* See trace__vfs_getname & trace__sys_exit */
+               ttrace->filename.pending_open = false;
+       }
 
        if (trace->current != thread) {
                thread__put(trace->current);
@@ -1879,9 +2027,9 @@ static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
 
        ret = perf_evsel__sc_tp_uint(evsel, ret, sample);
 
-       if (id == trace->audit.open_id && ret >= 0 && trace->last_vfs_getname) {
-               trace__set_fd_pathname(thread, ret, trace->last_vfs_getname);
-               trace->last_vfs_getname = NULL;
+       if (id == trace->audit.open_id && ret >= 0 && ttrace->filename.pending_open) {
+               trace__set_fd_pathname(thread, ret, ttrace->filename.name);
+               ttrace->filename.pending_open = false;
                ++trace->stats.vfs_getname;
        }
 
@@ -1936,7 +2084,56 @@ static int trace__vfs_getname(struct trace *trace, struct perf_evsel *evsel,
                              union perf_event *event __maybe_unused,
                              struct perf_sample *sample)
 {
-       trace->last_vfs_getname = perf_evsel__rawptr(evsel, sample, "pathname");
+       struct thread *thread = machine__findnew_thread(trace->host, sample->pid, sample->tid);
+       struct thread_trace *ttrace;
+       size_t filename_len, entry_str_len, to_move;
+       ssize_t remaining_space;
+       char *pos;
+       const char *filename = perf_evsel__rawptr(evsel, sample, "pathname");
+
+       if (!thread)
+               goto out;
+
+       ttrace = thread__priv(thread);
+       if (!ttrace)
+               goto out;
+
+       filename_len = strlen(filename);
+
+       if (ttrace->filename.namelen < filename_len) {
+               char *f = realloc(ttrace->filename.name, filename_len + 1);
+
+               if (f == NULL)
+                               goto out;
+
+               ttrace->filename.namelen = filename_len;
+               ttrace->filename.name = f;
+       }
+
+       strcpy(ttrace->filename.name, filename);
+       ttrace->filename.pending_open = true;
+
+       if (!ttrace->filename.ptr)
+               goto out;
+
+       entry_str_len = strlen(ttrace->entry_str);
+       remaining_space = trace__entry_str_size - entry_str_len - 1; /* \0 */
+       if (remaining_space <= 0)
+               goto out;
+
+       if (filename_len > (size_t)remaining_space) {
+               filename += filename_len - remaining_space;
+               filename_len = remaining_space;
+       }
+
+       to_move = entry_str_len - ttrace->filename.entry_str_pos + 1; /* \0 */
+       pos = ttrace->entry_str + ttrace->filename.entry_str_pos;
+       memmove(pos + filename_len, pos, to_move);
+       memcpy(pos, filename, filename_len);
+
+       ttrace->filename.ptr = 0;
+       ttrace->filename.entry_str_pos = 0;
+out:
        return 0;
 }
 
@@ -2641,9 +2838,9 @@ static size_t thread__dump_stats(struct thread_trace *ttrace,
 
        printed += fprintf(fp, "\n");
 
-       printed += fprintf(fp, "   syscall            calls      min       avg       max      stddev\n");
-       printed += fprintf(fp, "                               (msec)    (msec)    (msec)        (%%)\n");
-       printed += fprintf(fp, "   --------------- -------- --------- --------- ---------     ------\n");
+       printed += fprintf(fp, "   syscall            calls    total       min       avg       max      stddev\n");
+       printed += fprintf(fp, "                               (msec)    (msec)    (msec)    (msec)        (%%)\n");
+       printed += fprintf(fp, "   --------------- -------- --------- --------- --------- ---------     ------\n");
 
        /* each int_node is a syscall */
        while (inode) {
@@ -2660,8 +2857,8 @@ static size_t thread__dump_stats(struct thread_trace *ttrace,
 
                        sc = &trace->syscalls.table[inode->i];
                        printed += fprintf(fp, "   %-15s", sc->name);
-                       printed += fprintf(fp, " %8" PRIu64 " %9.3f %9.3f",
-                                          n, min, avg);
+                       printed += fprintf(fp, " %8" PRIu64 " %9.3f %9.3f %9.3f",
+                                          n, avg * n, min, avg);
                        printed += fprintf(fp, " %9.3f %9.2f%%\n", max, pct);
                }
 
@@ -2833,7 +3030,7 @@ int cmd_trace(int argc, const char **argv, const char *prefix __maybe_unused)
                        .mmap_pages    = UINT_MAX,
                        .proc_map_timeout  = 500,
                },
-               .output = stdout,
+               .output = stderr,
                .show_comm = true,
                .trace_syscalls = true,
        };