[PATCH] perf trace: Simplify '--summary' output

[PATCH] perf trace: Simplify '--summary' output

[Pekka Enberg]

The output of 'perf trace --summary' tries to be too cute with
formatting and makes it very hard to read.  Simplify it in the spirit of
"strace -c":

[penberg@localhost libtrading]$ perf trace -a --duration 10000 --summary -- sleep 1
^C
 Summary of events:

 dbus-daemon (555), 10 events, 0.0%, 0.000 msec

                                                    msec/call
   syscall            calls      min      avg      max stddev
   --------------- -------- -------- -------- -------- ------
   sendmsg                2    0.002    0.005    0.008  55.00
   recvmsg                2    0.002    0.003    0.005  44.00
   epoll_wait             1    0.000    0.000    0.000   0.00

 NetworkManager (667), 56 events, 0.0%, 0.000 msec

                                                    msec/call
   syscall            calls      min      avg      max stddev
   --------------- -------- -------- -------- -------- ------
   poll                   2    0.000    0.002    0.003 100.00
   sendmsg               10    0.004    0.007    0.016  15.41
   recvmsg               16    0.002    0.003    0.005   8.24

 zfs-fuse (669), 4 events, 0.0%, 0.000 msec

                                                    msec/call
   syscall            calls      min      avg      max stddev
   --------------- -------- -------- -------- -------- ------
   futex                  2    0.000    0.001    0.002 100.00

Cc: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>
Signed-off-by: Pekka Enberg <penberg@kernel.org>
---
 tools/perf/builtin-trace.c | 25 ++++++++++++-------------
 1 file changed, 12 insertions(+), 13 deletions(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index f841d2a..22354c8 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -2082,12 +2082,7 @@ 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, "                                  syscall  count    min     avg    max  stddev\n");
-	printed += fprintf(fp, "                                                   msec    msec   msec     %%\n");
-	printed += fprintf(fp, " _____________________________________________________________________________\n\n");
+	printed  = fprintf(fp, "\n Summary of events:\n\n");
 
 	return printed;
 }
