mirror of
https://mirrors.bfsu.edu.cn/git/linux.git
synced 2024-12-05 10:04:12 +08:00
perf trace: Add syscall failure stats to -s/--summary and -S/--with-summary
Just like strace has: # trace -s sleep 1 Summary of events: sleep (32370), 80 events, 93.0% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ nanosleep 1 0 1000.402 1000.402 1000.402 1000.402 0.00% mmap 8 0 0.023 0.002 0.003 0.004 8.49% close 5 0 0.015 0.001 0.003 0.009 51.39% mprotect 4 0 0.014 0.002 0.003 0.005 16.95% openat 3 0 0.013 0.003 0.004 0.005 14.29% munmap 1 0 0.010 0.010 0.010 0.010 0.00% read 4 0 0.005 0.001 0.001 0.002 16.83% brk 4 0 0.004 0.001 0.001 0.002 20.82% access 1 1 0.004 0.004 0.004 0.004 0.00% fstat 3 0 0.003 0.001 0.001 0.001 12.17% lseek 3 0 0.003 0.001 0.001 0.001 11.45% arch_prctl 2 1 0.002 0.001 0.001 0.001 2.30% execve 1 0 0.000 0.000 0.000 0.000 0.00% # # perf trace -S sleep 1 ? ... [continued]: execve()) = 0 0.028 brk(brk: NULL) = 0x559f5bd96000 0.033 arch_prctl(option: 0x3001, arg2: 0x7ffda8b715a0) = -1 EINVAL (Invalid argument) 0.046 access(filename: "/etc/ld.so.preload", mode: R) = -1 ENOENT (No such file or directory) 0.055 openat(dfd: CWD, filename: "/etc/ld.so.cache", flags: RDONLY|CLOEXEC) = 3 0.060 fstat(fd: 3, statbuf: 0x7ffda8b707a0) = 0 0.062 mmap(addr: NULL, len: 134346, prot: READ, flags: PRIVATE, fd: 3, off: 0) = 0x7f3aedfc4000 0.066 close(fd: 3) = 0 0.079 openat(dfd: CWD, filename: "/lib64/libc.so.6", flags: RDONLY|CLOEXEC) = 3 0.085 read(fd: 3, buf: 0x7ffda8b70948, count: 832) = 832 0.088 lseek(fd: 3, offset: 792, whence: SET) = 792 0.090 read(fd: 3, buf: 0x7ffda8b70810, count: 68) = 68 0.093 fstat(fd: 3, statbuf: 0x7ffda8b707f0) = 0 0.095 mmap(addr: NULL, len: 8192, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS) = 0x7f3aedfc2000 0.101 lseek(fd: 3, offset: 792, whence: SET) = 792 0.103 read(fd: 3, buf: 0x7ffda8b70450, count: 68) = 68 0.105 lseek(fd: 3, offset: 864, whence: SET) = 864 0.107 read(fd: 3, buf: 0x7ffda8b70470, count: 32) = 32 0.110 mmap(addr: NULL, len: 1857472, prot: READ, flags: PRIVATE|DENYWRITE, fd: 3, off: 0) = 0x7f3aeddfc000 0.114 mprotect(start: 0x7f3aede1e000, len: 1679360, prot: NONE) = 0 0.121 mmap(addr: 0x7f3aede1e000, len: 1363968, prot: READ|EXEC, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x22000) = 0x7f3aede1e000 0.127 mmap(addr: 0x7f3aedf6b000, len: 311296, prot: READ, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x16f000) = 0x7f3aedf6b000 0.131 mmap(addr: 0x7f3aedfb8000, len: 24576, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 3, off: 0x1bb000) = 0x7f3aedfb8000 0.138 mmap(addr: 0x7f3aedfbe000, len: 14272, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7f3aedfbe000 0.147 close(fd: 3) = 0 0.158 arch_prctl(option: SET_FS, arg2: 0x7f3aedfc3580) = 0 0.210 mprotect(start: 0x7f3aedfb8000, len: 16384, prot: READ) = 0 0.230 mprotect(start: 0x559f5b27d000, len: 4096, prot: READ) = 0 0.236 mprotect(start: 0x7f3aee00f000, len: 4096, prot: READ) = 0 0.240 munmap(addr: 0x7f3aedfc4000, len: 134346) = 0 0.300 brk(brk: NULL) = 0x559f5bd96000 0.302 brk(brk: 0x559f5bdb7000) = 0x559f5bdb7000 0.305 brk(brk: NULL) = 0x559f5bdb7000 0.310 openat(dfd: CWD, filename: "/usr/lib/locale/locale-archive", flags: RDONLY|CLOEXEC) = 3 0.315 fstat(fd: 3, statbuf: 0x7f3aedfbdac0) = 0 0.318 mmap(addr: NULL, len: 217750512, prot: READ, flags: PRIVATE, fd: 3, off: 0) = 0x7f3ae0e52000 0.325 close(fd: 3) = 0 0.358 nanosleep(rqtp: 0x7ffda8b714b0, rmtp: NULL) = 0 1000.622 close(fd: 1) = 0 1000.641 close(fd: 2) = 0 1000.664 exit_group(error_code: 0) = ? Summary of events: sleep (722), 80 events, 93.0% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ nanosleep 1 0 1000.194 1000.194 1000.194 1000.194 0.00% mmap 8 0 0.025 0.002 0.003 0.005 10.17% close 5 0 0.018 0.001 0.004 0.010 50.18% mprotect 4 0 0.016 0.003 0.004 0.006 16.81% openat 3 0 0.011 0.003 0.004 0.004 6.57% munmap 1 0 0.010 0.010 0.010 0.010 0.00% brk 4 0 0.005 0.001 0.001 0.002 20.72% read 4 0 0.005 0.001 0.001 0.002 16.71% access 1 1 0.005 0.005 0.005 0.005 0.00% fstat 3 0 0.004 0.001 0.001 0.002 14.82% lseek 3 0 0.003 0.001 0.001 0.001 11.66% arch_prctl 2 1 0.002 0.001 0.001 0.001 3.59% execve 1 0 0.000 0.000 0.000 0.000 0.00% # Works for system wide, e.g. for 1ms: # perf trace -s -a sleep 0.001 Summary of events: sleep (768), 94 events, 37.9% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ nanosleep 1 0 1.133 1.133 1.133 1.133 0.00% execve 7 6 0.351 0.003 0.050 0.316 88.53% mmap 8 0 0.024 0.002 0.003 0.004 8.86% mprotect 4 0 0.017 0.003 0.004 0.006 16.02% openat 3 0 0.013 0.004 0.004 0.005 8.34% munmap 1 0 0.010 0.010 0.010 0.010 0.00% brk 4 0 0.007 0.001 0.002 0.002 10.99% close 5 0 0.005 0.001 0.001 0.002 11.69% read 5 0 0.005 0.000 0.001 0.002 30.53% access 1 1 0.004 0.004 0.004 0.004 0.00% fstat 3 0 0.004 0.001 0.001 0.002 10.74% lseek 3 0 0.003 0.001 0.001 0.001 10.20% arch_prctl 2 1 0.002 0.001 0.001 0.001 3.34% Web Content (21258), 46 events, 18.5% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ recvmsg 12 12 0.015 0.001 0.001 0.002 8.50% futex 2 0 0.008 0.003 0.004 0.005 27.08% poll 6 0 0.006 0.000 0.001 0.002 22.14% read 2 0 0.006 0.002 0.003 0.003 26.08% write 1 0 0.002 0.002 0.002 0.002 0.00% Web Content (4365), 36 events, 14.5% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ recvmsg 10 10 0.015 0.001 0.002 0.003 11.83% poll 5 0 0.006 0.000 0.001 0.002 28.44% futex 2 0 0.005 0.001 0.003 0.004 48.29% read 1 0 0.003 0.003 0.003 0.003 0.00% Timer (21275), 14 events, 5.6% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ futex 6 1 0.240 0.000 0.040 0.149 64.58% write 1 0 0.008 0.008 0.008 0.008 0.00% Timer (4383), 14 events, 5.6% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ futex 6 2 0.186 0.000 0.031 0.181 96.45% write 1 0 0.010 0.010 0.010 0.010 0.00% Web Content (20354), 28 events, 11.3% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ recvmsg 8 8 0.010 0.001 0.001 0.002 15.24% poll 4 0 0.004 0.000 0.001 0.002 35.68% futex 1 0 0.003 0.003 0.003 0.003 0.00% read 1 0 0.003 0.003 0.003 0.003 0.00% Timer (20371), 10 events, 4.0% syscall calls errors total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- ------ -------- --------- --------- --------- ------ futex 4 1 0.077 0.000 0.019 0.075 95.46% write 1 0 0.005 0.005 0.005 0.005 0.00% [root@quaco ~]# Cc: Adrian Hunter <adrian.hunter@intel.com> Cc: Andi Kleen <ak@linux.intel.com> Cc: Brendan Gregg <brendan.d.gregg@gmail.com> Cc: Jiri Olsa <jolsa@kernel.org> Cc: Luis Cláudio Gonçalves <lclaudio@redhat.com> Cc: Namhyung Kim <namhyung@kernel.org> Link: https://lkml.kernel.org/n/tip-k7kh2muo5oeg56yx446hnw9v@git.kernel.org Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
This commit is contained in:
parent
dd071024bf
commit
8eded45fcd
@ -1958,11 +1958,16 @@ out_cant_read:
|
|||||||
return NULL;
|
return NULL;
|
||||||
}
|
}
|
||||||
|
|
||||||
|
struct syscall_stats {
|
||||||
|
struct stats stats;
|
||||||
|
u64 nr_failures;
|
||||||
|
};
|
||||||
|
|
||||||
static void thread__update_stats(struct thread_trace *ttrace,
|
static void thread__update_stats(struct thread_trace *ttrace,
|
||||||
int id, struct perf_sample *sample)
|
int id, struct perf_sample *sample, long err)
|
||||||
{
|
{
|
||||||
struct int_node *inode;
|
struct int_node *inode;
|
||||||
struct stats *stats;
|
struct syscall_stats *stats;
|
||||||
u64 duration = 0;
|
u64 duration = 0;
|
||||||
|
|
||||||
inode = intlist__findnew(ttrace->syscall_stats, id);
|
inode = intlist__findnew(ttrace->syscall_stats, id);
|
||||||
@ -1971,17 +1976,22 @@ static void thread__update_stats(struct thread_trace *ttrace,
|
|||||||
|
|
||||||
stats = inode->priv;
|
stats = inode->priv;
|
||||||
if (stats == NULL) {
|
if (stats == NULL) {
|
||||||
stats = malloc(sizeof(struct stats));
|
stats = malloc(sizeof(*stats));
|
||||||
if (stats == NULL)
|
if (stats == NULL)
|
||||||
return;
|
return;
|
||||||
init_stats(stats);
|
|
||||||
|
stats->nr_failures = 0;
|
||||||
|
init_stats(&stats->stats);
|
||||||
inode->priv = stats;
|
inode->priv = stats;
|
||||||
}
|
}
|
||||||
|
|
||||||
if (ttrace->entry_time && sample->time > ttrace->entry_time)
|
if (ttrace->entry_time && sample->time > ttrace->entry_time)
|
||||||
duration = sample->time - ttrace->entry_time;
|
duration = sample->time - ttrace->entry_time;
|
||||||
|
|
||||||
update_stats(stats, duration);
|
update_stats(&stats->stats, duration);
|
||||||
|
|
||||||
|
if (err < 0)
|
||||||
|
++stats->nr_failures;
|
||||||
}
|
}
|
||||||
|
|
||||||
static int trace__printf_interrupted_entry(struct trace *trace)
|
static int trace__printf_interrupted_entry(struct trace *trace)
|
||||||
@ -2226,11 +2236,11 @@ static int trace__sys_exit(struct trace *trace, struct evsel *evsel,
|
|||||||
|
|
||||||
trace__fprintf_sample(trace, evsel, sample, thread);
|
trace__fprintf_sample(trace, evsel, sample, thread);
|
||||||
|
|
||||||
if (trace->summary)
|
|
||||||
thread__update_stats(ttrace, id, sample);
|
|
||||||
|
|
||||||
ret = perf_evsel__sc_tp_uint(evsel, ret, sample);
|
ret = perf_evsel__sc_tp_uint(evsel, ret, sample);
|
||||||
|
|
||||||
|
if (trace->summary)
|
||||||
|
thread__update_stats(ttrace, id, sample, ret);
|
||||||
|
|
||||||
if (!trace->fd_path_disabled && sc->is_open && ret >= 0 && ttrace->filename.pending_open) {
|
if (!trace->fd_path_disabled && sc->is_open && ret >= 0 && ttrace->filename.pending_open) {
|
||||||
trace__set_fd_pathname(thread, ret, ttrace->filename.name);
|
trace__set_fd_pathname(thread, ret, ttrace->filename.name);
|
||||||
ttrace->filename.pending_open = false;
|
ttrace->filename.pending_open = false;
|
||||||
@ -4016,17 +4026,17 @@ static size_t trace__fprintf_threads_header(FILE *fp)
|
|||||||
}
|
}
|
||||||
|
|
||||||
DEFINE_RESORT_RB(syscall_stats, a->msecs > b->msecs,
|
DEFINE_RESORT_RB(syscall_stats, a->msecs > b->msecs,
|
||||||
struct stats *stats;
|
struct syscall_stats *stats;
|
||||||
double msecs;
|
double msecs;
|
||||||
int syscall;
|
int syscall;
|
||||||
)
|
)
|
||||||
{
|
{
|
||||||
struct int_node *source = rb_entry(nd, struct int_node, rb_node);
|
struct int_node *source = rb_entry(nd, struct int_node, rb_node);
|
||||||
struct stats *stats = source->priv;
|
struct syscall_stats *stats = source->priv;
|
||||||
|
|
||||||
entry->syscall = source->i;
|
entry->syscall = source->i;
|
||||||
entry->stats = stats;
|
entry->stats = stats;
|
||||||
entry->msecs = stats ? (u64)stats->n * (avg_stats(stats) / NSEC_PER_MSEC) : 0;
|
entry->msecs = stats ? (u64)stats->stats.n * (avg_stats(&stats->stats) / NSEC_PER_MSEC) : 0;
|
||||||
}
|
}
|
||||||
|
|
||||||
static size_t thread__dump_stats(struct thread_trace *ttrace,
|
static size_t thread__dump_stats(struct thread_trace *ttrace,
|
||||||
@ -4042,26 +4052,26 @@ static size_t thread__dump_stats(struct thread_trace *ttrace,
|
|||||||
|
|
||||||
printed += fprintf(fp, "\n");
|
printed += fprintf(fp, "\n");
|
||||||
|
|
||||||
printed += fprintf(fp, " syscall calls total min avg max stddev\n");
|
printed += fprintf(fp, " syscall calls errors total min avg max stddev\n");
|
||||||
printed += fprintf(fp, " (msec) (msec) (msec) (msec) (%%)\n");
|
printed += fprintf(fp, " (msec) (msec) (msec) (msec) (%%)\n");
|
||||||
printed += fprintf(fp, " --------------- -------- --------- --------- --------- --------- ------\n");
|
printed += fprintf(fp, " --------------- -------- ------ -------- --------- --------- --------- ------\n");
|
||||||
|
|
||||||
resort_rb__for_each_entry(nd, syscall_stats) {
|
resort_rb__for_each_entry(nd, syscall_stats) {
|
||||||
struct stats *stats = syscall_stats_entry->stats;
|
struct syscall_stats *stats = syscall_stats_entry->stats;
|
||||||
if (stats) {
|
if (stats) {
|
||||||
double min = (double)(stats->min) / NSEC_PER_MSEC;
|
double min = (double)(stats->stats.min) / NSEC_PER_MSEC;
|
||||||
double max = (double)(stats->max) / NSEC_PER_MSEC;
|
double max = (double)(stats->stats.max) / NSEC_PER_MSEC;
|
||||||
double avg = avg_stats(stats);
|
double avg = avg_stats(&stats->stats);
|
||||||
double pct;
|
double pct;
|
||||||
u64 n = (u64) stats->n;
|
u64 n = (u64)stats->stats.n;
|
||||||
|
|
||||||
pct = avg ? 100.0 * stddev_stats(stats)/avg : 0.0;
|
pct = avg ? 100.0 * stddev_stats(&stats->stats) / avg : 0.0;
|
||||||
avg /= NSEC_PER_MSEC;
|
avg /= NSEC_PER_MSEC;
|
||||||
|
|
||||||
sc = &trace->syscalls.table[syscall_stats_entry->syscall];
|
sc = &trace->syscalls.table[syscall_stats_entry->syscall];
|
||||||
printed += fprintf(fp, " %-15s", sc->name);
|
printed += fprintf(fp, " %-15s", sc->name);
|
||||||
printed += fprintf(fp, " %8" PRIu64 " %9.3f %9.3f %9.3f",
|
printed += fprintf(fp, " %8" PRIu64 " %6" PRIu64 " %9.3f %9.3f %9.3f",
|
||||||
n, syscall_stats_entry->msecs, min, avg);
|
n, stats->nr_failures, syscall_stats_entry->msecs, min, avg);
|
||||||
printed += fprintf(fp, " %9.3f %9.2f%%\n", max, pct);
|
printed += fprintf(fp, " %9.3f %9.2f%%\n", max, pct);
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
|
Loading…
Reference in New Issue
Block a user