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

2013-11-13 Thread Ingo Molnar

* Pekka Enberg  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:
> >
> > syscallcalls min  avg  max  stddev
> >(msec)   (msec)   (msec)(%)
> > ---     --
> > sendmsg20.0020.0050.008  55.00
> > recvmsg20.0020.0030.005  44.00
> > epoll_wait 10.0000.0000.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:

 syscallcalls min  avg  max  stddev
(msec)   (msec)   (msec)(%)
 ---     --
 sendmsg20.0020.0050.008  55.0%
 recvmsg20.0020.0030.005  44.0%
 epoll_wait 10.0000.0000.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 .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:

 syscallcalls  min   avg   max  stddev
 (msec)(msec)(msec)(%)
 ---  - - - --
 sendmsg2 0.002 0.005 0.008  55.0%
 recvmsg2 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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-13 Thread Ingo Molnar

* Pekka Enberg penb...@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:
 
  syscallcalls min  avg  max  stddev
 (msec)   (msec)   (msec)(%)
  ---     --
  sendmsg20.0020.0050.008  55.00
  recvmsg20.0020.0030.005  44.00
  epoll_wait 10.0000.0000.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:

 syscallcalls min  avg  max  stddev
(msec)   (msec)   (msec)(%)
 ---     --
 sendmsg20.0020.0050.008  55.0%
 recvmsg20.0020.0030.005  44.0%
 epoll_wait 10.0000.0000.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 .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:

 syscallcalls  min   avg   max  stddev
 (msec)(msec)(msec)(%)
 ---  - - - --
 sendmsg2 0.002 0.005 0.008  55.0%
 recvmsg2 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
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread 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:

 syscallcalls min  avg  max  stddev
(msec)   (msec)   (msec)(%)
 ---     --
 sendmsg20.0020.0050.008  55.00
 recvmsg20.0020.0030.005  44.00
 epoll_wait 10.0000.0000.000   0.00

or so?


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


Pekka
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread Ingo Molnar

* Pekka Enberg  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:

syscallcalls  min  avg  max stddev
---     --
sendmsg20.0020.0050.008 0.001
recvmsg20.0020.0030.005 0.0003
epoll_wait 10.0000.0000.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

  real0m0.002s
  user0m0.000s
  sys 0m0.000s

  # Mockup:

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

  real0m0.002s  [ +- 1.38% ]
  user0m0.000s  [ +- 0.53% ]
  sys 0m0.000s  [ +- 0.43% ]

?

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

Thanks,

Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread 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


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread Ingo Molnar

* 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
> >>>syscallcalls  min  avg  max stddev
> >>>---     --
> >>>sendmsg20.0020.0050.008  55.00
> >>>recvmsg20.0020.0030.005  44.00
> >>>epoll_wait 10.0000.0000.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:

syscallcalls min  avg  max  stddev
   (msec)   (msec)   (msec)(%)
---     --
sendmsg20.0020.0050.008  55.00
recvmsg20.0020.0030.005  44.00
epoll_wait 10.0000.0000.000   0.00

or so?

Thanks,

Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread 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
>syscallcalls  min  avg  max stddev
>---     --
>sendmsg20.0020.0050.008 55.00
>recvmsg20.0020.0030.005 44.00
>epoll_wait 10.0000.0000.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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread 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
>syscallcalls  min  avg  max stddev
>---     --
>sendmsg20.0020.0050.008  55.00
>recvmsg20.0020.0030.005  44.00
>epoll_wait 10.0000.0000.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
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread Ingo Molnar

* Pekka Enberg  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 1 --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 1'.

>  Summary of events:
> 
>  dbus-daemon (555), 10 events, 0.0%, 0.000 msec
> 
> msec/call
>syscallcalls  min  avg  max stddev
>---     --
>sendmsg20.0020.0050.008  55.00
>recvmsg20.0020.0030.005  44.00
>epoll_wait 10.0000.0000.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
>syscallcalls  min  avg  max stddev
>---     --
>poll   20.0000.0020.003 100.00
>sendmsg   100.0040.0070.016  15.41
>recvmsg   160.0020.0030.005   8.24
> 
>  zfs-fuse (669), 4 events, 0.0%, 0.000 msec
> 
> msec/call
>syscallcalls  min  avg  max stddev
>---     --
>futex  20.0000.0010.002 100.00

Nice looking output btw! :-)

Acked-by: Ingo Molnar 

Thanks,

Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread Ingo Molnar

* Pekka Enberg penb...@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 1 --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 1'.

  Summary of events:
 
  dbus-daemon (555), 10 events, 0.0%, 0.000 msec
 
 msec/call
syscallcalls  min  avg  max stddev
---     --
sendmsg20.0020.0050.008  55.00
recvmsg20.0020.0030.005  44.00
epoll_wait 10.0000.0000.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
syscallcalls  min  avg  max stddev
---     --
poll   20.0000.0020.003 100.00
sendmsg   100.0040.0070.016  15.41
recvmsg   160.0020.0030.005   8.24
 
  zfs-fuse (669), 4 events, 0.0%, 0.000 msec
 
 msec/call
syscallcalls  min  avg  max stddev
---     --
futex  20.0000.0010.002 100.00

Nice looking output btw! :-)

Acked-by: Ingo Molnar mi...@kernel.org

Thanks,

Ingo
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread 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
syscallcalls  min  avg  max stddev
---     --
sendmsg20.0020.0050.008  55.00
recvmsg20.0020.0030.005  44.00
epoll_wait 10.0000.0000.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
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread 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
syscallcalls  min  avg  max stddev
---     --
sendmsg20.0020.0050.008 55.00
recvmsg20.0020.0030.005 44.00
epoll_wait 10.0000.0000.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
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread Ingo Molnar

* David Ahern dsah...@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
 syscallcalls  min  avg  max stddev
 ---     --
 sendmsg20.0020.0050.008  55.00
 recvmsg20.0020.0030.005  44.00
 epoll_wait 10.0000.0000.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:

syscallcalls min  avg  max  stddev
   (msec)   (msec)   (msec)(%)
---     --
sendmsg20.0020.0050.008  55.00
recvmsg20.0020.0030.005  44.00
epoll_wait 10.0000.0000.000   0.00

or so?

Thanks,

Ingo
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread 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


--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread Ingo Molnar

* Pekka Enberg penb...@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:

syscallcalls  min  avg  max stddev
---     --
sendmsg20.0020.0050.008 0.001
recvmsg20.0020.0030.005 0.0003
epoll_wait 10.0000.0000.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

  real0m0.002s
  user0m0.000s
  sys 0m0.000s

  # Mockup:

  comet:~ perf time --repeat 10 usleep 1000

  real0m0.002s  [ +- 1.38% ]
  user0m0.000s  [ +- 0.53% ]
  sys 0m0.000s  [ +- 0.43% ]

?

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

Thanks,

Ingo
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/


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

2013-11-12 Thread 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:

 syscallcalls min  avg  max  stddev
(msec)   (msec)   (msec)(%)
 ---     --
 sendmsg20.0020.0050.008  55.00
 recvmsg20.0020.0030.005  44.00
 epoll_wait 10.0000.0000.000   0.00

or so?


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


Pekka
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/