@@ -2105,6 +2100,10 @@ static size_t thread__dump_stats(struct thread_trace *ttrace,
 
 	printed += fprintf(fp, "\n");
 
+	printed += fprintf(fp, "                                                    msec/call\n");
+	printed += fprintf(fp, "   syscall            calls      min      avg      max stddev\n");
+	printed += fprintf(fp, "   --------------- -------- -------- -------- -------- ------\n");
+
 	/* each int_node is a syscall */
 	while (inode) {
 		stats = inode->priv;
@@ -2119,10 +2118,10 @@ static size_t thread__dump_stats(struct thread_trace *ttrace,
 			avg /= NSEC_PER_MSEC;
 
 			sc = &trace->syscalls.table[inode->i];
-			printed += fprintf(fp, "%24s  %14s : ", "", sc->name);
-			printed += fprintf(fp, "%5" PRIu64 "  %8.3f  %8.3f",
+			printed += fprintf(fp, "   %-15s", sc->name);
+			printed += fprintf(fp, " %8" PRIu64 " %8.3f %8.3f",
 					   n, min, avg);
-			printed += fprintf(fp, "  %8.3f  %6.2f\n", max, pct);
+			printed += fprintf(fp, " %8.3f %6.2f\n", max, pct);
 		}
 
 		inode = intlist__next(inode);
@@ -2163,10 +2162,10 @@ static int trace__fprintf_one_thread(struct thread *thread, void *priv)
 	else if (ratio > 5.0)
 		color = PERF_COLOR_YELLOW;
 
-	printed += color_fprintf(fp, color, "%20s", thread__comm_str(thread));
-	printed += fprintf(fp, " - %-5d :%11lu   [", thread->tid, ttrace->nr_events);
-	printed += color_fprintf(fp, color, "%5.1f%%", ratio);
-	printed += fprintf(fp, " ] %10.3f ms\n", ttrace->runtime_ms);
+	printed += color_fprintf(fp, color, " %s (%d), ", thread__comm_str(thread), thread->tid);
+	printed += fprintf(fp, "%lu events, ", ttrace->nr_events);
+	printed += color_fprintf(fp, color, "%.1f%%", ratio);
+	printed += fprintf(fp, ", %.3f msec\n", ttrace->runtime_ms);
 	printed += thread__dump_stats(ttrace, trace, fp);
 
 	data->printed += printed;
-- 
1.8.3.1

Re: [PATCH] perf trace: Simplify '--summary' output

[Ingo Molnar]

* Pekka Enberg <penberg@kernel.org> wrote:

> The output of 'perf trace --summary' tries to be too cute with
> formatting and makes it very hard to read.  Simplify it in the spirit of
> "strace -c":
> 
> [penberg@localhost libtrading]$ perf trace -a --duration 10000 --summary -- sleep 1
> ^C

Btw., just a very small feature suggestion - instead of forcing the 
somewhat counter-intuitive '-- sleep X' pattern it might be helpful to 
have a general option parser for 'delay' values, which would allow a wide 
range of time units like:

	--delay 10.5h
        --delay 0.1s
        --delay 0.1sec

etc. - with the default unit being 'seconds'.

That parser could then be applied to '--duration' filter as well, allowing 
things like:

   --duration 10sec

which IMHO are more obvious to read (and easier to remember!) than 
'--duration 10000'.

>  Summary of events:
> 
>  dbus-daemon (555), 10 events, 0.0%, 0.000 msec
> 
>                                                     msec/call
>    syscall            calls      min      avg      max stddev
>    --------------- -------- -------- -------- -------- ------
>    sendmsg                2    0.002    0.005    0.008  55.00
>    recvmsg                2    0.002    0.003    0.005  44.00
>    epoll_wait             1    0.000    0.000    0.000   0.00

In what units is stddev? Percentage? If yes then it might be useful to 
output it as %. [and probably to restrict precision to a single digit, 
standard deviations are rarely more accurate than 0.1%.]

>  NetworkManager (667), 56 events, 0.0%, 0.000 msec
> 
>                                                     msec/call
>    syscall            calls      min      avg      max stddev
>    --------------- -------- -------- -------- -------- ------
>    poll                   2    0.000    0.002    0.003 100.00
>    sendmsg               10    0.004    0.007    0.016  15.41
>    recvmsg               16    0.002    0.003    0.005   8.24
> 
>  zfs-fuse (669), 4 events, 0.0%, 0.000 msec
> 
>                                                     msec/call
>    syscall            calls      min      avg      max stddev
>    --------------- -------- -------- -------- -------- ------
>    futex                  2    0.000    0.001    0.002 100.00

Nice looking output btw! :-)

Acked-by: Ingo Molnar <mingo@kernel.org>

Thanks,

	Ingo

Re: [PATCH] perf trace: Simplify '--summary' output

[David Ahern]

On 11/12/13, 2:33 PM, Ingo Molnar wrote:
>> >  Summary of events:
>> >
>> >  dbus-daemon (555), 10 events, 0.0%, 0.000 msec
>> >
>> >                                                     msec/call
>> >    syscall            calls      min      avg      max stddev
>> >    --------------- -------- -------- -------- -------- ------
>> >    sendmsg                2    0.002    0.005    0.008  55.00
>> >    recvmsg                2    0.002    0.003    0.005  44.00
>> >    epoll_wait             1    0.000    0.000    0.000   0.00
> In what units is stddev? Percentage? If yes then it might be useful to
> output it as %. [and probably to restrict precision to a single digit,
> standard deviations are rarely more accurate than 0.1%.]
>

%. That was dropped in the recent output change.

David

Re: [PATCH] perf trace: Simplify '--summary' output

[Pekka Enberg]

On 11/12/13 11:36 PM, David Ahern wrote:
> On 11/12/13, 2:33 PM, Ingo Molnar wrote:
>>> >  Summary of events:
>>> >
>>> >  dbus-daemon (555), 10 events, 0.0%, 0.000 msec
>>> >
>>> > msec/call
>>> >    syscall            calls      min      avg      max stddev
>>> >    --------------- -------- -------- -------- -------- ------
>>> >    sendmsg                2    0.002    0.005    0.008 55.00
>>> >    recvmsg                2    0.002    0.003    0.005 44.00
>>> >    epoll_wait             1    0.000    0.000    0.000 0.00
>> In what units is stddev? Percentage? If yes then it might be useful to
>> output it as %. [and probably to restrict precision to a single digit,
>> standard deviations are rarely more accurate than 0.1%.]
>>
>
> %. That was dropped in the recent output change.

Sorry about that. Why do we show them in percentages, btw? Standard 
deviation is usually represented in the same unit as the data to make it 
readable.

                         Pekka

Re: [PATCH] perf trace: Simplify '--summary' output

[Ingo Molnar]

* David Ahern <dsahern@gmail.com> wrote:

> On 11/12/13, 2:33 PM, Ingo Molnar wrote:
> >>>  Summary of events:
> >>>
> >>>  dbus-daemon (555), 10 events, 0.0%, 0.000 msec
> >>>
> >>>                                                     msec/call
> >>>    syscall            calls      min      avg      max stddev
> >>>    --------------- -------- -------- -------- -------- ------
> >>>    sendmsg                2    0.002    0.005    0.008  55.00
> >>>    recvmsg                2    0.002    0.003    0.005  44.00
> >>>    epoll_wait             1    0.000    0.000    0.000   0.00
> >In what units is stddev? Percentage? If yes then it might be useful to
> >output it as %. [and probably to restrict precision to a single digit,
> >standard deviations are rarely more accurate than 0.1%.]
> >
> 
> %. That was dropped in the recent output change.

So if you prefer unit-less lines that's defensible, perhaps output the 
unit somewhere else:

    syscall            calls     min      avg      max  stddev
                               (msec)   (msec)   (msec)    (%)
    --------------- -------- -------- -------- -------- ------
    sendmsg                2    0.002    0.005    0.008  55.00
    recvmsg                2    0.002    0.003    0.005  44.00
    epoll_wait             1    0.000    0.000    0.000   0.00

or so?

Thanks,

	Ingo

Re: [PATCH] perf trace: Simplify '--summary' output

[David Ahern]

On 11/12/13, 2:38 PM, Pekka Enberg wrote:
> Sorry about that. Why do we show them in percentages, btw? Standard
> deviation is usually represented in the same unit as the data to make it
> readable.
>

Consistency. perf-stat shows relative stddev, for example.

David

Re: [PATCH] perf trace: Simplify '--summary' output

[Ingo Molnar]

* Pekka Enberg <penberg@iki.fi> wrote:

> > %. That was dropped in the recent output change.
> 
> Sorry about that. Why do we show them in percentages, btw? Standard 
> deviation is usually represented in the same unit as the data to make it 
> readable.

So, the problem with output in the same unit is that it's hard to tell
'at a glance' what the real, relative stddev is:

    syscall            calls      min      avg      max stddev
    --------------- -------- -------- -------- -------- ------
    sendmsg                2    0.002    0.005    0.008 0.001
    recvmsg                2    0.002    0.003    0.005 0.0003
    epoll_wait             1    0.000    0.000    0.000 0.000

it's also harder to compare stddevs side by side if they are absolute.

The way we try to solve this in perf stat is to output:

  comet:~/tip> perf stat -a --repeat 10 --null usleep 1000

   Performance counter stats for 'system wide' (10 runs):

       0.001772475 seconds time elapsed                                          ( +-  0.58% )

Oh, btw., would anyone would like to implement a cool new 'perf time' 
subcommand, which offers time(1) look-alike output but with better 
precision and sttdev output?

  comet:~> time usleep 1000

  real    0m0.002s
  user    0m0.000s
  sys     0m0.000s

  # Mockup:

  comet:~> perf time --repeat 10 usleep 1000

  real    0m0.002s      [ +- 1.38% ]
  user    0m0.000s      [ +- 0.53% ]
  sys     0m0.000s      [ +- 0.43% ]

?

I'd use it instead of 'time' all the time ;-)

Thanks,

	Ingo

[tip:perf/urgent] perf trace: Simplify '--summary' output

[tip-bot for Pekka Enberg]

Commit-ID:  99ff7150547382ee612c40d8d6a0670ddec7c9fc
Gitweb:     http://git.kernel.org/tip/99ff7150547382ee612c40d8d6a0670ddec7c9fc
Author:     Pekka Enberg <penberg@kernel.org>
AuthorDate: Tue, 12 Nov 2013 16:42:14 +0200
Committer:  Arnaldo Carvalho de Melo <acme@redhat.com>
CommitDate: Tue, 12 Nov 2013 13:00:38 -0300

perf trace: Simplify '--summary' output

The output of 'perf trace --summary' tries to be too cute with
formatting and makes it very hard to read.  Simplify it in the spirit of
"strace -c":

[penberg@localhost libtrading]$ perf trace -a --duration 10000 --summary -- sleep 1
^C
 Summary of events:

 dbus-daemon (555), 10 events, 0.0%, 0.000 msec

                                                    msec/call
   syscall            calls      min      avg      max stddev
   --------------- -------- -------- -------- -------- ------
   sendmsg                2    0.002    0.005    0.008  55.00
   recvmsg                2    0.002    0.003    0.005  44.00
   epoll_wait             1    0.000    0.000    0.000   0.00

 NetworkManager (667), 56 events, 0.0%, 0.000 msec

                                                    msec/call
   syscall            calls      min      avg      max stddev
   --------------- -------- -------- -------- -------- ------
   poll                   2    0.000    0.002    0.003 100.00
   sendmsg               10    0.004    0.007    0.016  15.41
   recvmsg               16    0.002    0.003    0.005   8.24

 zfs-fuse (669), 4 events, 0.0%, 0.000 msec

                                                    msec/call
   syscall            calls      min      avg      max stddev
   --------------- -------- -------- -------- -------- ------
   futex                  2    0.000    0.001    0.002 100.00

Signed-off-by: Pekka Enberg <penberg@kernel.org>
Cc: David Ahern <dsahern@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
Link: http://lkml.kernel.org/r/1384267334-18953-1-git-send-email-penberg@kernel.org
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/builtin-trace.c | 25 ++++++++++++-------------
 1 file changed, 12 insertions(+), 13 deletions(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 8990fbe..0964c0c 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -2090,12 +2090,7 @@ 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, "                                  syscall  count    min     avg    max  stddev\n");
-	printed += fprintf(fp, "                                                   msec    msec   msec     %%\n");
-	printed += fprintf(fp, " _____________________________________________________________________________\n\n");
+	printed  = fprintf(fp, "\n Summary of events:\n\n");
 
 	return printed;
 }
@@ -2113,6 +2108,10 @@ static size_t thread__dump_stats(struct thread_trace *ttrace,
 
 	printed += fprintf(fp, "\n");
 
+	printed += fprintf(fp, "                                                    msec/call\n");
+	printed += fprintf(fp, "   syscall            calls      min      avg      max stddev\n");
+	printed += fprintf(fp, "   --------------- -------- -------- -------- -------- ------\n");
+
 	/* each int_node is a syscall */
 	while (inode) {
 		stats = inode->priv;
@@ -2127,10 +2126,10 @@ static size_t thread__dump_stats(struct thread_trace *ttrace,
 			avg /= NSEC_PER_MSEC;
 
 			sc = &trace->syscalls.table[inode->i];
-			printed += fprintf(fp, "%24s  %14s : ", "", sc->name);
-			printed += fprintf(fp, "%5" PRIu64 "  %8.3f  %8.3f",
+			printed += fprintf(fp, "   %-15s", sc->name);
+			printed += fprintf(fp, " %8" PRIu64 " %8.3f %8.3f",
 					   n, min, avg);
-			printed += fprintf(fp, "  %8.3f  %6.2f\n", max, pct);
+			printed += fprintf(fp, " %8.3f %6.2f\n", max, pct);
 		}
 
 		inode = intlist__next(inode);
@@ -2171,10 +2170,10 @@ static int trace__fprintf_one_thread(struct thread *thread, void *priv)
 	else if (ratio > 5.0)
 		color = PERF_COLOR_YELLOW;
 
-	printed += color_fprintf(fp, color, "%20s", thread__comm_str(thread));
-	printed += fprintf(fp, " - %-5d :%11lu   [", thread->tid, ttrace->nr_events);
-	printed += color_fprintf(fp, color, "%5.1f%%", ratio);
-	printed += fprintf(fp, " ] %10.3f ms\n", ttrace->runtime_ms);
+	printed += color_fprintf(fp, color, " %s (%d), ", thread__comm_str(thread), thread->tid);
+	printed += fprintf(fp, "%lu events, ", ttrace->nr_events);
+	printed += color_fprintf(fp, color, "%.1f%%", ratio);
+	printed += fprintf(fp, ", %.3f msec\n", ttrace->runtime_ms);
 	printed += thread__dump_stats(ttrace, trace, fp);
 
 	data->printed += printed;

Re: [PATCH] perf trace: Simplify '--summary' output

[Pekka Enberg]

On 11/12/13 11:40 PM, Ingo Molnar wrote:
> So if you prefer unit-less lines that's defensible, perhaps output the
> unit somewhere else:
>
>      syscall            calls     min      avg      max  stddev
>                                 (msec)   (msec)   (msec)    (%)
>      --------------- -------- -------- -------- -------- ------
>      sendmsg                2    0.002    0.005    0.008  55.00
>      recvmsg                2    0.002    0.003    0.005  44.00
>      epoll_wait             1    0.000    0.000    0.000   0.00
>
> or so?

Looks good.  I'll make a patch later today unless someone else beats me 
to it.

                         Pekka

Re: [PATCH] perf trace: Simplify '--summary' output

[Ingo Molnar]

* Pekka Enberg <penberg@iki.fi> wrote:

> On 11/12/13 11:40 PM, Ingo Molnar wrote:
> >So if you prefer unit-less lines that's defensible, perhaps output the
> >unit somewhere else:
> >
> >     syscall            calls     min      avg      max  stddev
> >                                (msec)   (msec)   (msec)    (%)
> >     --------------- -------- -------- -------- -------- ------
> >     sendmsg                2    0.002    0.005    0.008  55.00
> >     recvmsg                2    0.002    0.003    0.005  44.00
> >     epoll_wait             1    0.000    0.000    0.000   0.00
> >
> >or so?
> 
> Looks good.  I'll make a patch later today unless someone else beats
> me to it.

Maybe this variant is even better:

     syscall            calls     min      avg      max      stddev
                                (msec)   (msec)   (msec)        (%)
     --------------- -------- -------- -------- --------     ------
     sendmsg                2    0.002    0.005    0.008      55.0%
     recvmsg                2    0.002    0.003    0.005      44.0%
     epoll_wait             1    0.000    0.000    0.000       0.0%

Note how we can squeeze the % into that column by using only single digit 
precision percentage - double digit is pretty pointless IMO.

Also note that the different nature of the stddev column stands out better 
if there's four more horizontal spaces separating it from the other 
colums.

But maybe it's just me.

Btw., the msec colums seem a bit narrow, they allow up to 9999.999msec 
values which is 10 seconds. If any delay is larger than that then what 
happens, do the values get unaligned in an ugly fashion like they so often 
do in 'vmstat'? Maybe space for one or two digits more would give it more 
breathing space:

     syscall            calls      min       avg       max      stddev
                                 (msec)    (msec)    (msec)        (%)
     --------------- -------- --------- --------- ---------     ------
     sendmsg                2     0.002     0.005     0.008      55.0%
     recvmsg                2     0.002     0.003     0.005      44.0%
     epoll_wait             1     0.000     0.000     0.000       0.0%

This still looks directly pasteable into email and commit logs and looks 
nicely compact on my terminals as well.

Thanks,

	Ingo