2013-06-11 17:29:18 +02:00
|
|
|
#include <traceevent/event-parse.h>
|
2012-09-27 01:05:56 +02:00
|
|
|
#include "builtin.h"
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
#include "util/color.h"
|
2013-08-22 21:49:54 +02:00
|
|
|
#include "util/debug.h"
|
2012-09-27 01:05:56 +02:00
|
|
|
#include "util/evlist.h"
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
#include "util/machine.h"
|
|
|
|
#include "util/thread.h"
|
2012-09-27 01:05:56 +02:00
|
|
|
#include "util/parse-options.h"
|
2013-08-09 17:28:31 +02:00
|
|
|
#include "util/strlist.h"
|
2012-09-27 01:05:56 +02:00
|
|
|
#include "util/thread_map.h"
|
|
|
|
|
|
|
|
#include <libaudit.h>
|
|
|
|
#include <stdlib.h>
|
perf trace: Add beautifier for mmap prot parm
[root@zoo ~]# perf trace -e mmap,mprotect sleep 1
0.984 ( 0.015 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd62ae000
1.114 ( 0.016 ms): mmap(addr: 0, len: 125100, prot: READ, flags: 2, fd: 3, off: 0 ) = 0xd628f000
1.252 ( 0.020 ms): mmap(addr: 0x33c1600000, len: 3896312, prot: EXEC|READ, flags: 2050, fd: 3, off: 0) = 0xc1600000
1.282 ( 0.024 ms): mprotect(start: 0x33c17ad000, len: 2097152, prot: NONE ) = 0
1.315 ( 0.026 ms): mmap(addr: 0x33c19ad000, len: 24576, prot: READ|WRITE, flags: 2066, fd: 3, off: 1757184) = 0xc19ad000
1.352 ( 0.017 ms): mmap(addr: 0x33c19b3000, len: 17400, prot: READ|WRITE, flags: 50, fd: 4294967295, off: 0) = 0xc19b3000
1.415 ( 0.011 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd628e000
1.440 ( 0.011 ms): mmap(addr: 0, len: 8192, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd628c000
1.569 ( 0.019 ms): mprotect(start: 0x606000, len: 4096, prot: READ ) = 0
1.591 ( 0.017 ms): mprotect(start: 0x33c19ad000, len: 16384, prot: READ ) = 0
1.616 ( 0.016 ms): mprotect(start: 0x33c1420000, len: 4096, prot: READ ) = 0
2.105 ( 0.018 ms): mmap(addr: 0, len: 104789808, prot: READ, flags: 2, fd: 3, off: 0 ) = 0xcfe9c000
[root@zoo ~]#
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-q1ubhdd9wigxneam616ggdsn@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2013-08-20 22:44:42 +02:00
|
|
|
#include <sys/mman.h>
|
2012-09-27 01:05:56 +02:00
|
|
|
|
2013-08-23 23:14:48 +02:00
|
|
|
static size_t syscall_arg__scnprintf_hex(char *bf, size_t size, unsigned long arg)
|
|
|
|
{
|
|
|
|
return scnprintf(bf, size, "%#lx", arg);
|
|
|
|
}
|
|
|
|
|
2013-08-26 17:29:38 +02:00
|
|
|
#define SCA_HEX syscall_arg__scnprintf_hex
|
|
|
|
|
perf trace: Add beautifier for mmap prot parm
[root@zoo ~]# perf trace -e mmap,mprotect sleep 1
0.984 ( 0.015 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd62ae000
1.114 ( 0.016 ms): mmap(addr: 0, len: 125100, prot: READ, flags: 2, fd: 3, off: 0 ) = 0xd628f000
1.252 ( 0.020 ms): mmap(addr: 0x33c1600000, len: 3896312, prot: EXEC|READ, flags: 2050, fd: 3, off: 0) = 0xc1600000
1.282 ( 0.024 ms): mprotect(start: 0x33c17ad000, len: 2097152, prot: NONE ) = 0
1.315 ( 0.026 ms): mmap(addr: 0x33c19ad000, len: 24576, prot: READ|WRITE, flags: 2066, fd: 3, off: 1757184) = 0xc19ad000
1.352 ( 0.017 ms): mmap(addr: 0x33c19b3000, len: 17400, prot: READ|WRITE, flags: 50, fd: 4294967295, off: 0) = 0xc19b3000
1.415 ( 0.011 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd628e000
1.440 ( 0.011 ms): mmap(addr: 0, len: 8192, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd628c000
1.569 ( 0.019 ms): mprotect(start: 0x606000, len: 4096, prot: READ ) = 0
1.591 ( 0.017 ms): mprotect(start: 0x33c19ad000, len: 16384, prot: READ ) = 0
1.616 ( 0.016 ms): mprotect(start: 0x33c1420000, len: 4096, prot: READ ) = 0
2.105 ( 0.018 ms): mmap(addr: 0, len: 104789808, prot: READ, flags: 2, fd: 3, off: 0 ) = 0xcfe9c000
[root@zoo ~]#
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-q1ubhdd9wigxneam616ggdsn@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2013-08-20 22:44:42 +02:00
|
|
|
static size_t syscall_arg__scnprintf_mmap_prot(char *bf, size_t size, unsigned long arg)
|
|
|
|
{
|
|
|
|
int printed = 0, prot = arg;
|
|
|
|
|
|
|
|
if (prot == PROT_NONE)
|
|
|
|
return scnprintf(bf, size, "NONE");
|
|
|
|
#define P_MMAP_PROT(n) \
|
|
|
|
if (prot & PROT_##n) { \
|
|
|
|
printed += scnprintf(bf + printed, size - printed, "%s%s", printed ? "|" : "", #n); \
|
|
|
|
prot &= ~PROT_##n; \
|
|
|
|
}
|
|
|
|
|
|
|
|
P_MMAP_PROT(EXEC);
|
|
|
|
P_MMAP_PROT(READ);
|
|
|
|
P_MMAP_PROT(WRITE);
|
|
|
|
#ifdef PROT_SEM
|
|
|
|
P_MMAP_PROT(SEM);
|
|
|
|
#endif
|
|
|
|
P_MMAP_PROT(GROWSDOWN);
|
|
|
|
P_MMAP_PROT(GROWSUP);
|
|
|
|
#undef P_MMAP_PROT
|
|
|
|
|
|
|
|
if (prot)
|
|
|
|
printed += scnprintf(bf + printed, size - printed, "%s%#x", printed ? "|" : "", prot);
|
|
|
|
|
|
|
|
return printed;
|
|
|
|
}
|
|
|
|
|
|
|
|
#define SCA_MMAP_PROT syscall_arg__scnprintf_mmap_prot
|
|
|
|
|
perf trace: Add beautifier for mmap flags parm
[root@zoo ~]# perf trace -e mmap,mprotect sleep 1
0.992 ( 0.015 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: 4294967295, off: 0) = 0xa60be000
1.108 ( 0.012 ms): mmap(addr: 0, len: 125100, prot: READ, flags: PRIVATE, fd: 3, off: 0 ) = 0xa609f000
1.209 ( 0.014 ms): mmap(addr: 0x33c1600000, len: 3896312, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 3, off: 0) = 0xc1600000
1.232 ( 0.018 ms): mprotect(start: 0x33c17ad000, len: 2097152, prot: NONE ) = 0
1.255 ( 0.018 ms): mmap(addr: 0x33c19ad000, len: 24576, prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 1757184) = 0xc19ad000
1.281 ( 0.011 ms): mmap(addr: 0x33c19b3000, len: 17400, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS|FIXED, fd: 4294967295, off: 0) = 0xc19b3000
1.328 ( 0.008 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: 4294967295, off: 0) = 0xa609e000
1.346 ( 0.008 ms): mmap(addr: 0, len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: 4294967295, off: 0) = 0xa609c000
1.443 ( 0.013 ms): mprotect(start: 0x606000, len: 4096, prot: READ ) = 0
1.459 ( 0.011 ms): mprotect(start: 0x33c19ad000, len: 16384, prot: READ ) = 0
1.477 ( 0.011 ms): mprotect(start: 0x33c1420000, len: 4096, prot: READ ) = 0
1.855 ( 0.013 ms): mmap(addr: 0, len: 104789808, prot: READ, flags: PRIVATE, fd: 3, off: 0) = 0x9fcac000
[root@zoo ~]#
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-q1ubhdd9wigxneam616ggdsn@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2013-08-23 15:48:33 +02:00
|
|
|
static size_t syscall_arg__scnprintf_mmap_flags(char *bf, size_t size, unsigned long arg)
|
|
|
|
{
|
|
|
|
int printed = 0, flags = arg;
|
|
|
|
|
|
|
|
#define P_MMAP_FLAG(n) \
|
|
|
|
if (flags & MAP_##n) { \
|
|
|
|
printed += scnprintf(bf + printed, size - printed, "%s%s", printed ? "|" : "", #n); \
|
|
|
|
flags &= ~MAP_##n; \
|
|
|
|
}
|
|
|
|
|
|
|
|
P_MMAP_FLAG(SHARED);
|
|
|
|
P_MMAP_FLAG(PRIVATE);
|
|
|
|
P_MMAP_FLAG(32BIT);
|
|
|
|
P_MMAP_FLAG(ANONYMOUS);
|
|
|
|
P_MMAP_FLAG(DENYWRITE);
|
|
|
|
P_MMAP_FLAG(EXECUTABLE);
|
|
|
|
P_MMAP_FLAG(FILE);
|
|
|
|
P_MMAP_FLAG(FIXED);
|
|
|
|
P_MMAP_FLAG(GROWSDOWN);
|
|
|
|
P_MMAP_FLAG(HUGETLB);
|
|
|
|
P_MMAP_FLAG(LOCKED);
|
|
|
|
P_MMAP_FLAG(NONBLOCK);
|
|
|
|
P_MMAP_FLAG(NORESERVE);
|
|
|
|
P_MMAP_FLAG(POPULATE);
|
|
|
|
P_MMAP_FLAG(STACK);
|
|
|
|
#ifdef MAP_UNINITIALIZED
|
|
|
|
P_MMAP_FLAG(UNINITIALIZED);
|
|
|
|
#endif
|
|
|
|
#undef P_MMAP_FLAG
|
|
|
|
|
|
|
|
if (flags)
|
|
|
|
printed += scnprintf(bf + printed, size - printed, "%s%#x", printed ? "|" : "", flags);
|
|
|
|
|
|
|
|
return printed;
|
|
|
|
}
|
|
|
|
|
|
|
|
#define SCA_MMAP_FLAGS syscall_arg__scnprintf_mmap_flags
|
|
|
|
|
2013-08-23 15:06:41 +02:00
|
|
|
static size_t syscall_arg__scnprintf_madvise_behavior(char *bf, size_t size, unsigned long arg)
|
|
|
|
{
|
|
|
|
int behavior = arg;
|
|
|
|
|
|
|
|
switch (behavior) {
|
|
|
|
#define P_MADV_BHV(n) case MADV_##n: return scnprintf(bf, size, #n)
|
|
|
|
P_MADV_BHV(NORMAL);
|
|
|
|
P_MADV_BHV(RANDOM);
|
|
|
|
P_MADV_BHV(SEQUENTIAL);
|
|
|
|
P_MADV_BHV(WILLNEED);
|
|
|
|
P_MADV_BHV(DONTNEED);
|
|
|
|
P_MADV_BHV(REMOVE);
|
|
|
|
P_MADV_BHV(DONTFORK);
|
|
|
|
P_MADV_BHV(DOFORK);
|
|
|
|
P_MADV_BHV(HWPOISON);
|
|
|
|
#ifdef MADV_SOFT_OFFLINE
|
|
|
|
P_MADV_BHV(SOFT_OFFLINE);
|
|
|
|
#endif
|
|
|
|
P_MADV_BHV(MERGEABLE);
|
|
|
|
P_MADV_BHV(UNMERGEABLE);
|
|
|
|
P_MADV_BHV(HUGEPAGE);
|
|
|
|
P_MADV_BHV(NOHUGEPAGE);
|
|
|
|
#ifdef MADV_DONTDUMP
|
|
|
|
P_MADV_BHV(DONTDUMP);
|
|
|
|
#endif
|
|
|
|
#ifdef MADV_DODUMP
|
|
|
|
P_MADV_BHV(DODUMP);
|
|
|
|
#endif
|
|
|
|
#undef P_MADV_PHV
|
|
|
|
default: break;
|
|
|
|
}
|
|
|
|
|
|
|
|
return scnprintf(bf, size, "%#x", behavior);
|
|
|
|
}
|
|
|
|
|
|
|
|
#define SCA_MADV_BHV syscall_arg__scnprintf_madvise_behavior
|
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
static struct syscall_fmt {
|
|
|
|
const char *name;
|
2012-09-27 18:16:00 +02:00
|
|
|
const char *alias;
|
2013-08-26 17:29:38 +02:00
|
|
|
size_t (*arg_scnprintf[6])(char *bf, size_t size, unsigned long arg);
|
2012-09-27 01:05:56 +02:00
|
|
|
bool errmsg;
|
|
|
|
bool timeout;
|
2013-08-26 16:36:30 +02:00
|
|
|
bool hexret;
|
2012-09-27 01:05:56 +02:00
|
|
|
} syscall_fmts[] = {
|
2012-10-19 00:06:13 +02:00
|
|
|
{ .name = "access", .errmsg = true, },
|
2012-09-27 18:16:00 +02:00
|
|
|
{ .name = "arch_prctl", .errmsg = true, .alias = "prctl", },
|
2013-08-26 17:29:38 +02:00
|
|
|
{ .name = "brk", .hexret = true,
|
|
|
|
.arg_scnprintf = { [0] = SCA_HEX, /* brk */ }, },
|
2013-08-26 16:36:30 +02:00
|
|
|
{ .name = "mmap", .hexret = true, },
|
2013-07-30 21:38:23 +02:00
|
|
|
{ .name = "connect", .errmsg = true, },
|
2012-09-27 18:16:00 +02:00
|
|
|
{ .name = "fstat", .errmsg = true, .alias = "newfstat", },
|
|
|
|
{ .name = "fstatat", .errmsg = true, .alias = "newfstatat", },
|
|
|
|
{ .name = "futex", .errmsg = true, },
|
2013-08-26 17:29:38 +02:00
|
|
|
{ .name = "ioctl", .errmsg = true,
|
|
|
|
.arg_scnprintf = { [2] = SCA_HEX, /* arg */ }, },
|
2013-08-26 17:21:41 +02:00
|
|
|
{ .name = "lstat", .errmsg = true, .alias = "newlstat", },
|
2013-08-23 15:06:41 +02:00
|
|
|
{ .name = "madvise", .errmsg = true,
|
|
|
|
.arg_scnprintf = { [0] = SCA_HEX, /* start */
|
|
|
|
[2] = SCA_MADV_BHV, /* behavior */ }, },
|
2013-08-26 17:29:38 +02:00
|
|
|
{ .name = "mmap", .hexret = true,
|
perf trace: Add beautifier for mmap prot parm
[root@zoo ~]# perf trace -e mmap,mprotect sleep 1
0.984 ( 0.015 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd62ae000
1.114 ( 0.016 ms): mmap(addr: 0, len: 125100, prot: READ, flags: 2, fd: 3, off: 0 ) = 0xd628f000
1.252 ( 0.020 ms): mmap(addr: 0x33c1600000, len: 3896312, prot: EXEC|READ, flags: 2050, fd: 3, off: 0) = 0xc1600000
1.282 ( 0.024 ms): mprotect(start: 0x33c17ad000, len: 2097152, prot: NONE ) = 0
1.315 ( 0.026 ms): mmap(addr: 0x33c19ad000, len: 24576, prot: READ|WRITE, flags: 2066, fd: 3, off: 1757184) = 0xc19ad000
1.352 ( 0.017 ms): mmap(addr: 0x33c19b3000, len: 17400, prot: READ|WRITE, flags: 50, fd: 4294967295, off: 0) = 0xc19b3000
1.415 ( 0.011 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd628e000
1.440 ( 0.011 ms): mmap(addr: 0, len: 8192, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd628c000
1.569 ( 0.019 ms): mprotect(start: 0x606000, len: 4096, prot: READ ) = 0
1.591 ( 0.017 ms): mprotect(start: 0x33c19ad000, len: 16384, prot: READ ) = 0
1.616 ( 0.016 ms): mprotect(start: 0x33c1420000, len: 4096, prot: READ ) = 0
2.105 ( 0.018 ms): mmap(addr: 0, len: 104789808, prot: READ, flags: 2, fd: 3, off: 0 ) = 0xcfe9c000
[root@zoo ~]#
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-q1ubhdd9wigxneam616ggdsn@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2013-08-20 22:44:42 +02:00
|
|
|
.arg_scnprintf = { [0] = SCA_HEX, /* addr */
|
perf trace: Add beautifier for mmap flags parm
[root@zoo ~]# perf trace -e mmap,mprotect sleep 1
0.992 ( 0.015 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: 4294967295, off: 0) = 0xa60be000
1.108 ( 0.012 ms): mmap(addr: 0, len: 125100, prot: READ, flags: PRIVATE, fd: 3, off: 0 ) = 0xa609f000
1.209 ( 0.014 ms): mmap(addr: 0x33c1600000, len: 3896312, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 3, off: 0) = 0xc1600000
1.232 ( 0.018 ms): mprotect(start: 0x33c17ad000, len: 2097152, prot: NONE ) = 0
1.255 ( 0.018 ms): mmap(addr: 0x33c19ad000, len: 24576, prot: READ|WRITE, flags: PRIVATE|DENYWRITE|FIXED, fd: 3, off: 1757184) = 0xc19ad000
1.281 ( 0.011 ms): mmap(addr: 0x33c19b3000, len: 17400, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS|FIXED, fd: 4294967295, off: 0) = 0xc19b3000
1.328 ( 0.008 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: 4294967295, off: 0) = 0xa609e000
1.346 ( 0.008 ms): mmap(addr: 0, len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: 4294967295, off: 0) = 0xa609c000
1.443 ( 0.013 ms): mprotect(start: 0x606000, len: 4096, prot: READ ) = 0
1.459 ( 0.011 ms): mprotect(start: 0x33c19ad000, len: 16384, prot: READ ) = 0
1.477 ( 0.011 ms): mprotect(start: 0x33c1420000, len: 4096, prot: READ ) = 0
1.855 ( 0.013 ms): mmap(addr: 0, len: 104789808, prot: READ, flags: PRIVATE, fd: 3, off: 0) = 0x9fcac000
[root@zoo ~]#
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-q1ubhdd9wigxneam616ggdsn@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2013-08-23 15:48:33 +02:00
|
|
|
[2] = SCA_MMAP_PROT, /* prot */
|
|
|
|
[3] = SCA_MMAP_FLAGS, /* flags */ }, },
|
2013-08-26 17:29:38 +02:00
|
|
|
{ .name = "mprotect", .errmsg = true,
|
perf trace: Add beautifier for mmap prot parm
[root@zoo ~]# perf trace -e mmap,mprotect sleep 1
0.984 ( 0.015 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd62ae000
1.114 ( 0.016 ms): mmap(addr: 0, len: 125100, prot: READ, flags: 2, fd: 3, off: 0 ) = 0xd628f000
1.252 ( 0.020 ms): mmap(addr: 0x33c1600000, len: 3896312, prot: EXEC|READ, flags: 2050, fd: 3, off: 0) = 0xc1600000
1.282 ( 0.024 ms): mprotect(start: 0x33c17ad000, len: 2097152, prot: NONE ) = 0
1.315 ( 0.026 ms): mmap(addr: 0x33c19ad000, len: 24576, prot: READ|WRITE, flags: 2066, fd: 3, off: 1757184) = 0xc19ad000
1.352 ( 0.017 ms): mmap(addr: 0x33c19b3000, len: 17400, prot: READ|WRITE, flags: 50, fd: 4294967295, off: 0) = 0xc19b3000
1.415 ( 0.011 ms): mmap(addr: 0, len: 4096, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd628e000
1.440 ( 0.011 ms): mmap(addr: 0, len: 8192, prot: READ|WRITE, flags: 34, fd: 4294967295, off: 0) = 0xd628c000
1.569 ( 0.019 ms): mprotect(start: 0x606000, len: 4096, prot: READ ) = 0
1.591 ( 0.017 ms): mprotect(start: 0x33c19ad000, len: 16384, prot: READ ) = 0
1.616 ( 0.016 ms): mprotect(start: 0x33c1420000, len: 4096, prot: READ ) = 0
2.105 ( 0.018 ms): mmap(addr: 0, len: 104789808, prot: READ, flags: 2, fd: 3, off: 0 ) = 0xcfe9c000
[root@zoo ~]#
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-q1ubhdd9wigxneam616ggdsn@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2013-08-20 22:44:42 +02:00
|
|
|
.arg_scnprintf = { [0] = SCA_HEX, /* start */
|
|
|
|
[2] = SCA_MMAP_PROT, /* prot */ }, },
|
|
|
|
{ .name = "mremap", .hexret = true,
|
|
|
|
.arg_scnprintf = { [0] = SCA_HEX, /* addr */
|
|
|
|
[4] = SCA_HEX, /* new_addr */ }, },
|
2013-08-26 17:29:38 +02:00
|
|
|
{ .name = "munmap", .errmsg = true,
|
|
|
|
.arg_scnprintf = { [0] = SCA_HEX, /* addr */ }, },
|
2012-10-19 00:06:13 +02:00
|
|
|
{ .name = "open", .errmsg = true, },
|
2012-09-27 18:16:00 +02:00
|
|
|
{ .name = "poll", .errmsg = true, .timeout = true, },
|
|
|
|
{ .name = "ppoll", .errmsg = true, .timeout = true, },
|
2013-08-26 17:21:41 +02:00
|
|
|
{ .name = "pread", .errmsg = true, .alias = "pread64", },
|
|
|
|
{ .name = "pwrite", .errmsg = true, .alias = "pwrite64", },
|
2012-09-27 18:16:00 +02:00
|
|
|
{ .name = "read", .errmsg = true, },
|
|
|
|
{ .name = "recvfrom", .errmsg = true, },
|
|
|
|
{ .name = "select", .errmsg = true, .timeout = true, },
|
2012-10-19 00:06:13 +02:00
|
|
|
{ .name = "socket", .errmsg = true, },
|
2012-09-27 18:16:00 +02:00
|
|
|
{ .name = "stat", .errmsg = true, .alias = "newstat", },
|
2013-08-26 17:21:41 +02:00
|
|
|
{ .name = "uname", .errmsg = true, .alias = "newuname", },
|
2012-09-27 01:05:56 +02:00
|
|
|
};
|
|
|
|
|
|
|
|
static int syscall_fmt__cmp(const void *name, const void *fmtp)
|
|
|
|
{
|
|
|
|
const struct syscall_fmt *fmt = fmtp;
|
|
|
|
return strcmp(name, fmt->name);
|
|
|
|
}
|
|
|
|
|
|
|
|
static struct syscall_fmt *syscall_fmt__find(const char *name)
|
|
|
|
{
|
|
|
|
const int nmemb = ARRAY_SIZE(syscall_fmts);
|
|
|
|
return bsearch(name, syscall_fmts, nmemb, sizeof(struct syscall_fmt), syscall_fmt__cmp);
|
|
|
|
}
|
|
|
|
|
|
|
|
struct syscall {
|
|
|
|
struct event_format *tp_format;
|
|
|
|
const char *name;
|
2013-08-09 17:28:31 +02:00
|
|
|
bool filtered;
|
2012-09-27 01:05:56 +02:00
|
|
|
struct syscall_fmt *fmt;
|
2013-08-23 23:14:48 +02:00
|
|
|
size_t (**arg_scnprintf)(char *bf, size_t size, unsigned long arg);
|
2012-09-27 01:05:56 +02:00
|
|
|
};
|
|
|
|
|
perf trace: Add an event duration column
# perf trace usleep 1 | tail -10
0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763342848
0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763346944
0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882 ) = 0
0.540 ( 0.001 ms): brk(brk: 0 ) = 31928320
0.542 ( 0.002 ms): brk(brk: 32063488 ) = 32063488
1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0 ) = 0
1.462 ( 0.000 ms): exit_group(error_code: 0
#
This also comes from the tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-24 21:24:47 +02:00
|
|
|
static size_t fprintf_duration(unsigned long t, FILE *fp)
|
|
|
|
{
|
|
|
|
double duration = (double)t / NSEC_PER_MSEC;
|
|
|
|
size_t printed = fprintf(fp, "(");
|
|
|
|
|
|
|
|
if (duration >= 1.0)
|
|
|
|
printed += color_fprintf(fp, PERF_COLOR_RED, "%6.3f ms", duration);
|
|
|
|
else if (duration >= 0.01)
|
|
|
|
printed += color_fprintf(fp, PERF_COLOR_YELLOW, "%6.3f ms", duration);
|
|
|
|
else
|
|
|
|
printed += color_fprintf(fp, PERF_COLOR_NORMAL, "%6.3f ms", duration);
|
2013-08-19 17:01:10 +02:00
|
|
|
return printed + fprintf(fp, "): ");
|
perf trace: Add an event duration column
# perf trace usleep 1 | tail -10
0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763342848
0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763346944
0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882 ) = 0
0.540 ( 0.001 ms): brk(brk: 0 ) = 31928320
0.542 ( 0.002 ms): brk(brk: 32063488 ) = 32063488
1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0 ) = 0
1.462 ( 0.000 ms): exit_group(error_code: 0
#
This also comes from the tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-24 21:24:47 +02:00
|
|
|
}
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
struct thread_trace {
|
|
|
|
u64 entry_time;
|
|
|
|
u64 exit_time;
|
|
|
|
bool entry_pending;
|
2012-10-17 22:09:46 +02:00
|
|
|
unsigned long nr_events;
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
char *entry_str;
|
2012-10-17 22:13:12 +02:00
|
|
|
double runtime_ms;
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
};
|
|
|
|
|
|
|
|
static struct thread_trace *thread_trace__new(void)
|
|
|
|
{
|
|
|
|
return zalloc(sizeof(struct thread_trace));
|
|
|
|
}
|
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
static struct thread_trace *thread__trace(struct thread *thread, FILE *fp)
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
{
|
2012-10-17 22:09:46 +02:00
|
|
|
struct thread_trace *ttrace;
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
if (thread == NULL)
|
|
|
|
goto fail;
|
|
|
|
|
|
|
|
if (thread->priv == NULL)
|
|
|
|
thread->priv = thread_trace__new();
|
2012-10-17 22:09:46 +02:00
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
if (thread->priv == NULL)
|
|
|
|
goto fail;
|
|
|
|
|
2012-10-17 22:09:46 +02:00
|
|
|
ttrace = thread->priv;
|
|
|
|
++ttrace->nr_events;
|
|
|
|
|
|
|
|
return ttrace;
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
fail:
|
2013-08-19 17:01:10 +02:00
|
|
|
color_fprintf(fp, PERF_COLOR_RED,
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
"WARNING: not enough memory, dropping samples!\n");
|
|
|
|
return NULL;
|
|
|
|
}
|
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
struct trace {
|
2013-08-19 17:01:10 +02:00
|
|
|
struct perf_tool tool;
|
2012-09-27 01:05:56 +02:00
|
|
|
int audit_machine;
|
|
|
|
struct {
|
|
|
|
int max;
|
|
|
|
struct syscall *table;
|
|
|
|
} syscalls;
|
|
|
|
struct perf_record_opts opts;
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
struct machine host;
|
|
|
|
u64 base_time;
|
2013-08-19 17:01:10 +02:00
|
|
|
FILE *output;
|
2012-10-17 22:09:46 +02:00
|
|
|
unsigned long nr_events;
|
2013-08-21 17:56:21 +02:00
|
|
|
struct strlist *ev_qualifier;
|
|
|
|
bool not_ev_qualifier;
|
2012-10-17 22:13:12 +02:00
|
|
|
bool sched;
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
bool multiple_threads;
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
double duration_filter;
|
2012-10-17 22:13:12 +02:00
|
|
|
double runtime_ms;
|
2012-09-27 01:05:56 +02:00
|
|
|
};
|
|
|
|
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
static bool trace__filter_duration(struct trace *trace, double t)
|
|
|
|
{
|
|
|
|
return t < (trace->duration_filter * NSEC_PER_MSEC);
|
|
|
|
}
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
static size_t trace__fprintf_tstamp(struct trace *trace, u64 tstamp, FILE *fp)
|
|
|
|
{
|
|
|
|
double ts = (double)(tstamp - trace->base_time) / NSEC_PER_MSEC;
|
|
|
|
|
perf trace: Add an event duration column
# perf trace usleep 1 | tail -10
0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763342848
0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763346944
0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882 ) = 0
0.540 ( 0.001 ms): brk(brk: 0 ) = 31928320
0.542 ( 0.002 ms): brk(brk: 32063488 ) = 32063488
1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0 ) = 0
1.462 ( 0.000 ms): exit_group(error_code: 0
#
This also comes from the tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-24 21:24:47 +02:00
|
|
|
return fprintf(fp, "%10.3f ", ts);
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
}
|
|
|
|
|
2012-10-05 07:02:16 +02:00
|
|
|
static bool done = false;
|
|
|
|
|
|
|
|
static void sig_handler(int sig __maybe_unused)
|
|
|
|
{
|
|
|
|
done = true;
|
|
|
|
}
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
static size_t trace__fprintf_entry_head(struct trace *trace, struct thread *thread,
|
perf trace: Add an event duration column
# perf trace usleep 1 | tail -10
0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763342848
0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763346944
0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882 ) = 0
0.540 ( 0.001 ms): brk(brk: 0 ) = 31928320
0.542 ( 0.002 ms): brk(brk: 32063488 ) = 32063488
1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0 ) = 0
1.462 ( 0.000 ms): exit_group(error_code: 0
#
This also comes from the tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-24 21:24:47 +02:00
|
|
|
u64 duration, u64 tstamp, FILE *fp)
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
{
|
|
|
|
size_t printed = trace__fprintf_tstamp(trace, tstamp, fp);
|
perf trace: Add an event duration column
# perf trace usleep 1 | tail -10
0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763342848
0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763346944
0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882 ) = 0
0.540 ( 0.001 ms): brk(brk: 0 ) = 31928320
0.542 ( 0.002 ms): brk(brk: 32063488 ) = 32063488
1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0 ) = 0
1.462 ( 0.000 ms): exit_group(error_code: 0
#
This also comes from the tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-24 21:24:47 +02:00
|
|
|
printed += fprintf_duration(duration, fp);
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
|
|
|
|
if (trace->multiple_threads)
|
2013-07-04 15:20:31 +02:00
|
|
|
printed += fprintf(fp, "%d ", thread->tid);
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
|
|
|
|
return printed;
|
|
|
|
}
|
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
static int trace__process_event(struct trace *trace, struct machine *machine,
|
|
|
|
union perf_event *event)
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
{
|
|
|
|
int ret = 0;
|
|
|
|
|
|
|
|
switch (event->header.type) {
|
|
|
|
case PERF_RECORD_LOST:
|
2013-08-19 17:01:10 +02:00
|
|
|
color_fprintf(trace->output, PERF_COLOR_RED,
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
"LOST %" PRIu64 " events!\n", event->lost.lost);
|
|
|
|
ret = machine__process_lost_event(machine, event);
|
|
|
|
default:
|
|
|
|
ret = machine__process_event(machine, event);
|
|
|
|
break;
|
|
|
|
}
|
|
|
|
|
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
static int trace__tool_process(struct perf_tool *tool,
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
union perf_event *event,
|
|
|
|
struct perf_sample *sample __maybe_unused,
|
|
|
|
struct machine *machine)
|
|
|
|
{
|
2013-08-19 17:01:10 +02:00
|
|
|
struct trace *trace = container_of(tool, struct trace, tool);
|
|
|
|
return trace__process_event(trace, machine, event);
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
static int trace__symbols_init(struct trace *trace, struct perf_evlist *evlist)
|
|
|
|
{
|
|
|
|
int err = symbol__init();
|
|
|
|
|
|
|
|
if (err)
|
|
|
|
return err;
|
|
|
|
|
|
|
|
machine__init(&trace->host, "", HOST_KERNEL_ID);
|
|
|
|
machine__create_kernel_maps(&trace->host);
|
|
|
|
|
|
|
|
if (perf_target__has_task(&trace->opts.target)) {
|
2013-08-19 17:01:10 +02:00
|
|
|
err = perf_event__synthesize_thread_map(&trace->tool, evlist->threads,
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
trace__tool_process,
|
|
|
|
&trace->host);
|
|
|
|
} else {
|
2013-08-19 17:01:10 +02:00
|
|
|
err = perf_event__synthesize_threads(&trace->tool, trace__tool_process,
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
&trace->host);
|
|
|
|
}
|
|
|
|
|
|
|
|
if (err)
|
|
|
|
symbol__exit();
|
|
|
|
|
|
|
|
return err;
|
|
|
|
}
|
|
|
|
|
2013-08-23 23:14:48 +02:00
|
|
|
static int syscall__set_arg_fmts(struct syscall *sc)
|
|
|
|
{
|
|
|
|
struct format_field *field;
|
|
|
|
int idx = 0;
|
|
|
|
|
|
|
|
sc->arg_scnprintf = calloc(sc->tp_format->format.nr_fields - 1, sizeof(void *));
|
|
|
|
if (sc->arg_scnprintf == NULL)
|
|
|
|
return -1;
|
|
|
|
|
|
|
|
for (field = sc->tp_format->format.fields->next; field; field = field->next) {
|
2013-08-26 17:29:38 +02:00
|
|
|
if (sc->fmt && sc->fmt->arg_scnprintf[idx])
|
|
|
|
sc->arg_scnprintf[idx] = sc->fmt->arg_scnprintf[idx];
|
|
|
|
else if (field->flags & FIELD_IS_POINTER)
|
2013-08-23 23:14:48 +02:00
|
|
|
sc->arg_scnprintf[idx] = syscall_arg__scnprintf_hex;
|
|
|
|
++idx;
|
|
|
|
}
|
|
|
|
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
static int trace__read_syscall_info(struct trace *trace, int id)
|
|
|
|
{
|
|
|
|
char tp_name[128];
|
|
|
|
struct syscall *sc;
|
2012-10-20 17:39:03 +02:00
|
|
|
const char *name = audit_syscall_to_name(id, trace->audit_machine);
|
|
|
|
|
|
|
|
if (name == NULL)
|
|
|
|
return -1;
|
2012-09-27 01:05:56 +02:00
|
|
|
|
|
|
|
if (id > trace->syscalls.max) {
|
|
|
|
struct syscall *nsyscalls = realloc(trace->syscalls.table, (id + 1) * sizeof(*sc));
|
|
|
|
|
|
|
|
if (nsyscalls == NULL)
|
|
|
|
return -1;
|
|
|
|
|
|
|
|
if (trace->syscalls.max != -1) {
|
|
|
|
memset(nsyscalls + trace->syscalls.max + 1, 0,
|
|
|
|
(id - trace->syscalls.max) * sizeof(*sc));
|
|
|
|
} else {
|
|
|
|
memset(nsyscalls, 0, (id + 1) * sizeof(*sc));
|
|
|
|
}
|
|
|
|
|
|
|
|
trace->syscalls.table = nsyscalls;
|
|
|
|
trace->syscalls.max = id;
|
|
|
|
}
|
|
|
|
|
|
|
|
sc = trace->syscalls.table + id;
|
2012-10-20 17:39:03 +02:00
|
|
|
sc->name = name;
|
2013-08-09 17:28:31 +02:00
|
|
|
|
2013-08-21 17:56:21 +02:00
|
|
|
if (trace->ev_qualifier) {
|
|
|
|
bool in = strlist__find(trace->ev_qualifier, name) != NULL;
|
|
|
|
|
|
|
|
if (!(in ^ trace->not_ev_qualifier)) {
|
|
|
|
sc->filtered = true;
|
|
|
|
/*
|
|
|
|
* No need to do read tracepoint information since this will be
|
|
|
|
* filtered out.
|
|
|
|
*/
|
|
|
|
return 0;
|
|
|
|
}
|
2013-08-09 17:28:31 +02:00
|
|
|
}
|
|
|
|
|
2012-10-20 17:39:03 +02:00
|
|
|
sc->fmt = syscall_fmt__find(sc->name);
|
2012-09-27 01:05:56 +02:00
|
|
|
|
2012-09-27 18:16:00 +02:00
|
|
|
snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->name);
|
2012-09-27 01:05:56 +02:00
|
|
|
sc->tp_format = event_format__new("syscalls", tp_name);
|
2012-09-27 18:16:00 +02:00
|
|
|
|
|
|
|
if (sc->tp_format == NULL && sc->fmt && sc->fmt->alias) {
|
|
|
|
snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->fmt->alias);
|
|
|
|
sc->tp_format = event_format__new("syscalls", tp_name);
|
|
|
|
}
|
2012-09-27 01:05:56 +02:00
|
|
|
|
2013-08-23 23:14:48 +02:00
|
|
|
if (sc->tp_format == NULL)
|
|
|
|
return -1;
|
|
|
|
|
|
|
|
return syscall__set_arg_fmts(sc);
|
2012-09-27 01:05:56 +02:00
|
|
|
}
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
static size_t syscall__scnprintf_args(struct syscall *sc, char *bf, size_t size,
|
|
|
|
unsigned long *args)
|
2012-09-27 01:05:56 +02:00
|
|
|
{
|
|
|
|
int i = 0;
|
|
|
|
size_t printed = 0;
|
|
|
|
|
|
|
|
if (sc->tp_format != NULL) {
|
|
|
|
struct format_field *field;
|
|
|
|
|
|
|
|
for (field = sc->tp_format->format.fields->next; field; field = field->next) {
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
printed += scnprintf(bf + printed, size - printed,
|
2013-08-23 23:14:48 +02:00
|
|
|
"%s%s: ", printed ? ", " : "", field->name);
|
|
|
|
|
|
|
|
if (sc->arg_scnprintf && sc->arg_scnprintf[i])
|
|
|
|
printed += sc->arg_scnprintf[i](bf + printed, size - printed, args[i]);
|
|
|
|
else
|
|
|
|
printed += scnprintf(bf + printed, size - printed,
|
|
|
|
"%ld", args[i]);
|
|
|
|
++i;
|
2012-09-27 01:05:56 +02:00
|
|
|
}
|
|
|
|
} else {
|
|
|
|
while (i < 6) {
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
printed += scnprintf(bf + printed, size - printed,
|
|
|
|
"%sarg%d: %ld",
|
|
|
|
printed ? ", " : "", i, args[i]);
|
2012-09-27 01:05:56 +02:00
|
|
|
++i;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
return printed;
|
|
|
|
}
|
|
|
|
|
2012-09-28 22:58:36 +02:00
|
|
|
typedef int (*tracepoint_handler)(struct trace *trace, struct perf_evsel *evsel,
|
|
|
|
struct perf_sample *sample);
|
|
|
|
|
|
|
|
static struct syscall *trace__syscall_info(struct trace *trace,
|
|
|
|
struct perf_evsel *evsel,
|
|
|
|
struct perf_sample *sample)
|
|
|
|
{
|
|
|
|
int id = perf_evsel__intval(evsel, sample, "id");
|
|
|
|
|
|
|
|
if (id < 0) {
|
2013-08-22 22:55:25 +02:00
|
|
|
|
|
|
|
/*
|
|
|
|
* XXX: Noticed on x86_64, reproduced as far back as 3.0.36, haven't tried
|
|
|
|
* before that, leaving at a higher verbosity level till that is
|
|
|
|
* explained. Reproduced with plain ftrace with:
|
|
|
|
*
|
|
|
|
* echo 1 > /t/events/raw_syscalls/sys_exit/enable
|
|
|
|
* grep "NR -1 " /t/trace_pipe
|
|
|
|
*
|
|
|
|
* After generating some load on the machine.
|
|
|
|
*/
|
|
|
|
if (verbose > 1) {
|
|
|
|
static u64 n;
|
|
|
|
fprintf(trace->output, "Invalid syscall %d id, skipping (%s, %" PRIu64 ") ...\n",
|
|
|
|
id, perf_evsel__name(evsel), ++n);
|
|
|
|
}
|
2012-09-28 22:58:36 +02:00
|
|
|
return NULL;
|
|
|
|
}
|
|
|
|
|
|
|
|
if ((id > trace->syscalls.max || trace->syscalls.table[id].name == NULL) &&
|
|
|
|
trace__read_syscall_info(trace, id))
|
|
|
|
goto out_cant_read;
|
|
|
|
|
|
|
|
if ((id > trace->syscalls.max || trace->syscalls.table[id].name == NULL))
|
|
|
|
goto out_cant_read;
|
|
|
|
|
|
|
|
return &trace->syscalls.table[id];
|
|
|
|
|
|
|
|
out_cant_read:
|
2013-08-22 21:49:54 +02:00
|
|
|
if (verbose) {
|
|
|
|
fprintf(trace->output, "Problems reading syscall %d", id);
|
|
|
|
if (id <= trace->syscalls.max && trace->syscalls.table[id].name != NULL)
|
|
|
|
fprintf(trace->output, "(%s)", trace->syscalls.table[id].name);
|
|
|
|
fputs(" information\n", trace->output);
|
|
|
|
}
|
2012-09-28 22:58:36 +02:00
|
|
|
return NULL;
|
|
|
|
}
|
|
|
|
|
|
|
|
static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
|
|
|
|
struct perf_sample *sample)
|
|
|
|
{
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
char *msg;
|
2012-09-28 22:58:36 +02:00
|
|
|
void *args;
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
size_t printed = 0;
|
2013-08-09 17:28:31 +02:00
|
|
|
struct thread *thread;
|
2012-09-28 22:58:36 +02:00
|
|
|
struct syscall *sc = trace__syscall_info(trace, evsel, sample);
|
2013-08-09 17:28:31 +02:00
|
|
|
struct thread_trace *ttrace;
|
|
|
|
|
|
|
|
if (sc == NULL)
|
|
|
|
return -1;
|
2012-09-28 22:58:36 +02:00
|
|
|
|
2013-08-09 17:28:31 +02:00
|
|
|
if (sc->filtered)
|
|
|
|
return 0;
|
|
|
|
|
2013-08-27 10:23:03 +02:00
|
|
|
thread = machine__findnew_thread(&trace->host, sample->pid,
|
|
|
|
sample->tid);
|
2013-08-19 17:01:10 +02:00
|
|
|
ttrace = thread__trace(thread, trace->output);
|
2013-08-09 17:28:31 +02:00
|
|
|
if (ttrace == NULL)
|
2012-09-28 22:58:36 +02:00
|
|
|
return -1;
|
|
|
|
|
|
|
|
args = perf_evsel__rawptr(evsel, sample, "args");
|
|
|
|
if (args == NULL) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Problems reading syscall arguments\n");
|
2012-09-28 22:58:36 +02:00
|
|
|
return -1;
|
|
|
|
}
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
ttrace = thread->priv;
|
|
|
|
|
|
|
|
if (ttrace->entry_str == NULL) {
|
|
|
|
ttrace->entry_str = malloc(1024);
|
|
|
|
if (!ttrace->entry_str)
|
|
|
|
return -1;
|
|
|
|
}
|
|
|
|
|
|
|
|
ttrace->entry_time = sample->time;
|
|
|
|
msg = ttrace->entry_str;
|
|
|
|
printed += scnprintf(msg + printed, 1024 - printed, "%s(", sc->name);
|
|
|
|
|
|
|
|
printed += syscall__scnprintf_args(sc, msg + printed, 1024 - printed, args);
|
|
|
|
|
|
|
|
if (!strcmp(sc->name, "exit_group") || !strcmp(sc->name, "exit")) {
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
if (!trace->duration_filter) {
|
2013-08-19 17:01:10 +02:00
|
|
|
trace__fprintf_entry_head(trace, thread, 1, sample->time, trace->output);
|
|
|
|
fprintf(trace->output, "%-70s\n", ttrace->entry_str);
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
}
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
} else
|
|
|
|
ttrace->entry_pending = true;
|
2012-09-28 22:58:36 +02:00
|
|
|
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
|
|
|
|
struct perf_sample *sample)
|
|
|
|
{
|
|
|
|
int ret;
|
perf trace: Add an event duration column
# perf trace usleep 1 | tail -10
0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763342848
0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763346944
0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882 ) = 0
0.540 ( 0.001 ms): brk(brk: 0 ) = 31928320
0.542 ( 0.002 ms): brk(brk: 32063488 ) = 32063488
1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0 ) = 0
1.462 ( 0.000 ms): exit_group(error_code: 0
#
This also comes from the tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-24 21:24:47 +02:00
|
|
|
u64 duration = 0;
|
2013-08-09 17:28:31 +02:00
|
|
|
struct thread *thread;
|
2012-09-28 22:58:36 +02:00
|
|
|
struct syscall *sc = trace__syscall_info(trace, evsel, sample);
|
2013-08-09 17:28:31 +02:00
|
|
|
struct thread_trace *ttrace;
|
|
|
|
|
|
|
|
if (sc == NULL)
|
|
|
|
return -1;
|
2012-09-28 22:58:36 +02:00
|
|
|
|
2013-08-09 17:28:31 +02:00
|
|
|
if (sc->filtered)
|
|
|
|
return 0;
|
|
|
|
|
2013-08-27 10:23:03 +02:00
|
|
|
thread = machine__findnew_thread(&trace->host, sample->pid,
|
|
|
|
sample->tid);
|
2013-08-19 17:01:10 +02:00
|
|
|
ttrace = thread__trace(thread, trace->output);
|
2013-08-09 17:28:31 +02:00
|
|
|
if (ttrace == NULL)
|
2012-09-28 22:58:36 +02:00
|
|
|
return -1;
|
|
|
|
|
|
|
|
ret = perf_evsel__intval(evsel, sample, "ret");
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
ttrace = thread->priv;
|
|
|
|
|
|
|
|
ttrace->exit_time = sample->time;
|
|
|
|
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
if (ttrace->entry_time) {
|
perf trace: Add an event duration column
# perf trace usleep 1 | tail -10
0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763342848
0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763346944
0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882 ) = 0
0.540 ( 0.001 ms): brk(brk: 0 ) = 31928320
0.542 ( 0.002 ms): brk(brk: 32063488 ) = 32063488
1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0 ) = 0
1.462 ( 0.000 ms): exit_group(error_code: 0
#
This also comes from the tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-24 21:24:47 +02:00
|
|
|
duration = sample->time - ttrace->entry_time;
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
if (trace__filter_duration(trace, duration))
|
|
|
|
goto out;
|
|
|
|
} else if (trace->duration_filter)
|
|
|
|
goto out;
|
perf trace: Add an event duration column
# perf trace usleep 1 | tail -10
0.453 ( 0.002 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763342848
0.456 ( 0.001 ms): mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -763346944
0.459 ( 0.001 ms): arch_prctl(option: 4098, arg2: 140126839658240, arg3: 140126839652352, arg4: 34, arg5: 4294967295) = 0
0.473 ( 0.003 ms): mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
0.477 ( 0.003 ms): mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
0.483 ( 0.004 ms): munmap(addr: 140126839664640, len: 91882 ) = 0
0.540 ( 0.001 ms): brk(brk: 0 ) = 31928320
0.542 ( 0.002 ms): brk(brk: 32063488 ) = 32063488
1.456 ( 0.901 ms): nanosleep(rqtp: 140735472817168, rmtp: 0 ) = 0
1.462 ( 0.000 ms): exit_group(error_code: 0
#
This also comes from the tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-g9akh5hjw2kvjerpo9xror6f@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-24 21:24:47 +02:00
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
trace__fprintf_entry_head(trace, thread, duration, sample->time, trace->output);
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
|
|
|
|
if (ttrace->entry_pending) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "%-70s", ttrace->entry_str);
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
} else {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, " ... [");
|
|
|
|
color_fprintf(trace->output, PERF_COLOR_YELLOW, "continued");
|
|
|
|
fprintf(trace->output, "]: %s()", sc->name);
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
}
|
|
|
|
|
2013-08-26 16:28:34 +02:00
|
|
|
if (sc->fmt == NULL) {
|
|
|
|
signed_print:
|
|
|
|
fprintf(trace->output, ") = %d", ret);
|
|
|
|
} else if (ret < 0 && sc->fmt->errmsg) {
|
2012-09-28 22:58:36 +02:00
|
|
|
char bf[256];
|
|
|
|
const char *emsg = strerror_r(-ret, bf, sizeof(bf)),
|
|
|
|
*e = audit_errno_to_name(-ret);
|
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, ") = -1 %s %s", e, emsg);
|
2013-08-26 16:28:34 +02:00
|
|
|
} else if (ret == 0 && sc->fmt->timeout)
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, ") = 0 Timeout");
|
2013-08-26 16:36:30 +02:00
|
|
|
else if (sc->fmt->hexret)
|
|
|
|
fprintf(trace->output, ") = %#x", ret);
|
2012-09-28 22:58:36 +02:00
|
|
|
else
|
2013-08-26 16:28:34 +02:00
|
|
|
goto signed_print;
|
2012-09-28 22:58:36 +02:00
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
fputc('\n', trace->output);
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
out:
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
ttrace->entry_pending = false;
|
|
|
|
|
2012-09-28 22:58:36 +02:00
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
2012-10-17 22:13:12 +02:00
|
|
|
static int trace__sched_stat_runtime(struct trace *trace, struct perf_evsel *evsel,
|
|
|
|
struct perf_sample *sample)
|
|
|
|
{
|
|
|
|
u64 runtime = perf_evsel__intval(evsel, sample, "runtime");
|
|
|
|
double runtime_ms = (double)runtime / NSEC_PER_MSEC;
|
2013-08-27 10:23:03 +02:00
|
|
|
struct thread *thread = machine__findnew_thread(&trace->host,
|
|
|
|
sample->pid,
|
|
|
|
sample->tid);
|
2013-08-19 17:01:10 +02:00
|
|
|
struct thread_trace *ttrace = thread__trace(thread, trace->output);
|
2012-10-17 22:13:12 +02:00
|
|
|
|
|
|
|
if (ttrace == NULL)
|
|
|
|
goto out_dump;
|
|
|
|
|
|
|
|
ttrace->runtime_ms += runtime_ms;
|
|
|
|
trace->runtime_ms += runtime_ms;
|
|
|
|
return 0;
|
|
|
|
|
|
|
|
out_dump:
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "%s: comm=%s,pid=%u,runtime=%" PRIu64 ",vruntime=%" PRIu64 ")\n",
|
2012-10-17 22:13:12 +02:00
|
|
|
evsel->name,
|
|
|
|
perf_evsel__strval(evsel, sample, "comm"),
|
|
|
|
(pid_t)perf_evsel__intval(evsel, sample, "pid"),
|
|
|
|
runtime,
|
|
|
|
perf_evsel__intval(evsel, sample, "vruntime"));
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
2012-10-05 07:02:16 +02:00
|
|
|
static int trace__run(struct trace *trace, int argc, const char **argv)
|
2012-09-27 01:05:56 +02:00
|
|
|
{
|
2013-03-11 08:43:12 +01:00
|
|
|
struct perf_evlist *evlist = perf_evlist__new();
|
2012-09-28 22:58:36 +02:00
|
|
|
struct perf_evsel *evsel;
|
2012-10-17 22:09:46 +02:00
|
|
|
int err = -1, i;
|
|
|
|
unsigned long before;
|
2012-10-05 07:02:16 +02:00
|
|
|
const bool forks = argc > 0;
|
2012-09-27 01:05:56 +02:00
|
|
|
|
|
|
|
if (evlist == NULL) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Not enough memory to run!\n");
|
2012-09-27 01:05:56 +02:00
|
|
|
goto out;
|
|
|
|
}
|
|
|
|
|
2012-10-03 16:40:22 +02:00
|
|
|
if (perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_enter", trace__sys_enter) ||
|
|
|
|
perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_exit", trace__sys_exit)) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Couldn't read the raw_syscalls tracepoints information!\n");
|
2012-09-27 01:05:56 +02:00
|
|
|
goto out_delete_evlist;
|
|
|
|
}
|
|
|
|
|
2012-10-17 22:13:12 +02:00
|
|
|
if (trace->sched &&
|
|
|
|
perf_evlist__add_newtp(evlist, "sched", "sched_stat_runtime",
|
|
|
|
trace__sched_stat_runtime)) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Couldn't read the sched_stat_runtime tracepoint information!\n");
|
2012-10-17 22:13:12 +02:00
|
|
|
goto out_delete_evlist;
|
|
|
|
}
|
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
err = perf_evlist__create_maps(evlist, &trace->opts.target);
|
|
|
|
if (err < 0) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Problems parsing the target to trace, check your options!\n");
|
2012-09-27 01:05:56 +02:00
|
|
|
goto out_delete_evlist;
|
|
|
|
}
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
err = trace__symbols_init(trace, evlist);
|
|
|
|
if (err < 0) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Problems initializing symbol libraries!\n");
|
2013-03-15 06:48:50 +01:00
|
|
|
goto out_delete_maps;
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
}
|
|
|
|
|
2012-12-10 20:41:31 +01:00
|
|
|
perf_evlist__config(evlist, &trace->opts);
|
2012-09-27 01:05:56 +02:00
|
|
|
|
2012-10-05 07:02:16 +02:00
|
|
|
signal(SIGCHLD, sig_handler);
|
|
|
|
signal(SIGINT, sig_handler);
|
|
|
|
|
|
|
|
if (forks) {
|
2013-03-11 08:43:15 +01:00
|
|
|
err = perf_evlist__prepare_workload(evlist, &trace->opts.target,
|
2013-03-11 08:43:17 +01:00
|
|
|
argv, false, false);
|
2012-10-05 07:02:16 +02:00
|
|
|
if (err < 0) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Couldn't run the workload!\n");
|
2013-03-15 06:48:50 +01:00
|
|
|
goto out_delete_maps;
|
2012-10-05 07:02:16 +02:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
err = perf_evlist__open(evlist);
|
|
|
|
if (err < 0) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Couldn't create the events: %s\n", strerror(errno));
|
2013-03-15 06:48:50 +01:00
|
|
|
goto out_delete_maps;
|
2012-09-27 01:05:56 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
err = perf_evlist__mmap(evlist, UINT_MAX, false);
|
|
|
|
if (err < 0) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Couldn't mmap the events: %s\n", strerror(errno));
|
2013-03-15 06:48:50 +01:00
|
|
|
goto out_close_evlist;
|
2012-09-27 01:05:56 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
perf_evlist__enable(evlist);
|
2012-10-05 07:02:16 +02:00
|
|
|
|
|
|
|
if (forks)
|
|
|
|
perf_evlist__start_workload(evlist);
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
trace->multiple_threads = evlist->threads->map[0] == -1 || evlist->threads->nr > 1;
|
2012-09-27 01:05:56 +02:00
|
|
|
again:
|
2012-10-17 22:09:46 +02:00
|
|
|
before = trace->nr_events;
|
2012-09-27 01:05:56 +02:00
|
|
|
|
|
|
|
for (i = 0; i < evlist->nr_mmaps; i++) {
|
|
|
|
union perf_event *event;
|
|
|
|
|
|
|
|
while ((event = perf_evlist__mmap_read(evlist, i)) != NULL) {
|
|
|
|
const u32 type = event->header.type;
|
2012-09-28 22:58:36 +02:00
|
|
|
tracepoint_handler handler;
|
2012-09-27 01:05:56 +02:00
|
|
|
struct perf_sample sample;
|
|
|
|
|
2012-10-17 22:09:46 +02:00
|
|
|
++trace->nr_events;
|
2012-09-27 01:05:56 +02:00
|
|
|
|
|
|
|
err = perf_evlist__parse_sample(evlist, event, &sample);
|
|
|
|
if (err) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Can't parse sample, err = %d, skipping...\n", err);
|
2012-09-27 01:05:56 +02:00
|
|
|
continue;
|
|
|
|
}
|
|
|
|
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
if (trace->base_time == 0)
|
|
|
|
trace->base_time = sample.time;
|
|
|
|
|
|
|
|
if (type != PERF_RECORD_SAMPLE) {
|
2013-08-19 17:01:10 +02:00
|
|
|
trace__process_event(trace, &trace->host, event);
|
perf trace: Support interrupted syscalls
Using the same strategies as in the tmp.perf/trace2, i.e. the 'trace'
tool implemented by tglx, just updated to the current codebase.
Example:
[root@sandy linux]# perf trace usleep 1 | tail
2.003: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128396288
2.017: mmap(addr: 0, len: 4096, prot: 3, flags: 34, fd: 4294967295, off: 0 ) = -2128400384
2.029: arch_prctl(option: 4098, arg2: 140146949441280, arg3: 140146949435392, arg4: 34, arg5: 4294967295) = 0
2.084: mprotect(start: 208741634048, len: 16384, prot: 1 ) = 0
2.098: mprotect(start: 208735956992, len: 4096, prot: 1 ) = 0
2.122: munmap(addr: 140146949447680, len: 91882 ) = 0
2.359: brk(brk: 0 ) = 28987392
2.371: brk(brk: 29122560 ) = 29122560
2.490: nanosleep(rqtp: 140735694241504, rmtp: 0 ) = 0
2.507: exit_group(error_code: 0
[root@sandy linux]#
For now the timestamp and duration are always on, will be selectable.
Also if multiple threads are being monitored, its tid will appear.
The ret output continues to be interpreted a la strace.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Link: http://lkml.kernel.org/n/tip-ly9ulroru4my5isn0xe9gr0m@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-06 23:43:19 +02:00
|
|
|
continue;
|
|
|
|
}
|
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
evsel = perf_evlist__id2evsel(evlist, sample.id);
|
|
|
|
if (evsel == NULL) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "Unknown tp ID %" PRIu64 ", skipping...\n", sample.id);
|
2012-09-27 01:05:56 +02:00
|
|
|
continue;
|
|
|
|
}
|
|
|
|
|
2012-10-20 18:08:46 +02:00
|
|
|
if (sample.raw_data == NULL) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace->output, "%s sample with no payload for tid: %d, cpu %d, raw_size=%d, skipping...\n",
|
2012-10-20 18:08:46 +02:00
|
|
|
perf_evsel__name(evsel), sample.tid,
|
|
|
|
sample.cpu, sample.raw_size);
|
|
|
|
continue;
|
|
|
|
}
|
|
|
|
|
2012-09-28 22:58:36 +02:00
|
|
|
handler = evsel->handler.func;
|
|
|
|
handler(trace, evsel, &sample);
|
2012-09-27 01:05:56 +02:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2012-10-17 22:09:46 +02:00
|
|
|
if (trace->nr_events == before) {
|
2012-10-05 07:02:16 +02:00
|
|
|
if (done)
|
2013-03-15 06:48:50 +01:00
|
|
|
goto out_unmap_evlist;
|
2012-10-05 07:02:16 +02:00
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
poll(evlist->pollfd, evlist->nr_fds, -1);
|
2012-10-05 07:02:16 +02:00
|
|
|
}
|
|
|
|
|
|
|
|
if (done)
|
|
|
|
perf_evlist__disable(evlist);
|
2012-09-27 01:05:56 +02:00
|
|
|
|
|
|
|
goto again;
|
|
|
|
|
2013-03-15 06:48:50 +01:00
|
|
|
out_unmap_evlist:
|
|
|
|
perf_evlist__munmap(evlist);
|
|
|
|
out_close_evlist:
|
|
|
|
perf_evlist__close(evlist);
|
|
|
|
out_delete_maps:
|
|
|
|
perf_evlist__delete_maps(evlist);
|
2012-09-27 01:05:56 +02:00
|
|
|
out_delete_evlist:
|
|
|
|
perf_evlist__delete(evlist);
|
|
|
|
out:
|
|
|
|
return err;
|
|
|
|
}
|
|
|
|
|
2012-10-17 22:13:12 +02:00
|
|
|
static size_t trace__fprintf_threads_header(FILE *fp)
|
|
|
|
{
|
|
|
|
size_t printed;
|
|
|
|
|
|
|
|
printed = fprintf(fp, "\n _____________________________________________________________________\n");
|
|
|
|
printed += fprintf(fp," __) Summary of events (__\n\n");
|
|
|
|
printed += fprintf(fp," [ task - pid ] [ events ] [ ratio ] [ runtime ]\n");
|
|
|
|
printed += fprintf(fp," _____________________________________________________________________\n\n");
|
|
|
|
|
|
|
|
return printed;
|
|
|
|
}
|
|
|
|
|
|
|
|
static size_t trace__fprintf_thread_summary(struct trace *trace, FILE *fp)
|
|
|
|
{
|
|
|
|
size_t printed = trace__fprintf_threads_header(fp);
|
|
|
|
struct rb_node *nd;
|
|
|
|
|
|
|
|
for (nd = rb_first(&trace->host.threads); nd; nd = rb_next(nd)) {
|
|
|
|
struct thread *thread = rb_entry(nd, struct thread, rb_node);
|
|
|
|
struct thread_trace *ttrace = thread->priv;
|
|
|
|
const char *color;
|
|
|
|
double ratio;
|
|
|
|
|
|
|
|
if (ttrace == NULL)
|
|
|
|
continue;
|
|
|
|
|
|
|
|
ratio = (double)ttrace->nr_events / trace->nr_events * 100.0;
|
|
|
|
|
|
|
|
color = PERF_COLOR_NORMAL;
|
|
|
|
if (ratio > 50.0)
|
|
|
|
color = PERF_COLOR_RED;
|
|
|
|
else if (ratio > 25.0)
|
|
|
|
color = PERF_COLOR_GREEN;
|
|
|
|
else if (ratio > 5.0)
|
|
|
|
color = PERF_COLOR_YELLOW;
|
|
|
|
|
|
|
|
printed += color_fprintf(fp, color, "%20s", thread->comm);
|
2013-07-04 15:20:31 +02:00
|
|
|
printed += fprintf(fp, " - %-5d :%11lu [", thread->tid, ttrace->nr_events);
|
2012-10-17 22:13:12 +02:00
|
|
|
printed += color_fprintf(fp, color, "%5.1f%%", ratio);
|
|
|
|
printed += fprintf(fp, " ] %10.3f ms\n", ttrace->runtime_ms);
|
|
|
|
}
|
|
|
|
|
|
|
|
return printed;
|
|
|
|
}
|
|
|
|
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
static int trace__set_duration(const struct option *opt, const char *str,
|
|
|
|
int unset __maybe_unused)
|
|
|
|
{
|
|
|
|
struct trace *trace = opt->value;
|
|
|
|
|
|
|
|
trace->duration_filter = atof(str);
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
static int trace__open_output(struct trace *trace, const char *filename)
|
|
|
|
{
|
|
|
|
struct stat st;
|
|
|
|
|
|
|
|
if (!stat(filename, &st) && st.st_size) {
|
|
|
|
char oldname[PATH_MAX];
|
|
|
|
|
|
|
|
scnprintf(oldname, sizeof(oldname), "%s.old", filename);
|
|
|
|
unlink(oldname);
|
|
|
|
rename(filename, oldname);
|
|
|
|
}
|
|
|
|
|
|
|
|
trace->output = fopen(filename, "w");
|
|
|
|
|
|
|
|
return trace->output == NULL ? -errno : 0;
|
|
|
|
}
|
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
int cmd_trace(int argc, const char **argv, const char *prefix __maybe_unused)
|
|
|
|
{
|
|
|
|
const char * const trace_usage[] = {
|
2012-10-05 07:02:16 +02:00
|
|
|
"perf trace [<options>] [<command>]",
|
|
|
|
"perf trace [<options>] -- <command> [<options>]",
|
2012-09-27 01:05:56 +02:00
|
|
|
NULL
|
|
|
|
};
|
|
|
|
struct trace trace = {
|
|
|
|
.audit_machine = audit_detect_machine(),
|
|
|
|
.syscalls = {
|
|
|
|
. max = -1,
|
|
|
|
},
|
|
|
|
.opts = {
|
|
|
|
.target = {
|
|
|
|
.uid = UINT_MAX,
|
|
|
|
.uses_mmap = true,
|
|
|
|
},
|
|
|
|
.user_freq = UINT_MAX,
|
|
|
|
.user_interval = ULLONG_MAX,
|
|
|
|
.no_delay = true,
|
|
|
|
.mmap_pages = 1024,
|
|
|
|
},
|
2013-08-19 17:01:10 +02:00
|
|
|
.output = stdout,
|
2012-09-27 01:05:56 +02:00
|
|
|
};
|
2013-08-19 17:01:10 +02:00
|
|
|
const char *output_name = NULL;
|
2013-08-09 17:28:31 +02:00
|
|
|
const char *ev_qualifier_str = NULL;
|
2012-09-27 01:05:56 +02:00
|
|
|
const struct option trace_options[] = {
|
2013-08-09 17:28:31 +02:00
|
|
|
OPT_STRING('e', "expr", &ev_qualifier_str, "expr",
|
|
|
|
"list of events to trace"),
|
2013-08-19 17:01:10 +02:00
|
|
|
OPT_STRING('o', "output", &output_name, "file", "output file name"),
|
2012-09-27 01:05:56 +02:00
|
|
|
OPT_STRING('p', "pid", &trace.opts.target.pid, "pid",
|
|
|
|
"trace events on existing process id"),
|
2013-08-20 19:15:45 +02:00
|
|
|
OPT_STRING('t', "tid", &trace.opts.target.tid, "tid",
|
2012-09-27 01:05:56 +02:00
|
|
|
"trace events on existing thread id"),
|
2013-08-20 19:15:45 +02:00
|
|
|
OPT_BOOLEAN('a', "all-cpus", &trace.opts.target.system_wide,
|
2012-09-27 01:05:56 +02:00
|
|
|
"system-wide collection from all CPUs"),
|
2013-08-20 19:15:45 +02:00
|
|
|
OPT_STRING('C', "cpu", &trace.opts.target.cpu_list, "cpu",
|
2012-09-27 01:05:56 +02:00
|
|
|
"list of cpus to monitor"),
|
2013-08-20 19:15:45 +02:00
|
|
|
OPT_BOOLEAN('i', "no-inherit", &trace.opts.no_inherit,
|
2012-09-27 01:05:56 +02:00
|
|
|
"child tasks do not inherit counters"),
|
2013-08-20 19:15:45 +02:00
|
|
|
OPT_UINTEGER('m', "mmap-pages", &trace.opts.mmap_pages,
|
2012-09-27 01:05:56 +02:00
|
|
|
"number of mmap data pages"),
|
2013-08-20 19:15:45 +02:00
|
|
|
OPT_STRING('u', "uid", &trace.opts.target.uid_str, "user",
|
2012-09-27 01:05:56 +02:00
|
|
|
"user to profile"),
|
perf trace: Add duration filter
Example:
[acme@sandy linux]$ perf trace --duration 0.025 usleep 1
2.221 ( 0.958 ms): 6724 execve(arg0: 140733557168278, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = -2
3.690 ( 1.443 ms): 6724 execve(arg0: 140733557168295, arg1: 140733557178768, arg2: 16134304, arg3: 140733557167840, arg4: 7955998171588342573, arg5: 6723) = 0
3.979 ( 0.048 ms): 6724 open(filename: 208733843841, flags: 0, mode: 1 ) = 3
4.071 ( 0.075 ms): 6724 open(filename: 139744419925673, flags: 0, mode: 0 ) = 3
4.318 ( 0.056 ms): 6724 nanosleep(rqtp: 140734030404608, rmtp: 0 ) = 0
[acme@sandy linux]$ perf trace --duration 0.100 usleep 1
1.143 ( 1.021 ms): 6726 execve(arg0: 140736323962279, arg1: 140736323972752, arg2: 34926752, arg3: 140736323961824, arg4: 7955998171588342573, arg5: 6725) = 0
[acme@sandy linux]$
Cherry picked from tmp.perf/trace2 branch.
Cc: David Ahern <dsahern@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Jiri Olsa <jolsa@redhat.com>
Cc: Mike Galbraith <efault@gmx.de>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Paul Mackerras <paulus@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/n/tip-oslw2j2958we9qf0ctra4whd@git.kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2012-10-08 14:56:00 +02:00
|
|
|
OPT_CALLBACK(0, "duration", &trace, "float",
|
|
|
|
"show only events with duration > N.M ms",
|
|
|
|
trace__set_duration),
|
2012-10-17 22:13:12 +02:00
|
|
|
OPT_BOOLEAN(0, "sched", &trace.sched, "show blocking scheduler events"),
|
2013-08-22 21:49:54 +02:00
|
|
|
OPT_INCR('v', "verbose", &verbose, "be more verbose"),
|
2012-09-27 01:05:56 +02:00
|
|
|
OPT_END()
|
|
|
|
};
|
|
|
|
int err;
|
2012-10-05 07:02:13 +02:00
|
|
|
char bf[BUFSIZ];
|
2012-09-27 01:05:56 +02:00
|
|
|
|
|
|
|
argc = parse_options(argc, argv, trace_options, trace_usage, 0);
|
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
if (output_name != NULL) {
|
|
|
|
err = trace__open_output(&trace, output_name);
|
|
|
|
if (err < 0) {
|
|
|
|
perror("failed to create output file");
|
|
|
|
goto out;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2013-08-09 17:28:31 +02:00
|
|
|
if (ev_qualifier_str != NULL) {
|
2013-08-21 17:56:21 +02:00
|
|
|
const char *s = ev_qualifier_str;
|
|
|
|
|
|
|
|
trace.not_ev_qualifier = *s == '!';
|
|
|
|
if (trace.not_ev_qualifier)
|
|
|
|
++s;
|
|
|
|
trace.ev_qualifier = strlist__new(true, s);
|
2013-08-09 17:28:31 +02:00
|
|
|
if (trace.ev_qualifier == NULL) {
|
2013-08-19 17:01:10 +02:00
|
|
|
fputs("Not enough memory to parse event qualifier",
|
|
|
|
trace.output);
|
|
|
|
err = -ENOMEM;
|
|
|
|
goto out_close;
|
2013-08-09 17:28:31 +02:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2012-10-05 07:02:13 +02:00
|
|
|
err = perf_target__validate(&trace.opts.target);
|
|
|
|
if (err) {
|
|
|
|
perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace.output, "%s", bf);
|
|
|
|
goto out_close;
|
2012-10-05 07:02:13 +02:00
|
|
|
}
|
|
|
|
|
2012-09-27 01:05:56 +02:00
|
|
|
err = perf_target__parse_uid(&trace.opts.target);
|
|
|
|
if (err) {
|
|
|
|
perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
|
2013-08-19 17:01:10 +02:00
|
|
|
fprintf(trace.output, "%s", bf);
|
|
|
|
goto out_close;
|
2012-09-27 01:05:56 +02:00
|
|
|
}
|
|
|
|
|
2012-10-05 07:02:16 +02:00
|
|
|
if (!argc && perf_target__none(&trace.opts.target))
|
2012-10-05 07:02:14 +02:00
|
|
|
trace.opts.target.system_wide = true;
|
|
|
|
|
2012-10-17 22:13:12 +02:00
|
|
|
err = trace__run(&trace, argc, argv);
|
|
|
|
|
|
|
|
if (trace.sched && !err)
|
2013-08-19 17:01:10 +02:00
|
|
|
trace__fprintf_thread_summary(&trace, trace.output);
|
2012-10-17 22:13:12 +02:00
|
|
|
|
2013-08-19 17:01:10 +02:00
|
|
|
out_close:
|
|
|
|
if (output_name != NULL)
|
|
|
|
fclose(trace.output);
|
|
|
|
out:
|
2012-10-17 22:13:12 +02:00
|
|
|
return err;
|
2012-09-27 01:05:56 +02:00
|
|
|
}
|