From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756060AbbHGCFo (ORCPT ); Thu, 6 Aug 2015 22:05:44 -0400 Received: from casper.infradead.org ([85.118.1.10]:46946 "EHLO casper.infradead.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754011AbbHGCFl (ORCPT ); Thu, 6 Aug 2015 22:05:41 -0400 From: Arnaldo Carvalho de Melo To: Ingo Molnar Cc: linux-kernel@vger.kernel.org, Milian Wolff , Arnaldo Carvalho de Melo Subject: [PATCH 01/26] perf trace: Add total time column to summary. Date: Thu, 6 Aug 2015 22:58:10 -0300 Message-Id: <1438912715-4000-2-git-send-email-acme@kernel.org> X-Mailer: git-send-email 2.1.0 In-Reply-To: <1438912715-4000-1-git-send-email-acme@kernel.org> References: <1438912715-4000-1-git-send-email-acme@kernel.org> X-SRS-Rewrite: SMTP reverse-path rewritten from by casper.infradead.org See http://www.infradead.org/rpr.html Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org From: Milian Wolff It is cumbersome to manually calculate the total time spent in a given syscall by multiplying the average value with the number of calls. Instead, we now do this directly inside perf trace. Note that this is also done by 'strace', which even adds a column with relative numbers - something we could do in the future. Example: perf trace -s find /some/folder > /dev/null Summary of events: find (19976), 700123 events, 100.0%, 0.000 msec syscall calls total min avg max stddev (msec) (msec) (msec) (msec) (%) --------------- -------- --------- --------- --------- --------- ------ read 4 0.006 0.001 0.002 0.003 27.42% write 8046 9.617 0.001 0.001 0.035 0.56% open 34196 40.384 0.001 0.001 0.071 0.30% close 68375 57.104 0.001 0.001 0.076 0.25% stat 4 0.004 0.001 0.001 0.001 3.14% fstat 34189 27.518 0.001 0.001 0.060 0.34% mmap 13 0.029 0.001 0.002 0.003 10.74% mprotect 6 0.018 0.002 0.003 0.005 17.04% munmap 3 0.014 0.003 0.005 0.006 24.87% brk 87 0.490 0.001 0.006 0.016 6.50% ioctl 3 0.004 0.001 0.001 0.003 36.39% access 1 0.004 0.004 0.004 0.004 0.00% uname 1 0.001 0.001 0.001 0.001 0.00% getdents 68393 143.600 0.001 0.002 0.187 0.95% fchdir 68371 56.980 0.001 0.001 0.111 0.39% arch_prctl 1 0.001 0.001 0.001 0.001 0.00% openat 34184 41.737 0.001 0.001 0.102 0.41% newfstatat 34184 41.180 0.001 0.001 0.064 0.34% Signed-off-by: Milian Wolff Tested-by: Arnaldo Carvalho de Melo LPU-Reference: 1438853069-5902-1-git-send-email-milian.wolff@kdab.com Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-trace.c | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c index a47497011c93..a25048c85b76 100644 --- a/tools/perf/builtin-trace.c +++ b/tools/perf/builtin-trace.c @@ -2773,9 +2773,9 @@ static size_t thread__dump_stats(struct thread_trace *ttrace, printed += fprintf(fp, "\n"); - printed += fprintf(fp, " syscall calls min avg max stddev\n"); - printed += fprintf(fp, " (msec) (msec) (msec) (%%)\n"); - printed += fprintf(fp, " --------------- -------- --------- --------- --------- ------\n"); + printed += fprintf(fp, " syscall calls total min avg max stddev\n"); + printed += fprintf(fp, " (msec) (msec) (msec) (msec) (%%)\n"); + printed += fprintf(fp, " --------------- -------- --------- --------- --------- --------- ------\n"); /* each int_node is a syscall */ while (inode) { @@ -2792,8 +2792,8 @@ static size_t thread__dump_stats(struct thread_trace *ttrace, sc = &trace->syscalls.table[inode->i]; printed += fprintf(fp, " %-15s", sc->name); - printed += fprintf(fp, " %8" PRIu64 " %9.3f %9.3f", - n, min, avg); + printed += fprintf(fp, " %8" PRIu64 " %9.3f %9.3f %9.3f", + n, avg * n, min, avg); printed += fprintf(fp, " %9.3f %9.2f%%\n", max, pct); } -- 2.1.0