[PATCH 0/2] perf stat: add -l <N> option to redirect stderr elsewhere

[PATCH 0/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Jim Cromie]

[PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere
[PATCH 2/2] dont commify big numbers by default, let -B do it

perl's make test.valgrind uses valgrinds --log-fd option to steer
valgrind output to a file for further processing.  Adding similar to
perf will allow easy adaptation of the test harness to use perf too.

[PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Jim Cromie]

This perf stat option emulates valgrind's --log-fd option, allowing the
user to send perf results elsewhere, and leaving stderr for use by the
program under test.

  3>results perf stat -l 3 -- <cmd>

The perl distro's make test.valgrind target uses valgrinds --log-fd
option, I've adapted it to invoke perf also, and tested this patch there.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |   85 +++++++++++++++++++++++++-------------------
 1 files changed, 48 insertions(+), 37 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index 03f0e45..3858573 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -92,6 +92,9 @@ static const char		*cpu_list;
 static const char		*csv_sep			= NULL;
 static bool			csv_output			= false;
 
+static int logfd = 2;	/* stderr by default, override with -l */
+static FILE *logfp;	/* = fdopen(logfd,"w") */
+
 static volatile int done = 0;
 
 struct stats
@@ -210,7 +213,7 @@ static int read_counter_aggr(struct perf_evsel *counter)
 		update_stats(&ps->res_stats[i], count[i]);
 
 	if (verbose) {
-		fprintf(stderr, "%s: %" PRIu64 " %" PRIu64 " %" PRIu64 "\n",
+		fprintf(logfp, "%s: %" PRIu64 " %" PRIu64 " %" PRIu64 "\n",
 			event_name(counter), count[0], count[1], count[2]);
 	}
 
@@ -380,7 +383,7 @@ static void print_noise(struct perf_evsel *evsel, double avg)
 		return;
 
 	ps = evsel->priv;
-	fprintf(stderr, "   ( +- %7.3f%% )",
+	fprintf(logfp, "   ( +- %7.3f%% )",
 			100 * stddev_stats(&ps->res_stats[0]) / avg);
 }
 
@@ -395,16 +398,16 @@ static void nsec_printout(int cpu, struct perf_evsel *evsel, double avg)
 			csv_output ? 0 : -4,
 			evsel_list->cpus->map[cpu], csv_sep);
 
-	fprintf(stderr, fmt, cpustr, msecs, csv_sep, event_name(evsel));
+	fprintf(logfp, fmt, cpustr, msecs, csv_sep, event_name(evsel));
 
 	if (evsel->cgrp)
-		fprintf(stderr, "%s%s", csv_sep, evsel->cgrp->name);
+		fprintf(logfp, "%s%s", csv_sep, evsel->cgrp->name);
 
 	if (csv_output)
 		return;
 
 	if (perf_evsel__match(evsel, SOFTWARE, SW_TASK_CLOCK))
-		fprintf(stderr, " # %10.3f CPUs ",
+		fprintf(logfp, " # %10.3f CPUs ",
 				avg / avg_stats(&walltime_nsecs_stats));
 }
 
@@ -428,10 +431,10 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 	else
 		cpu = 0;
 
-	fprintf(stderr, fmt, cpustr, avg, csv_sep, event_name(evsel));
+	fprintf(logfp, fmt, cpustr, avg, csv_sep, event_name(evsel));
 
 	if (evsel->cgrp)
-		fprintf(stderr, "%s%s", csv_sep, evsel->cgrp->name);
+		fprintf(logfp, "%s%s", csv_sep, evsel->cgrp->name);
 
 	if (csv_output)
 		return;
@@ -442,7 +445,7 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 		if (total)
 			ratio = avg / total;
 
-		fprintf(stderr, " # %10.3f IPC  ", ratio);
+		fprintf(logfp, " # %10.3f IPC  ", ratio);
 	} else if (perf_evsel__match(evsel, HARDWARE, HW_BRANCH_MISSES) &&
 			runtime_branches_stats[cpu].n != 0) {
 		total = avg_stats(&runtime_branches_stats[cpu]);
@@ -450,7 +453,7 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 		if (total)
 			ratio = avg * 100 / total;
 
-		fprintf(stderr, " # %10.3f %%    ", ratio);
+		fprintf(logfp, " # %10.3f %%    ", ratio);
 
 	} else if (runtime_nsecs_stats[cpu].n != 0) {
 		total = avg_stats(&runtime_nsecs_stats[cpu]);
@@ -458,7 +461,7 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 		if (total)
 			ratio = 1000.0 * avg / total;
 
-		fprintf(stderr, " # %10.3f M/sec", ratio);
+		fprintf(logfp, " # %10.3f M/sec", ratio);
 	}
 }
 
@@ -473,7 +476,7 @@ static void print_counter_aggr(struct perf_evsel *counter)
 	int scaled = counter->counts->scaled;
 
 	if (scaled == -1) {
-		fprintf(stderr, "%*s%s%*s",
+		fprintf(logfp, "%*s%s%*s",
 			csv_output ? 0 : 18,
 			"<not counted>",
 			csv_sep,
@@ -481,9 +484,9 @@ static void print_counter_aggr(struct perf_evsel *counter)
 			event_name(counter));
 
 		if (counter->cgrp)
-			fprintf(stderr, "%s%s", csv_sep, counter->cgrp->name);
+			fprintf(logfp, "%s%s", csv_sep, counter->cgrp->name);
 
-		fputc('\n', stderr);
+		fputc('\n', logfp);
 		return;
 	}
 
@@ -493,7 +496,7 @@ static void print_counter_aggr(struct perf_evsel *counter)
 		abs_printout(-1, counter, avg);
 
 	if (csv_output) {
-		fputc('\n', stderr);
+		fputc('\n', logfp);
 		return;
 	}
 
@@ -505,10 +508,10 @@ static void print_counter_aggr(struct perf_evsel *counter)
 		avg_enabled = avg_stats(&ps->res_stats[1]);
 		avg_running = avg_stats(&ps->res_stats[2]);
 
-		fprintf(stderr, "  (scaled from %.2f%%)",
+		fprintf(logfp, "  (scaled from %.2f%%)",
 				100 * avg_running / avg_enabled);
 	}
-	fprintf(stderr, "\n");
+	fprintf(logfp, "\n");
 }
 
 /*
@@ -525,7 +528,7 @@ static void print_counter(struct perf_evsel *counter)
 		ena = counter->counts->cpu[cpu].ena;
 		run = counter->counts->cpu[cpu].run;
 		if (run == 0 || ena == 0) {
-			fprintf(stderr, "CPU%*d%s%*s%s%*s",
+			fprintf(logfp, "CPU%*d%s%*s%s%*s",
 				csv_output ? 0 : -4,
 				evsel_list->cpus->map[cpu], csv_sep,
 				csv_output ? 0 : 18,
@@ -534,9 +537,9 @@ static void print_counter(struct perf_evsel *counter)
 				event_name(counter));
 
 			if (counter->cgrp)
-				fprintf(stderr, "%s%s", csv_sep, counter->cgrp->name);
+				fprintf(logfp, "%s%s", csv_sep, counter->cgrp->name);
 
-			fputc('\n', stderr);
+			fputc('\n', logfp);
 			continue;
 		}
 
@@ -549,11 +552,11 @@ static void print_counter(struct perf_evsel *counter)
 			print_noise(counter, 1.0);
 
 			if (run != ena) {
-				fprintf(stderr, "  (scaled from %.2f%%)",
+				fprintf(logfp, "  (scaled from %.2f%%)",
 					100.0 * run / ena);
 			}
 		}
-		fputc('\n', stderr);
+		fputc('\n', logfp);
 	}
 }
 
@@ -565,21 +568,21 @@ static void print_stat(int argc, const char **argv)
 	fflush(stdout);
 
 	if (!csv_output) {
-		fprintf(stderr, "\n");
-		fprintf(stderr, " Performance counter stats for ");
+		fprintf(logfp, "\n");
+		fprintf(logfp, " Performance counter stats for ");
 		if(target_pid == -1 && target_tid == -1) {
-			fprintf(stderr, "\'%s", argv[0]);
+			fprintf(logfp, "\'%s", argv[0]);
 			for (i = 1; i < argc; i++)
-				fprintf(stderr, " %s", argv[i]);
+				fprintf(logfp, " %s", argv[i]);
 		} else if (target_pid != -1)
-			fprintf(stderr, "process id \'%d", target_pid);
+			fprintf(logfp, "process id \'%d", target_pid);
 		else
-			fprintf(stderr, "thread id \'%d", target_tid);
+			fprintf(logfp, "thread id \'%d", target_tid);
 
-		fprintf(stderr, "\'");
+		fprintf(logfp, "\'");
 		if (run_count > 1)
-			fprintf(stderr, " (%d runs)", run_count);
-		fprintf(stderr, ":\n\n");
+			fprintf(logfp, " (%d runs)", run_count);
+		fprintf(logfp, ":\n\n");
 	}
 
 	if (no_aggr) {
@@ -591,15 +594,15 @@ static void print_stat(int argc, const char **argv)
 	}
 
 	if (!csv_output) {
-		fprintf(stderr, "\n");
-		fprintf(stderr, " %18.9f  seconds time elapsed",
+		fprintf(logfp, "\n");
+		fprintf(logfp, " %18.9f  seconds time elapsed",
 				avg_stats(&walltime_nsecs_stats)/1e9);
 		if (run_count > 1) {
-			fprintf(stderr, "   ( +- %7.3f%% )",
+			fprintf(logfp, "   ( +- %7.3f%% )",
 				100*stddev_stats(&walltime_nsecs_stats) /
 				avg_stats(&walltime_nsecs_stats));
 		}
-		fprintf(stderr, "\n\n");
+		fprintf(logfp, "\n\n");
 	}
 }
 
@@ -671,6 +674,8 @@ static const struct option options[] = {
 	OPT_CALLBACK('G', "cgroup", &evsel_list, "name",
 		     "monitor event in cgroup name only",
 		     parse_cgroups),
+	OPT_INTEGER('l', "logfd", &logfd,
+		    "log output to fd, instead of stderr"),
 	OPT_END()
 };
 
@@ -688,6 +693,12 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 	argc = parse_options(argc, argv, options, stat_usage,
 		PARSE_OPT_STOP_AT_NON_OPTION);
 
+	logfp = fdopen(logfd, "w");
+	if (!logfp) {
+		perror("failed opening logfd");
+		exit(1);
+	}
+
 	if (csv_sep)
 		csv_output = true;
 	else
@@ -699,7 +710,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 	if (csv_output) {
 		/* User explicitely passed -B? */
 		if (big_num_opt == 1) {
-			fprintf(stderr, "-B option not supported with -x\n");
+			fprintf(logfp, "-B option not supported with -x\n");
 			usage_with_options(stat_usage, options);
 		} else /* Nope, so disable big number formatting */
 			big_num = false;
@@ -713,7 +724,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 
 	/* no_aggr, cgroup are for system-wide only */
 	if ((no_aggr || nr_cgroups) && !system_wide) {
-		fprintf(stderr, "both cgroup and no-aggregation "
+		fprintf(logfp, "both cgroup and no-aggregation "
 			"modes only available in system-wide mode\n");
 
 		usage_with_options(stat_usage, options);
@@ -772,7 +783,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 	status = 0;
 	for (run_idx = 0; run_idx < run_count; run_idx++) {
 		if (run_count != 1 && verbose)
-			fprintf(stderr, "[ perf stat: executing run #%d ... ]\n", run_idx + 1);
+			fprintf(logfp, "[ perf stat: executing run #%d ... ]\n", run_idx + 1);
 		status = run_perf_stat(argc, argv);
 	}
 
-- 
1.7.4.1

[PATCH 2/2] dont commify big numbers by default, let -B do it

[Jim Cromie]

Currently, big numbers get commas by default, which complicates parsing
by automation.  Turn it off by default, users can add -B.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index 3858573..3a703e4 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -86,7 +86,7 @@ static pid_t			target_pid			= -1;
 static pid_t			target_tid			= -1;
 static pid_t			child_pid			= -1;
 static bool			null_run			=  false;
-static bool			big_num				=  true;
+static bool			big_num				=  false;
 static int			big_num_opt			=  -1;
 static const char		*cpu_list;
 static const char		*csv_sep			= NULL;
-- 
1.7.4.1

Re: [PATCH 2/2] dont commify big numbers by default, let -B do it

[Ingo Molnar]

* Jim Cromie <jim.cromie@gmail.com> wrote:

> Currently, big numbers get commas by default, which complicates parsing
> by automation. [...]

Well, automation can turn it off via --no-big-num, right?

Also, i think for automation we'd also like to have a 'simple output' mode, 
would you like to add that?

Something a bit like what you can see in 'perf stat -v true':

 $ perf stat -v --no-big-num true
 task-clock: 164545 164545 164545
 context-switches: 0 164545 164545
 CPU-migrations: 0 164545 164545
 page-faults: 83 164545 164545
 cycles: 518743 169550 169550
 stalled-cycles-frontend: 326178 169550 169550
 stalled-cycles-backend: 269753 169550 169550
 instructions: 326864 169550 169550
 branches: 67886 169550 169550
 branch-misses: 3874 169550 169550

Without the human output later on, and with elapsed time added as well.

Thanks,

	Ingo

Re: [PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Ingo Molnar]

* Jim Cromie <jim.cromie@gmail.com> wrote:

> This perf stat option emulates valgrind's --log-fd option, allowing the
> user to send perf results elsewhere, and leaving stderr for use by the
> program under test.
> 
>   3>results perf stat -l 3 -- <cmd>
> 
> The perl distro's make test.valgrind target uses valgrinds --log-fd
> option, I've adapted it to invoke perf also, and tested this patch there.
> 
> Signed-off-by: Jim Cromie <jim.cromie@gmail.com>

Makes sense!

Arnaldo, if you are fine with it, do you want to pick it up - or should i? If 
you pick it up:

Acked-by: Ingo Molnar <mingo@elte.hu>

Thanks,

	Ingo

Re: [PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Arnaldo Carvalho de Melo]

Em Sat, May 21, 2011 at 12:34:18PM +0200, Ingo Molnar escreveu:
> 
> * Jim Cromie <jim.cromie@gmail.com> wrote:
> 
> > This perf stat option emulates valgrind's --log-fd option, allowing the
> > user to send perf results elsewhere, and leaving stderr for use by the
> > program under test.
> > 
> >   3>results perf stat -l 3 -- <cmd>
> > 
> > The perl distro's make test.valgrind target uses valgrinds --log-fd
> > option, I've adapted it to invoke perf also, and tested this patch there.
> > 
> > Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> 
> Makes sense!
> 
> Arnaldo, if you are fine with it, do you want to pick it up - or should i? If 
> you pick it up:
> 
> Acked-by: Ingo Molnar <mingo@elte.hu>

Its ok with me:

Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>

I will pick it this weekend, if you don't merge it till then.

- Arnaldo

Re: [PATCH 2/2] dont commify big numbers by default, let -B do it

[Jim Cromie]

[-- Attachment #1: Type: text/plain, Size: 3334 bytes --]

On Sat, May 21, 2011 at 4:33 AM, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Jim Cromie <jim.cromie@gmail.com> wrote:
>
>> Currently, big numbers get commas by default, which complicates parsing
>> by automation. [...]
>
> Well, automation can turn it off via --no-big-num, right?

ah.  my man-page is a bit behind
(but is in usage, and in Doc/perf-stat.txt)

> Also, i think for automation we'd also like to have a 'simple output' mode,
> would you like to add that?

OK, heres 1st cut at it, adding option --simple, for review / feedback

Its based upon the csv-output code mostly, with some vestiges of verbose..

I altered csv-output to have event-name 1st
this seems what folks would expect normally,
I surmised that existing was a short-cut..
Then added "noise"

part of reason for sending early is this column swap,
it might annoy existing users.

[jimc@groucho perf]$ ./perf stat -r3 -x' ' true
task-clock-msecs1.009533  0.142%
context-switches 0 -nan%
CPU-migrations 0 100.000%
page-faults 85 0.000%
cycles 789434 0.107%
instructions 488768 0.546%
branches 102796 0.505%
branch-misses 8472 1.688%
cache-references 0 -nan%  (scaled from 0.00%)
cache-misses 0 -nan%  (scaled from 0.00%)

[jimc@groucho perf]$ ./perf stat -r3 -x' ------- ' true
task-clock-msecs1.036450 -------  ------- 3.519%
context-switches ------- 0 ------- -nan%
CPU-migrations ------- 0 ------- -nan%
page-faults ------- 85 ------- 0.000%
cycles ------- 812151 ------- 3.463%
instructions ------- 499263 ------- 0.368%
branches ------- 104240 ------- 0.224%
branch-misses ------- 8125 ------- 4.627%
cache-references ------- 0 ------- -nan%  (scaled from 0.00%)
cache-misses ------- 0 ------- -nan%  (scaled from 0.00%)

I also need to do something better with -no-aggr format,
doesnt do right with extra column

[jimc@groucho perf]$ sudo ./perf stat -r3 -x' ------- ' -A -a true
CPU0 ------- task-clock-msecs2.099862 -------
CPU1 ------- task-clock-msecs2.084522 -------
CPU2 ------- task-clock-msecs2.072948 -------
CPU3 ------- task-clock-msecs2.071611 -------
CPU0 ------- context-switches ------- 2
CPU1 ------- context-switches ------- 0
CPU2 ------- context-switches ------- 3
CPU3 ------- context-switches ------- 6
CPU0 ------- CPU-migrations ------- 2
...




> Something a bit like what you can see in 'perf stat -v true':
> Without the human output later on, and with elapsed time added as well.

for my part, Id like the moral equivalent of time(s)? output too,
though I suspect thats a separate patch..

[jimc@groucho perf]$ time ./perf stat -x'  ' -- sh -c 'sleep 3'
task-clock-msecs6.830999
context-switches  2
CPU-migrations  1
page-faults  477
cycles  5404163  (scaled from 72.07%)
instructions  3302699
branches  804750
branch-misses  51870
cache-references  1584532  (scaled from 45.93%)
cache-misses  36616  (scaled from 31.36%)

real	0m3.019s
user	0m0.005s
sys	0m0.012s

are these timings already taken by perf-stat ?
is it a simple matter of addition and printing ?
If not, whats involved ?

Also, task-clock-msec doesnt quite match up with times' user number
Whats going on here ?


> Thanks,
>
>        Ingo
>

thank you
~jimc

PS: attaching now (in gmail web iface),
will try to thread up to this, RSN, with git send-email

[-- Attachment #2: 0001-add-simple-output-mode-to-perf-stat-based-upon-csv-o.patch --]
[-- Type: text/x-patch, Size: 5447 bytes --]

From 6cd1667ae522737d577d3f67314c6952bc3a5e4f Mon Sep 17 00:00:00 2001
From: Jim Cromie <jim.cromie@gmail.com>
Date: Tue, 24 May 2011 15:56:39 -0600
Subject: [PATCH] add --simple output mode to perf-stat, based upon csv-output

produces output like this (WIP):

perf]$ ./perf stat -x'  ' -r3 -- sh -c 'sleep 3'
task-clock-msecs6.896594    1.105%
context-switches  3  0.000%
CPU-migrations  0  -nan%
page-faults  477  0.000%
cycles  5540483  1.002%  (scaled from 69.92%)
instructions  3881794  7.779%  (scaled from 83.70%)
branches  932435  3.343%  (scaled from 82.21%)
branch-misses  43830  11.999%
cache-references  1582931  3.718%  (scaled from 52.72%)
cache-misses  37199  10.154%  (scaled from 37.65%)

Its based upon csv-output, and prints event-name in 1st column, in
contrast to previous format.  This may be problematic for some
existing users, but is more "normal" and therefore better.

Whether '%' symbols or scalings should be printed is TBD.
Also, -A -a output needs work.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |   44 ++++++++++++++++++++++++++++++++------------
 1 files changed, 32 insertions(+), 12 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index 3a703e4..1711535 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -91,6 +91,7 @@ static int			big_num_opt			=  -1;
 static const char		*cpu_list;
 static const char		*csv_sep			= NULL;
 static bool			csv_output			= false;
+static bool			simple				= false;
 
 static int logfd = 2;	/* stderr by default, override with -l */
 static FILE *logfp;	/* = fdopen(logfd,"w") */
@@ -212,7 +213,7 @@ static int read_counter_aggr(struct perf_evsel *counter)
 	for (i = 0; i < 3; i++)
 		update_stats(&ps->res_stats[i], count[i]);
 
-	if (verbose) {
+	if (verbose || simple) {
 		fprintf(logfp, "%s: %" PRIu64 " %" PRIu64 " %" PRIu64 "\n",
 			event_name(counter), count[0], count[1], count[2]);
 	}
@@ -383,22 +384,31 @@ static void print_noise(struct perf_evsel *evsel, double avg)
 		return;
 
 	ps = evsel->priv;
-	fprintf(logfp, "   ( +- %7.3f%% )",
-			100 * stddev_stats(&ps->res_stats[0]) / avg);
+	if (!csv_output)
+		fprintf(logfp, "   ( +- %7.3f%% )",
+				100 * stddev_stats(&ps->res_stats[0]) / avg);
+	else
+	  fprintf(logfp, "%s%.3f%%",
+		  csv_sep, 100 * stddev_stats(&ps->res_stats[0]) / avg);
+
+
 }
 
 static void nsec_printout(int cpu, struct perf_evsel *evsel, double avg)
 {
 	double msecs = avg / 1e6;
 	char cpustr[16] = { '\0', };
-	const char *fmt = csv_output ? "%s%.6f%s%s" : "%s%18.6f%s%-24s";
+	const char *fmt = csv_output ? "%s%s%.6f%s" : "%s%18.6f%s%-24s";
 
 	if (no_aggr)
 		sprintf(cpustr, "CPU%*d%s",
 			csv_output ? 0 : -4,
 			evsel_list->cpus->map[cpu], csv_sep);
 
-	fprintf(logfp, fmt, cpustr, msecs, csv_sep, event_name(evsel));
+	if (!csv_output)
+	  fprintf(logfp, fmt, cpustr, msecs, csv_sep, event_name(evsel));
+	else
+	  fprintf(logfp, fmt, cpustr, event_name(evsel), csv_sep, msecs);
 
 	if (evsel->cgrp)
 		fprintf(logfp, "%s%s", csv_sep, evsel->cgrp->name);
@@ -418,7 +428,7 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 	const char *fmt;
 
 	if (csv_output)
-		fmt = "%s%.0f%s%s";
+		fmt = "%s%s%s%.0f";
 	else if (big_num)
 		fmt = "%s%'18.0f%s%-24s";
 	else
@@ -431,7 +441,10 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 	else
 		cpu = 0;
 
-	fprintf(logfp, fmt, cpustr, avg, csv_sep, event_name(evsel));
+	if (csv_output)
+	  fprintf(logfp, fmt, cpustr, event_name(evsel), csv_sep, avg);
+	else
+	  fprintf(logfp, fmt, cpustr, avg, csv_sep, event_name(evsel));
 
 	if (evsel->cgrp)
 		fprintf(logfp, "%s%s", csv_sep, evsel->cgrp->name);
@@ -475,7 +488,7 @@ static void print_counter_aggr(struct perf_evsel *counter)
 	double avg = avg_stats(&ps->res_stats[0]);
 	int scaled = counter->counts->scaled;
 
-	if (scaled == -1) {
+	if (scaled == -1 && !csv_output) {
 		fprintf(logfp, "%*s%s%*s",
 			csv_output ? 0 : 18,
 			"<not counted>",
@@ -495,7 +508,7 @@ static void print_counter_aggr(struct perf_evsel *counter)
 	else
 		abs_printout(-1, counter, avg);
 
-	if (csv_output) {
+	if (0 && csv_output) {
 		fputc('\n', logfp);
 		return;
 	}
@@ -536,9 +549,12 @@ static void print_counter(struct perf_evsel *counter)
 				csv_output ? 0 : -24,
 				event_name(counter));
 
-			if (counter->cgrp)
+			if (counter->cgrp) {
+			  if (csv_output)
+				fprintf(logfp, "%s%s", counter->cgrp->name, csv_sep);
+			  else
 				fprintf(logfp, "%s%s", csv_sep, counter->cgrp->name);
-
+			}
 			fputc('\n', logfp);
 			continue;
 		}
@@ -567,6 +583,8 @@ static void print_stat(int argc, const char **argv)
 
 	fflush(stdout);
 
+	if (simple) return;
+
 	if (!csv_output) {
 		fprintf(logfp, "\n");
 		fprintf(logfp, " Performance counter stats for ");
@@ -670,12 +688,14 @@ static const struct option options[] = {
 	OPT_BOOLEAN('A', "no-aggr", &no_aggr,
 		    "disable CPU count aggregation"),
 	OPT_STRING('x', "field-separator", &csv_sep, "separator",
-		   "print counts with custom separator"),
+		   "print counts with custom separator (csv-output)"),
 	OPT_CALLBACK('G', "cgroup", &evsel_list, "name",
 		     "monitor event in cgroup name only",
 		     parse_cgroups),
 	OPT_INTEGER('l', "logfd", &logfd,
 		    "log output to fd, instead of stderr"),
+	OPT_BOOLEAN('s', "simple", &simple,
+		    "simple output for scripts/automation"),
 	OPT_END()
 };
 
-- 
1.7.4.4

[PATCH] add --simple output mode to perf-stat, based upon csv-output

[Jim Cromie]

produces output like this (WIP):

perf]$ ./perf stat -x'  ' -r3 -- sh -c 'sleep 3'
task-clock-msecs6.896594    1.105%
context-switches  3  0.000%
CPU-migrations  0  -nan%
page-faults  477  0.000%
cycles  5540483  1.002%  (scaled from 69.92%)
instructions  3881794  7.779%  (scaled from 83.70%)
branches  932435  3.343%  (scaled from 82.21%)
branch-misses  43830  11.999%
cache-references  1582931  3.718%  (scaled from 52.72%)
cache-misses  37199  10.154%  (scaled from 37.65%)

Its based upon csv-output, and prints event-name in 1st column, in
contrast to previous format.  This may be problematic for some
existing users, but is more "normal" and therefore better.

Whether '%' symbols or scalings should be printed is TBD.
Also, -A -a output needs work.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |   44 ++++++++++++++++++++++++++++++++------------
 1 files changed, 32 insertions(+), 12 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index 3a703e4..1711535 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -91,6 +91,7 @@ static int			big_num_opt			=  -1;
 static const char		*cpu_list;
 static const char		*csv_sep			= NULL;
 static bool			csv_output			= false;
+static bool			simple				= false;
 
 static int logfd = 2;	/* stderr by default, override with -l */
 static FILE *logfp;	/* = fdopen(logfd,"w") */
@@ -212,7 +213,7 @@ static int read_counter_aggr(struct perf_evsel *counter)
 	for (i = 0; i < 3; i++)
 		update_stats(&ps->res_stats[i], count[i]);
 
-	if (verbose) {
+	if (verbose || simple) {
 		fprintf(logfp, "%s: %" PRIu64 " %" PRIu64 " %" PRIu64 "\n",
 			event_name(counter), count[0], count[1], count[2]);
 	}
@@ -383,22 +384,31 @@ static void print_noise(struct perf_evsel *evsel, double avg)
 		return;
 
 	ps = evsel->priv;
-	fprintf(logfp, "   ( +- %7.3f%% )",
-			100 * stddev_stats(&ps->res_stats[0]) / avg);
+	if (!csv_output)
+		fprintf(logfp, "   ( +- %7.3f%% )",
+				100 * stddev_stats(&ps->res_stats[0]) / avg);
+	else
+	  fprintf(logfp, "%s%.3f%%",
+		  csv_sep, 100 * stddev_stats(&ps->res_stats[0]) / avg);
+
+
 }
 
 static void nsec_printout(int cpu, struct perf_evsel *evsel, double avg)
 {
 	double msecs = avg / 1e6;
 	char cpustr[16] = { '\0', };
-	const char *fmt = csv_output ? "%s%.6f%s%s" : "%s%18.6f%s%-24s";
+	const char *fmt = csv_output ? "%s%s%.6f%s" : "%s%18.6f%s%-24s";
 
 	if (no_aggr)
 		sprintf(cpustr, "CPU%*d%s",
 			csv_output ? 0 : -4,
 			evsel_list->cpus->map[cpu], csv_sep);
 
-	fprintf(logfp, fmt, cpustr, msecs, csv_sep, event_name(evsel));
+	if (!csv_output)
+	  fprintf(logfp, fmt, cpustr, msecs, csv_sep, event_name(evsel));
+	else
+	  fprintf(logfp, fmt, cpustr, event_name(evsel), csv_sep, msecs);
 
 	if (evsel->cgrp)
 		fprintf(logfp, "%s%s", csv_sep, evsel->cgrp->name);
@@ -418,7 +428,7 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 	const char *fmt;
 
 	if (csv_output)
-		fmt = "%s%.0f%s%s";
+		fmt = "%s%s%s%.0f";
 	else if (big_num)
 		fmt = "%s%'18.0f%s%-24s";
 	else
@@ -431,7 +441,10 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 	else
 		cpu = 0;
 
-	fprintf(logfp, fmt, cpustr, avg, csv_sep, event_name(evsel));
+	if (csv_output)
+	  fprintf(logfp, fmt, cpustr, event_name(evsel), csv_sep, avg);
+	else
+	  fprintf(logfp, fmt, cpustr, avg, csv_sep, event_name(evsel));
 
 	if (evsel->cgrp)
 		fprintf(logfp, "%s%s", csv_sep, evsel->cgrp->name);
@@ -475,7 +488,7 @@ static void print_counter_aggr(struct perf_evsel *counter)
 	double avg = avg_stats(&ps->res_stats[0]);
 	int scaled = counter->counts->scaled;
 
-	if (scaled == -1) {
+	if (scaled == -1 && !csv_output) {
 		fprintf(logfp, "%*s%s%*s",
 			csv_output ? 0 : 18,
 			"<not counted>",
@@ -495,7 +508,7 @@ static void print_counter_aggr(struct perf_evsel *counter)
 	else
 		abs_printout(-1, counter, avg);
 
-	if (csv_output) {
+	if (0 && csv_output) {
 		fputc('\n', logfp);
 		return;
 	}
@@ -536,9 +549,12 @@ static void print_counter(struct perf_evsel *counter)
 				csv_output ? 0 : -24,
 				event_name(counter));
 
-			if (counter->cgrp)
+			if (counter->cgrp) {
+			  if (csv_output)
+				fprintf(logfp, "%s%s", counter->cgrp->name, csv_sep);
+			  else
 				fprintf(logfp, "%s%s", csv_sep, counter->cgrp->name);
-
+			}
 			fputc('\n', logfp);
 			continue;
 		}
@@ -567,6 +583,8 @@ static void print_stat(int argc, const char **argv)
 
 	fflush(stdout);
 
+	if (simple) return;
+
 	if (!csv_output) {
 		fprintf(logfp, "\n");
 		fprintf(logfp, " Performance counter stats for ");
@@ -670,12 +688,14 @@ static const struct option options[] = {
 	OPT_BOOLEAN('A', "no-aggr", &no_aggr,
 		    "disable CPU count aggregation"),
 	OPT_STRING('x', "field-separator", &csv_sep, "separator",
-		   "print counts with custom separator"),
+		   "print counts with custom separator (csv-output)"),
 	OPT_CALLBACK('G', "cgroup", &evsel_list, "name",
 		     "monitor event in cgroup name only",
 		     parse_cgroups),
 	OPT_INTEGER('l', "logfd", &logfd,
 		    "log output to fd, instead of stderr"),
+	OPT_BOOLEAN('s', "simple", &simple,
+		    "simple output for scripts/automation"),
 	OPT_END()
 };
 
-- 
1.7.4.4

Re: [PATCH 2/2] dont commify big numbers by default, let -B do it

[Ingo Molnar]

* Jim Cromie <jim.cromie@gmail.com> wrote:

> > Also, i think for automation we'd also like to have a 'simple 
> > output' mode, would you like to add that?
> 
> OK, heres 1st cut at it, adding option --simple, for review / 
> feedback
> 
> Its based upon the csv-output code mostly, with some vestiges of 
> verbose..

Ok, we can do something like this - but please see the comments on 
the patch further below:

> > Something a bit like what you can see in 'perf stat -v true': 
> > Without the human output later on, and with elapsed time added as 
> > well.
> 
> for my part, Id like the moral equivalent of time(s)? output too, 
> though I suspect thats a separate patch..

yeah. No objection to that either: time is well known and the stddev 
output by perf stat --repeat is well liked. Wanna combine the two?

> [jimc@groucho perf]$ time ./perf stat -x'  ' -- sh -c 'sleep 3'
> task-clock-msecs6.830999
> context-switches  2
> CPU-migrations  1
> page-faults  477
> cycles  5404163  (scaled from 72.07%)
> instructions  3302699
> branches  804750
> branch-misses  51870
> cache-references  1584532  (scaled from 45.93%)
> cache-misses  36616  (scaled from 31.36%)
> 
> real	0m3.019s
> user	0m0.005s
> sys	0m0.012s
> 
> are these timings already taken by perf-stat ?
> is it a simple matter of addition and printing ?
> If not, whats involved ?

Do you mean the real/user/sys bits? Elapsed time is already measured, 
but you'd have to extract the rusage bits to get to the stime/utime 
values.

We could also add those as explicit events.

> Also, task-clock-msec doesnt quite match up with times' user number 
> Whats going on here ?

task-clock-msec is generally much more accurate than the 0.005 
printed by 'time'.

About the patch:

> -	fprintf(logfp, "   ( +- %7.3f%% )",
> -			100 * stddev_stats(&ps->res_stats[0]) / avg);
> +	if (!csv_output)
> +		fprintf(logfp, "   ( +- %7.3f%% )",
> +				100 * stddev_stats(&ps->res_stats[0]) / avg);
> +	else
> +	  fprintf(logfp, "%s%.3f%%",
> +		  csv_sep, 100 * stddev_stats(&ps->res_stats[0]) / avg);

We *really* want something cleaner here: a print_ops vector of 
function pointers which would contain a handful of helper functions 
called by the higher level code?

That way adding a new format method would not uglify the highlevel 
code but could be done by adding a new print_ops 'driver' which would 
be selected if the right option is provided.

Also, instead of adding -s/--simple we really want a single 
print-format option that knows about all the format 'drivers':

  --print simple
  --print csv
  --print default
  --print verbose

or so.

Also, please run scripts/checkpatch.pl over your patches, the above 
is i think not matching the coding style we use in the kernel (unless 
webmail mangled your patch).

Thanks,

	Ingo

Re: [PATCH 2/2] dont commify big numbers by default, let -B do it

[Jim Cromie]

On Wed, May 25, 2011 at 6:44 AM, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Jim Cromie <jim.cromie@gmail.com> wrote:
>
>> > Also, i think for automation we'd also like to have a 'simple
>> > output' mode, would you like to add that?
>>
>> OK, heres 1st cut at it, adding option --simple, for review /
>> feedback
>>
>> Its based upon the csv-output code mostly, with some vestiges of
>> verbose..
>
> Ok, we can do something like this - but please see the comments on
> the patch further below:
>
>> > Something a bit like what you can see in 'perf stat -v true':
>> > Without the human output later on, and with elapsed time added as
>> > well.
>>
>> for my part, Id like the moral equivalent of time(s)? output too,
>> though I suspect thats a separate patch..
>
> yeah. No objection to that either: time is well known and the stddev
> output by perf stat --repeat is well liked. Wanna combine the two?

I think so, depending upon what exactly 'combining' means.

>>
>> real  0m3.019s
>> user  0m0.005s
>> sys   0m0.012s
>>
>> are these timings already taken by perf-stat ?
>> is it a simple matter of addition and printing ?
>> If not, whats involved ?
>
> Do you mean the real/user/sys bits? Elapsed time is already measured,
> but you'd have to extract the rusage bits to get to the stime/utime
> values.
>

> We could also add those as explicit events.

ISTM this makes sense - make them 1st class objects,
rather than some crufty fiddling in builtin-stats.
Can you give me a few hints re what/where to add ?

Also, is it sensible/practical to add self / +children flavors

>
>> Also, task-clock-msec doesnt quite match up with times' user number
>> Whats going on here ?
>
> task-clock-msec is generally much more accurate than the 0.005
> printed by 'time'.
>
> About the patch:
> We *really* want something cleaner here: a print_ops vector of
> function pointers which would contain a handful of helper functions
> called by the higher level code?

added struct print_ops:
0001-perf-stat-refactor-print-formatting-into-print-ops-f.patch
0002-perf-stat-fix-nan-in-Aa-runs.patch
0003-perf-stat-clean-up-no-count-handling-CPUx-prefixing.patch

sending separately, will attempt to in-reply-to them here.

> Also, instead of adding -s/--simple we really want a single
> print-format option that knows about all the format 'drivers':
>
>  --print simple
>  --print csv
>  --print default
>  --print verbose
>
> or so.

I left it as -x <delim> , since simple is basically csv.
in csv, "<not counted>" becomes "<not-counted>"
since latter makes -x ' ' useful.
also added -x '\t'  --> tab


> Also, please run scripts/checkpatch.pl over your patches, the above
> is i think not matching the coding style we use in the kernel (unless
> webmail mangled your patch).

emacs did it.  I didnt fuss to correct cuz patch wasnt for prime-time.
Now corrected with .emacs additions from CodingStyle.
and checkpatched.

thanks

>
> Thanks,
>
>        Ingo
>

[PATCH 0/3] perf-stat: refactor print/formatting into print-ops

[Jim Cromie]

 [PATCH 1/3] perf-stat: refactor print/formatting into print-ops for
 [PATCH 2/3] perf-stat: fix +- nan% in -Aa runs
 [PATCH 3/3] perf-stat: clean up <no count> handling, CPUx prefixing



[PATCH 1/3] perf-stat: refactor print/formatting into print-ops for

produces output like this for csv-output:

[jimc@harpo perf]$  sudo ./perf stat -Aa -x'\t' perl -e '$i++ for 1..100000'
CPU0	task-clock-msecs	16.255272
CPU0	context-switches	12
CPU0	CPU-migrations	0
CPU0	page-faults	445
CPU0	cycles	27441481	67.07%
CPU0	instructions	36775396	73.16%
CPU0	branches	8836245	20.72%
CPU0	branch-misses	21646	14.62%
CPU0	cache-references	58221	12.31%
CPU0	cache-misses	6815	12.28%
seconds-time-elapsed	0.016211262

This alters csv-output form by printing event-name in 1st column,
swapping cols 1, 2 from previous table.  This may be problematic for
some existing users, but is more "normal" and therefore better
long-term.  The 3rd - 5th colums match those in pretty

As before, csv-output is triggered by use of -x "sep", where sep can
be any string, not just a char.  This patch adds special case for
"\t", which is converted to a tab.

[PATCH 2/3] perf-stat: fix +- nan% in -Aa runs

without this patch, I get computations like this:

[jimc@groucho perf]$ sudo ./perf stat -r3 -Aa  perl -e '$i++ for 1..100000'

 Performance counter stats for 'perl -e $i++ for 1..100000' (3 runs):

CPU0             12.391883 task-clock-msecs         #      0.966 CPUs    ( +-    -nan% )
CPU1             12.446571 task-clock-msecs         #      0.970 CPUs    ( +-    -nan% )
CPU2             12.408014 task-clock-msecs         #      0.967 CPUs    ( +-    -nan% )
CPU3             12.422264 task-clock-msecs         #      0.968 CPUs    ( +-    -nan% )

I couldnt see anything wrong in the caller, so fixed it in stddev_stats()

[PATCH 3/3] perf-stat: clean up <no count> handling, CPUx prefixing

push <no-count> printing into print-ops to hide some cruft, and fold
away dynamic formats.  Refactor cpustr string prep into cpustr(int
cpu), use it everywhere, and change fn-sigs accordingly.

Also includes 1-line fixup for overlooked hack in earlier patch:
  -       if (scaled == -1 && !csv_output) {
  +       if (scaled == -1) {

[PATCH 1/3] perf-stat: refactor print/formatting into print-ops for pretty, csv

[Jim Cromie]

produces output like this for csv-output:

[jimc@harpo perf]$  sudo ./perf stat -Aa -x'\t' perl -e '$i++ for 1..100000'
CPU0	task-clock-msecs	16.255272
CPU0	context-switches	12
CPU0	CPU-migrations	0
CPU0	page-faults	445
CPU0	cycles	27441481	67.07%
CPU0	instructions	36775396	73.16%
CPU0	branches	8836245	20.72%
CPU0	branch-misses	21646	14.62%
CPU0	cache-references	58221	12.31%
CPU0	cache-misses	6815	12.28%
seconds-time-elapsed	0.016211262

This alters csv-output form by printing event-name in 1st column,
swapping cols 1, 2 from previous table.  This may be problematic for
some existing users, but is more "normal" and therefore better
long-term.  The 3rd - 5th colums match those in pretty

As before, csv-output is triggered by use of -x "sep", where sep can
be any string, not just a char.  This patch adds special case for
"\t", which is converted to a tab.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |  213 +++++++++++++++++++++++++++++++--------------
 1 files changed, 149 insertions(+), 64 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index 3858573..71bbf72 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -195,6 +195,7 @@ static inline int nsec_counter(struct perf_evsel *evsel)
 	return 0;
 }
 
+
 /*
  * Read out the results of a single counter:
  * aggregate counts across CPUs in system-wide mode
@@ -375,6 +376,113 @@ static int run_perf_stat(int argc __used, const char **argv)
 	return WEXITSTATUS(status);
 }
 
+struct print_ops {
+	int (*noise)  (double numer, double denom);
+	int (*nsec)   (const char *evt_name, double msecs, char *cpustr);
+	int (*abs)    (const char*, double avg, char *cpustr);
+	int (*unit)   (const char*, double, double);
+	int (*scaled) (double);
+	int (*cgrp)   (const char *name);
+	int (*time)   (const char *label, double mtime);
+};
+static struct print_ops *prt;
+
+static int user_pr_noise(double numer, double denom)
+{
+	double ratio = 0.0;
+	if (denom)
+		ratio = numer / denom;
+	return fprintf(logfp, "   ( +- %7.3f%% )", ratio);
+}
+static int csv_pr_noise(double numer, double denom)
+{
+	double ratio = 0.0;
+	if (denom)
+		ratio = numer / denom;
+	return fprintf(logfp, "%s%.3f%%", csv_sep, ratio);
+}
+static int user_pr_nsec(const char *evt_name, double msecs, char *cpustr)
+{
+	return fprintf(logfp, "%s%18.6f%s%-24s",
+			cpustr, msecs, csv_sep, evt_name);
+}
+static int csv_pr_nsec(const char *evt_name, double msecs, char *cpustr)
+{
+	return fprintf(logfp, "%s%s%s%.6f", cpustr, evt_name, csv_sep, msecs);
+}
+
+static int user_pr_abs(const char *evt_name, double avg, char *cpustr)
+{
+	const char *fmt = (big_num) ? "%s%'18.0f%s%-24s" : "%s%18.0f%s%-24s";
+	return fprintf(logfp, fmt, cpustr, avg, csv_sep, evt_name);
+}
+static int csv_pr_abs(const char *evt_name, double avg, char *cpustr)
+{
+	return fprintf(logfp, "%s%s%s%.0f", cpustr, evt_name, csv_sep, avg);
+}
+
+static int user_pr_unit(const char *unit, double numer, double denom)
+{
+	double ratio = 0.0;
+	if (denom)
+		ratio = numer / denom;
+	return fprintf(logfp, " # %10.3f %-5s", ratio, unit);
+}
+static int csv_pr_unit(const char *unit, double numer, double denom)
+{
+	double ratio = 0.0;
+	if (denom)
+		ratio = numer / denom;
+	return fprintf(logfp, "%s%.3f%s", csv_sep, ratio, unit);
+}
+
+static int user_pr_scaled(double val)
+{
+	return fprintf(logfp, "  (scaled from %.2f%%)", val);
+}
+static int csv_pr_scaled(double val)
+{
+	return fprintf(logfp, "%s%.2f%%", csv_sep, val);
+}
+
+static int user_pr_cgrp(const char *name)
+{
+	return fprintf(logfp, "%s%s", name, csv_sep);
+}
+static int csv_pr_cgrp(const char *name)
+{
+	return fprintf(logfp, "%s%s", csv_sep, name);
+}
+
+static int user_pr_time(const char *label, double mtime)
+{
+	return fprintf(logfp, " %18.9f  %s", mtime, label);
+}
+static int csv_pr_time(const char *label, double mtime)
+{
+	return fprintf(logfp, "%s%s%.9f", label, csv_sep, mtime);
+}
+
+struct print_ops user_print_ops = {
+	.noise	= user_pr_noise,
+	.nsec	= user_pr_nsec,
+	.abs	= user_pr_abs,
+	.scaled	= user_pr_scaled,
+	.cgrp	= user_pr_cgrp,
+	.unit	= user_pr_unit,
+	.time	= user_pr_time,
+};
+
+struct print_ops csv_print_ops = {
+	.noise	= csv_pr_noise,
+	.nsec	= csv_pr_nsec,
+	.abs	= csv_pr_abs,
+	.scaled	= csv_pr_scaled,
+	.cgrp	= csv_pr_cgrp,
+	.unit	= csv_pr_unit,
+	.time	= csv_pr_time,
+};
+
 static void print_noise(struct perf_evsel *evsel, double avg)
 {
 	struct perf_stat *ps;
@@ -383,46 +491,35 @@ static void print_noise(struct perf_evsel *evsel, double avg)
 		return;
 
 	ps = evsel->priv;
-	fprintf(logfp, "   ( +- %7.3f%% )",
-			100 * stddev_stats(&ps->res_stats[0]) / avg);
+	prt->noise(100 * stddev_stats(&ps->res_stats[0]), avg);
 }
 
 static void nsec_printout(int cpu, struct perf_evsel *evsel, double avg)
 {
 	double msecs = avg / 1e6;
 	char cpustr[16] = { '\0', };
-	const char *fmt = csv_output ? "%s%.6f%s%s" : "%s%18.6f%s%-24s";
 
 	if (no_aggr)
 		sprintf(cpustr, "CPU%*d%s",
 			csv_output ? 0 : -4,
 			evsel_list->cpus->map[cpu], csv_sep);
 
-	fprintf(logfp, fmt, cpustr, msecs, csv_sep, event_name(evsel));
+	prt->nsec(event_name(evsel), msecs, cpustr);
 
 	if (evsel->cgrp)
-		fprintf(logfp, "%s%s", csv_sep, evsel->cgrp->name);
+		prt->cgrp(evsel->cgrp->name);
 
 	if (csv_output)
 		return;
 
 	if (perf_evsel__match(evsel, SOFTWARE, SW_TASK_CLOCK))
-		fprintf(logfp, " # %10.3f CPUs ",
-				avg / avg_stats(&walltime_nsecs_stats));
+		prt->unit("CPUs", avg,
+			avg_stats(&walltime_nsecs_stats));
 }
 
 static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 {
-	double total, ratio = 0.0;
 	char cpustr[16] = { '\0', };
-	const char *fmt;
-
-	if (csv_output)
-		fmt = "%s%.0f%s%s";
-	else if (big_num)
-		fmt = "%s%'18.0f%s%-24s";
-	else
-		fmt = "%s%18.0f%s%-24s";
 
 	if (no_aggr)
 		sprintf(cpustr, "CPU%*d%s",
@@ -431,37 +528,29 @@ static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 	else
 		cpu = 0;
 
-	fprintf(logfp, fmt, cpustr, avg, csv_sep, event_name(evsel));
+	prt->abs(event_name(evsel), avg, cpustr);
 
 	if (evsel->cgrp)
-		fprintf(logfp, "%s%s", csv_sep, evsel->cgrp->name);
+		prt->cgrp(evsel->cgrp->name);
 
 	if (csv_output)
 		return;
 
 	if (perf_evsel__match(evsel, HARDWARE, HW_INSTRUCTIONS)) {
-		total = avg_stats(&runtime_cycles_stats[cpu]);
 
-		if (total)
-			ratio = avg / total;
+		prt->unit("IPC", avg,
+			avg_stats(&runtime_cycles_stats[cpu]));
 
-		fprintf(logfp, " # %10.3f IPC  ", ratio);
 	} else if (perf_evsel__match(evsel, HARDWARE, HW_BRANCH_MISSES) &&
 			runtime_branches_stats[cpu].n != 0) {
-		total = avg_stats(&runtime_branches_stats[cpu]);
-
-		if (total)
-			ratio = avg * 100 / total;
 
-		fprintf(logfp, " # %10.3f %%    ", ratio);
+		prt->unit("%", avg * 100,
+			avg_stats(&runtime_branches_stats[cpu]));
 
 	} else if (runtime_nsecs_stats[cpu].n != 0) {
-		total = avg_stats(&runtime_nsecs_stats[cpu]);
 
-		if (total)
-			ratio = 1000.0 * avg / total;
-
-		fprintf(logfp, " # %10.3f M/sec", ratio);
+		prt->unit("M/sec", 1000.0 * avg,
+			avg_stats(&runtime_nsecs_stats[cpu]));
 	}
 }
 
@@ -475,7 +564,8 @@ static void print_counter_aggr(struct perf_evsel *counter)
 	double avg = avg_stats(&ps->res_stats[0]);
 	int scaled = counter->counts->scaled;
 
-	if (scaled == -1) {
+	if (scaled == -1 && !csv_output) {
+
 		fprintf(logfp, "%*s%s%*s",
 			csv_output ? 0 : 18,
 			"<not counted>",
@@ -484,7 +574,7 @@ static void print_counter_aggr(struct perf_evsel *counter)
 			event_name(counter));
 
 		if (counter->cgrp)
-			fprintf(logfp, "%s%s", csv_sep, counter->cgrp->name);
+			prt->cgrp(counter->cgrp->name);
 
 		fputc('\n', logfp);
 		return;
@@ -495,11 +585,6 @@ static void print_counter_aggr(struct perf_evsel *counter)
 	else
 		abs_printout(-1, counter, avg);
 
-	if (csv_output) {
-		fputc('\n', logfp);
-		return;
-	}
-
 	print_noise(counter, avg);
 
 	if (scaled) {
@@ -508,8 +593,7 @@ static void print_counter_aggr(struct perf_evsel *counter)
 		avg_enabled = avg_stats(&ps->res_stats[1]);
 		avg_running = avg_stats(&ps->res_stats[2]);
 
-		fprintf(logfp, "  (scaled from %.2f%%)",
-				100 * avg_running / avg_enabled);
+		prt->scaled(100 * avg_running / avg_enabled);
 	}
 	fprintf(logfp, "\n");
 }
@@ -527,6 +611,7 @@ static void print_counter(struct perf_evsel *counter)
 		val = counter->counts->cpu[cpu].val;
 		ena = counter->counts->cpu[cpu].ena;
 		run = counter->counts->cpu[cpu].run;
+
 		if (run == 0 || ena == 0) {
 			fprintf(logfp, "CPU%*d%s%*s%s%*s",
 				csv_output ? 0 : -4,
@@ -537,7 +622,7 @@ static void print_counter(struct perf_evsel *counter)
 				event_name(counter));
 
 			if (counter->cgrp)
-				fprintf(logfp, "%s%s", csv_sep, counter->cgrp->name);
+				prt->cgrp(counter->cgrp->name);
 
 			fputc('\n', logfp);
 			continue;
@@ -548,14 +633,12 @@ static void print_counter(struct perf_evsel *counter)
 		else
 			abs_printout(cpu, counter, val);
 
-		if (!csv_output) {
+		if (!csv_output)
 			print_noise(counter, 1.0);
 
-			if (run != ena) {
-				fprintf(logfp, "  (scaled from %.2f%%)",
-					100.0 * run / ena);
-			}
-		}
+		if (run != ena)
+			prt->scaled(100.0 * run / ena);
+
 		fputc('\n', logfp);
 	}
 }
@@ -593,17 +676,15 @@ static void print_stat(int argc, const char **argv)
 			print_counter_aggr(counter);
 	}
 
-	if (!csv_output) {
+	if (!csv_output)
 		fprintf(logfp, "\n");
-		fprintf(logfp, " %18.9f  seconds time elapsed",
-				avg_stats(&walltime_nsecs_stats)/1e9);
-		if (run_count > 1) {
-			fprintf(logfp, "   ( +- %7.3f%% )",
-				100*stddev_stats(&walltime_nsecs_stats) /
-				avg_stats(&walltime_nsecs_stats));
-		}
-		fprintf(logfp, "\n\n");
-	}
+
+	prt->time("seconds-time-elapsed", avg_stats(&walltime_nsecs_stats)/1e9);
+	if (run_count > 1)
+		prt->noise(
+			100 * stddev_stats(&walltime_nsecs_stats),
+			avg_stats(&walltime_nsecs_stats));
+	fprintf(logfp, "\n");
 }
 
 static volatile int signr = -1;
@@ -662,7 +743,7 @@ static const struct option options[] = {
 		    "repeat command and print average + stddev (max: 100)"),
 	OPT_BOOLEAN('n', "null", &null_run,
 		    "null run - dont start any counters"),
-	OPT_CALLBACK_NOOPT('B', "big-num", NULL, NULL, 
+	OPT_CALLBACK_NOOPT('B', "big-num", NULL, NULL,
 			   "print large numbers with thousands\' separators",
 			   stat__set_big_num),
 	OPT_STRING('C', "cpu", &cpu_list, "cpu",
@@ -670,7 +751,7 @@ static const struct option options[] = {
 	OPT_BOOLEAN('A', "no-aggr", &no_aggr,
 		    "disable CPU count aggregation"),
 	OPT_STRING('x', "field-separator", &csv_sep, "separator",
-		   "print counts with custom separator"),
+		   "print counts with custom separator (csv-output)"),
 	OPT_CALLBACK('G', "cgroup", &evsel_list, "name",
 		     "monitor event in cgroup name only",
 		     parse_cgroups),
@@ -699,16 +780,20 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 		exit(1);
 	}
 
-	if (csv_sep)
+	if (csv_sep) {
 		csv_output = true;
-	else
+		prt = &csv_print_ops;
+		if (!strcmp(csv_sep, "\\t"))
+			csv_sep = "\t";
+	} else {
 		csv_sep = DEFAULT_SEPARATOR;
-
+		prt = &user_print_ops;
+	}
 	/*
 	 * let the spreadsheet do the pretty-printing
 	 */
 	if (csv_output) {
-		/* User explicitely passed -B? */
+		/* User explicitly passed -B? */
 		if (big_num_opt == 1) {
 			fprintf(logfp, "-B option not supported with -x\n");
 			usage_with_options(stat_usage, options);
-- 
1.7.4.4

[PATCH 2/3] perf-stat: fix +- nan% in -Aa runs

[Jim Cromie]

without this patch, I get computations like this:

[jimc@groucho perf]$ sudo ./perf stat -r3 -Aa  perl -e '$i++ for 1..100000'

 Performance counter stats for 'perl -e $i++ for 1..100000' (3 runs):

CPU0             12.391883 task-clock-msecs         #      0.966 CPUs    ( +-    -nan% )
CPU1             12.446571 task-clock-msecs         #      0.970 CPUs    ( +-    -nan% )
CPU2             12.408014 task-clock-msecs         #      0.967 CPUs    ( +-    -nan% )
CPU3             12.422264 task-clock-msecs         #      0.968 CPUs    ( +-    -nan% )

I couldnt see anything wrong in the caller, so fixed it in stddev_stats()

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |    9 +++++++--
 1 files changed, 7 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index 71bbf72..c59d199 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -151,8 +151,13 @@ static double avg_stats(struct stats *stats)
  */
 static double stddev_stats(struct stats *stats)
 {
-	double variance = stats->M2 / (stats->n - 1);
-	double variance_mean = variance / stats->n;
+	double variance, variance_mean;
+
+	if (!stats->n)
+		return 0.0;
+
+	variance = stats->M2 / (stats->n - 1);
+	variance_mean = variance / stats->n;
 
 	return sqrt(variance_mean);
 }
-- 
1.7.4.4

[PATCH 3/3] perf-stat: clean up <no count> handling, CPUx prefixing

[Jim Cromie]

push <no-count> printing into print-ops to hide some cruft, and fold
away dynamic formats.  Refactor cpustr string prep into cpustr(int
cpu), use it everywhere, and change fn-sigs accordingly.

Also includes 1-line fixup for overlooked hack in earlier patch:
  -       if (scaled == -1 && !csv_output) {
  +       if (scaled == -1) {

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |  101 +++++++++++++++++++++++++++-----------------
 1 files changed, 62 insertions(+), 39 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index c59d199..9c03e99 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -383,12 +383,14 @@ static int run_perf_stat(int argc __used, const char **argv)
 
 struct print_ops {
 	int (*noise)  (double numer, double denom);
-	int (*nsec)   (const char *evt_name, double msecs, char *cpustr);
-	int (*abs)    (const char*, double avg, char *cpustr);
+	int (*nsec)   (const char *evt_name, double msecs, int cpu);
+	int (*abs)    (const char*, double avg, int cpu);
 	int (*unit)   (const char*, double, double);
 	int (*scaled) (double);
 	int (*cgrp)   (const char *name);
 	int (*time)   (const char *label, double mtime);
+	int (*ctr)    (const char *label, int val);
+	int (*noct)   (const char *label, int cpu);
 };
 static struct print_ops *prt;
 
@@ -406,24 +408,48 @@ static int csv_pr_noise(double numer, double denom)
 		ratio = numer / denom;
 	return fprintf(logfp, "%s%.3f%%", csv_sep, ratio);
 }
-static int user_pr_nsec(const char *evt_name, double msecs, char *cpustr)
+
+static char _cpustr[16];
+static char * cpustr(int cpu)
+{
+	_cpustr[0] = '\0';
+	if (cpu > -1) {
+		sprintf(_cpustr, "CPU%*d%s",
+			csv_output ? 0 : -4,
+			cpu, csv_sep);
+	}
+	return _cpustr;
+}
+static int user_pr_nsec(const char *evt_name, double msecs, int cpu)
 {
 	return fprintf(logfp, "%s%18.6f%s%-24s",
-			cpustr, msecs, csv_sep, evt_name);
+			cpustr(cpu), msecs, csv_sep, evt_name);
 }
-static int csv_pr_nsec(const char *evt_name, double msecs, char *cpustr)
+static int csv_pr_nsec(const char *evt_name, double msecs, int cpu)
 {
-	return fprintf(logfp, "%s%s%s%.6f", cpustr, evt_name, csv_sep, msecs);
+	return fprintf(logfp, "%s%s%s%.6f", cpustr(cpu), evt_name,
+			csv_sep, msecs);
 }
 
-static int user_pr_abs(const char *evt_name, double avg, char *cpustr)
+static int user_pr_abs(const char *evt_name, double avg, int cpu)
 {
 	const char *fmt = (big_num) ? "%s%'18.0f%s%-24s" : "%s%18.0f%s%-24s";
-	return fprintf(logfp, fmt, cpustr, avg, csv_sep, evt_name);
+	return fprintf(logfp, fmt, cpustr(cpu), avg, csv_sep, evt_name);
+}
+static int csv_pr_abs(const char *evt_name, double avg, int cpu)
+{
+	return fprintf(logfp, "%s%s%s%.0f", cpustr(cpu), evt_name, csv_sep, avg);
+}
+
+static int user_pr_nc(const char *evt_name, int cpu)
+{
+	return fprintf(logfp, "%s%18s%s%-24s", cpustr(cpu), "<not counted>",
+			csv_sep, evt_name);
 }
-static int csv_pr_abs(const char *evt_name, double avg, char *cpustr)
+static int csv_pr_nc(const char *evt_name, int cpu)
 {
-	return fprintf(logfp, "%s%s%s%.0f", cpustr, evt_name, csv_sep, avg);
+	return fprintf(logfp, "%s%s%s%s", cpustr(cpu), evt_name,
+			csv_sep, "<not-counted>");
 }
 
 static int user_pr_unit(const char *unit, double numer, double denom)
@@ -468,6 +494,20 @@ static int csv_pr_time(const char *label, double mtime)
 	return fprintf(logfp, "%s%s%.9f", label, csv_sep, mtime);
 }
 
+static int _pr_ctr(const char *label, int val)
+{
+	if (csv_output)
+		return fprintf(logfp, "CPU%0d%s%s%s%s",
+				val, csv_sep,
+				"<not counted>", csv_sep,
+				label);
+	else
+		return fprintf(logfp, "CPU%-4d%s%18s%s%-24s",
+				val, csv_sep,
+				"<not counted>", csv_sep,
+				label);
+}
+
 struct print_ops user_print_ops = {
 	.noise	= user_pr_noise,
 	.nsec	= user_pr_nsec,
@@ -476,6 +516,8 @@ struct print_ops user_print_ops = {
 	.cgrp	= user_pr_cgrp,
 	.unit	= user_pr_unit,
 	.time	= user_pr_time,
+	.ctr	= _pr_ctr,
+	.noct	= user_pr_nc,
 };
 
 struct print_ops csv_print_ops = {
@@ -486,6 +528,8 @@ struct print_ops csv_print_ops = {
 	.cgrp	= csv_pr_cgrp,
 	.unit	= csv_pr_unit,
 	.time	= csv_pr_time,
+	.ctr	= _pr_ctr,
+	.noct	= csv_pr_nc,
 };
 
 static void print_noise(struct perf_evsel *evsel, double avg)
@@ -502,14 +546,8 @@ static void print_noise(struct perf_evsel *evsel, double avg)
 static void nsec_printout(int cpu, struct perf_evsel *evsel, double avg)
 {
 	double msecs = avg / 1e6;
-	char cpustr[16] = { '\0', };
-
-	if (no_aggr)
-		sprintf(cpustr, "CPU%*d%s",
-			csv_output ? 0 : -4,
-			evsel_list->cpus->map[cpu], csv_sep);
 
-	prt->nsec(event_name(evsel), msecs, cpustr);
+	prt->nsec(event_name(evsel), msecs, cpu);
 
 	if (evsel->cgrp)
 		prt->cgrp(evsel->cgrp->name);
@@ -524,17 +562,11 @@ static void nsec_printout(int cpu, struct perf_evsel *evsel, double avg)
 
 static void abs_printout(int cpu, struct perf_evsel *evsel, double avg)
 {
-	char cpustr[16] = { '\0', };
+	prt->abs(event_name(evsel), avg, cpu);
 
-	if (no_aggr)
-		sprintf(cpustr, "CPU%*d%s",
-			csv_output ? 0 : -4,
-			evsel_list->cpus->map[cpu], csv_sep);
-	else
+	if (!no_aggr)
 		cpu = 0;
 
-	prt->abs(event_name(evsel), avg, cpustr);
-
 	if (evsel->cgrp)
 		prt->cgrp(evsel->cgrp->name);
 
@@ -569,14 +601,9 @@ static void print_counter_aggr(struct perf_evsel *counter)
 	double avg = avg_stats(&ps->res_stats[0]);
 	int scaled = counter->counts->scaled;
 
-	if (scaled == -1 && !csv_output) {
+	if (scaled == -1) {
 
-		fprintf(logfp, "%*s%s%*s",
-			csv_output ? 0 : 18,
-			"<not counted>",
-			csv_sep,
-			csv_output ? 0 : -24,
-			event_name(counter));
+		prt->noct(event_name(counter), -1);
 
 		if (counter->cgrp)
 			prt->cgrp(counter->cgrp->name);
@@ -618,13 +645,9 @@ static void print_counter(struct perf_evsel *counter)
 		run = counter->counts->cpu[cpu].run;
 
 		if (run == 0 || ena == 0) {
-			fprintf(logfp, "CPU%*d%s%*s%s%*s",
-				csv_output ? 0 : -4,
-				evsel_list->cpus->map[cpu], csv_sep,
-				csv_output ? 0 : 18,
-				"<not counted>", csv_sep,
-				csv_output ? 0 : -24,
-				event_name(counter));
+
+			prt->ctr(event_name(counter),
+				evsel_list->cpus->map[cpu]);
 
 			if (counter->cgrp)
 				prt->cgrp(counter->cgrp->name);
-- 
1.7.4.4

Re: [PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Jim Cromie]

On Sat, May 21, 2011 at 2:41 PM, Arnaldo Carvalho de Melo
<acme@ghostprotocols.net> wrote:
> Em Sat, May 21, 2011 at 12:34:18PM +0200, Ingo Molnar escreveu:
>>
>> * Jim Cromie <jim.cromie@gmail.com> wrote:
>>
>> > This perf stat option emulates valgrind's --log-fd option, allowing the
>> > user to send perf results elsewhere, and leaving stderr for use by the
>> > program under test.
>> >
>> >   3>results perf stat -l 3 -- <cmd>
>> >
>> > The perl distro's make test.valgrind target uses valgrinds --log-fd
>> > option, I've adapted it to invoke perf also, and tested this patch there.
>> >
>> > Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
>>
>> Makes sense!
>>
>> Arnaldo, if you are fine with it, do you want to pick it up - or should i? If
>> you pick it up:
>>
>> Acked-by: Ingo Molnar <mingo@elte.hu>
>
> Its ok with me:
>
> Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>
>
> I will pick it this weekend, if you don't merge it till then.
>
> - Arnaldo
>

Did this ever happen ?
Can you point me to the git-url where it did/will end up ?

Re: [PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Arnaldo Carvalho de Melo]

Em Thu, Sep 01, 2011 at 03:58:13PM -0600, Jim Cromie escreveu:
> On Sat, May 21, 2011 at 2:41 PM, Arnaldo Carvalho de Melo
> <acme@ghostprotocols.net> wrote:
> > Em Sat, May 21, 2011 at 12:34:18PM +0200, Ingo Molnar escreveu:
> >> * Jim Cromie <jim.cromie@gmail.com> wrote:
> >>
> >> > This perf stat option emulates valgrind's --log-fd option, allowing the
> >> > user to send perf results elsewhere, and leaving stderr for use by the
> >> > program under test.
> >> >
> >> >   3>results perf stat -l 3 -- <cmd>
> >> >
> >> > The perl distro's make test.valgrind target uses valgrinds --log-fd
> >> > option, I've adapted it to invoke perf also, and tested this patch there.
> >> >
> >> > Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> >>
> >> Makes sense!
> >>
> >> Arnaldo, if you are fine with it, do you want to pick it up - or should i? If
> >> you pick it up:
> >>
> >> Acked-by: Ingo Molnar <mingo@elte.hu>
> >
> > Its ok with me:
> >
> > Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> >
> > I will pick it this weekend, if you don't merge it till then.

> Did this ever happen ?
> Can you point me to the git-url where it did/will end up ?

Fell thru the cracks, then Stephane implemented --output:

http://git.kernel.org/?p=linux/kernel/git/tip/linux-tip.git;a=commitdiff;h=4aa9015f8bfd2c8d7cc33a360275b71a9d708b37

That introduces an output FILE pointer as in your patch (logfp), so I
adjusted your patch, that ended up like below. I removed -l and made it
--log-fd, just like valgrind and added the Documentation bits about the
new cmdline option, ok?

I'll look at the other 3 patch series that came after, will fix up and
post here for your consideration.

- Arnaldo

diff --git a/tools/perf/Documentation/perf-stat.txt b/tools/perf/Documentation/perf-stat.txt
index 08394c4..b6bfd1e 100644
--- a/tools/perf/Documentation/perf-stat.txt
+++ b/tools/perf/Documentation/perf-stat.txt
@@ -101,6 +101,9 @@ Print the output into the designated file.
 --append::
 Append to the output file designated with the -o option. Ignored if -o is not specified.
 
+--log-fd::
+Log output to fd, instead of stderr.
+
 EXAMPLES
 --------
 
diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index bec64a9..c991d66 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -196,6 +196,8 @@ static bool			csv_output			= false;
 static bool			group				= false;
 static const char		*output_name			= NULL;
 static FILE			*output				= NULL;
+/* stderr by default, override with -l */
+static int			output_fd			= 2;
 
 static volatile int done = 0;
 
@@ -1080,6 +1082,8 @@ static const struct option options[] = {
 	OPT_STRING('o', "output", &output_name, "file",
 		    "output file name"),
 	OPT_BOOLEAN(0, "append", &append_file, "append to the output file"),
+	OPT_INTEGER(0, "log-fd", &output_fd,
+		    "log output to fd, instead of stderr"),
 	OPT_END()
 };
 
@@ -1177,6 +1181,12 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 		}
 		clock_gettime(CLOCK_REALTIME, &tm);
 		fprintf(output, "# started on %s\n", ctime(&tm.tv_sec));
+	} else if (output_fd != 2) {
+		output = fdopen(output_fd, "w");
+		if (!output) {
+			perror("Failed opening logfd");
+			return -errno;
+		}
 	}
 
 	if (csv_sep)

Re: [PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Arnaldo Carvalho de Melo]

Em Fri, Sep 02, 2011 at 11:35:49AM -0300, Arnaldo Carvalho de Melo escreveu:
> I'll look at the other 3 patch series that came after, will fix up and
> post here for your consideration.

Can you try to rehash those? Ingo added a series of patches to print
other metrics (stalled cycles frontend, etc) and the changes require
some more work, if you could work on it I'd appreciate.

Again, sorry for not having merged this sooner, avoiding this work now.

- Arnaldo

Re: [PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Jim Cromie]

On Fri, Sep 2, 2011 at 8:35 AM, Arnaldo Carvalho de Melo
<acme@ghostprotocols.net> wrote:
> Em Thu, Sep 01, 2011 at 03:58:13PM -0600, Jim Cromie escreveu:
>> On Sat, May 21, 2011 at 2:41 PM, Arnaldo Carvalho de Melo
>> <acme@ghostprotocols.net> wrote:
>> > Em Sat, May 21, 2011 at 12:34:18PM +0200, Ingo Molnar escreveu:
>> >> * Jim Cromie <jim.cromie@gmail.com> wrote:
>> >>
>> >> > This perf stat option emulates valgrind's --log-fd option, allowing the
>> >> > user to send perf results elsewhere, and leaving stderr for use by the
>> >> > program under test.
>> >> >
>> >> >   3>results perf stat -l 3 -- <cmd>
>> >> >
>> >> > The perl distro's make test.valgrind target uses valgrinds --log-fd
>> >> > option, I've adapted it to invoke perf also, and tested this patch there.
>> >> >
>> >> > Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
>> >>
>> >> Makes sense!
>> >>
>> >> Arnaldo, if you are fine with it, do you want to pick it up - or should i? If
>> >> you pick it up:
>> >>
>> >> Acked-by: Ingo Molnar <mingo@elte.hu>
>> >
>> > Its ok with me:
>> >
>> > Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>
>> >
>> > I will pick it this weekend, if you don't merge it till then.
>
>> Did this ever happen ?
>> Can you point me to the git-url where it did/will end up ?
>
> Fell thru the cracks, then Stephane implemented --output:
>
> http://git.kernel.org/?p=linux/kernel/git/tip/linux-tip.git;a=commitdiff;h=4aa9015f8bfd2c8d7cc33a360275b71a9d708b37
>
> That introduces an output FILE pointer as in your patch (logfp), so I
> adjusted your patch, that ended up like below. I removed -l and made it
> --log-fd, just like valgrind and added the Documentation bits about the
> new cmdline option, ok?
>

absolutely.
theres one comment I added (just above output_fd decl)
that mentions -I, it should be updated to --log-fd

And probably --output and --log-fd should be mutually exclusive.

> I'll look at the other 3 patch series that came after, will fix up and
> post here for your consideration.

those are the output format refactoring ?

ah, your new message just arrived.
I'll take another go at them..
thanks

>
> - Arnaldo
>
> diff --git a/tools/perf/Documentation/perf-stat.txt b/tools/perf/Documentation/perf-stat.txt
> index 08394c4..b6bfd1e 100644
> --- a/tools/perf/Documentation/perf-stat.txt
> +++ b/tools/perf/Documentation/perf-stat.txt
> @@ -101,6 +101,9 @@ Print the output into the designated file.
>  --append::
>  Append to the output file designated with the -o option. Ignored if -o is not specified.
>
> +--log-fd::
> +Log output to fd, instead of stderr.

stderr / outputfile ??

> +
>  EXAMPLES
>  --------
>
> diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
> index bec64a9..c991d66 100644
> --- a/tools/perf/builtin-stat.c
> +++ b/tools/perf/builtin-stat.c
> @@ -196,6 +196,8 @@ static bool                 csv_output                      = false;
>  static bool                    group                           = false;
>  static const char              *output_name                    = NULL;
>  static FILE                    *output                         = NULL;
> +/* stderr by default, override with -l */

with --log-fd

> +static int                     output_fd                       = 2;
>
>  static volatile int done = 0;
>
> @@ -1080,6 +1082,8 @@ static const struct option options[] = {
>        OPT_STRING('o', "output", &output_name, "file",
>                    "output file name"),
>        OPT_BOOLEAN(0, "append", &append_file, "append to the output file"),
> +       OPT_INTEGER(0, "log-fd", &output_fd,
> +                   "log output to fd, instead of stderr"),
>        OPT_END()
>  };
>
> @@ -1177,6 +1181,12 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
>                }
>                clock_gettime(CLOCK_REALTIME, &tm);
>                fprintf(output, "# started on %s\n", ctime(&tm.tv_sec));
> +       } else if (output_fd != 2) {
> +               output = fdopen(output_fd, "w");
> +               if (!output) {
> +                       perror("Failed opening logfd");
> +                       return -errno;
> +               }
>        }
>
>        if (csv_sep)
>

Re: [PATCH 1/2] perf stat: add -l <N> option to redirect stderr elsewhere

[Arnaldo Carvalho de Melo]

Em Fri, Sep 02, 2011 at 12:04:03PM -0600, Jim Cromie escreveu:
> On Fri, Sep 2, 2011 at 8:35 AM, Arnaldo Carvalho de Melo
> <acme@ghostprotocols.net> wrote:
> > Em Thu, Sep 01, 2011 at 03:58:13PM -0600, Jim Cromie escreveu:
> >> On Sat, May 21, 2011 at 2:41 PM, Arnaldo Carvalho de Melo
> >> <acme@ghostprotocols.net> wrote:
> >> > Em Sat, May 21, 2011 at 12:34:18PM +0200, Ingo Molnar escreveu:
> >> >> * Jim Cromie <jim.cromie@gmail.com> wrote:
> >> >>
> >> >> > This perf stat option emulates valgrind's --log-fd option, allowing the
> >> >> > user to send perf results elsewhere, and leaving stderr for use by the
> >> >> > program under test.
> >> >> >
> >> >> >   3>results perf stat -l 3 -- <cmd>
> >> >> >
> >> >> > The perl distro's make test.valgrind target uses valgrinds --log-fd
> >> >> > option, I've adapted it to invoke perf also, and tested this patch there.
> >> >> >
> >> >> > Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
> >> >>
> >> >> Makes sense!
> >> >>
> >> >> Arnaldo, if you are fine with it, do you want to pick it up - or should i? If
> >> >> you pick it up:
> >> >>
> >> >> Acked-by: Ingo Molnar <mingo@elte.hu>
> >> >
> >> > Its ok with me:
> >> >
> >> > Acked-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> >> >
> >> > I will pick it this weekend, if you don't merge it till then.
> >
> >> Did this ever happen ?
> >> Can you point me to the git-url where it did/will end up ?
> >
> > Fell thru the cracks, then Stephane implemented --output:
> >
> > http://git.kernel.org/?p=linux/kernel/git/tip/linux-tip.git;a=commitdiff;h=4aa9015f8bfd2c8d7cc33a360275b71a9d708b37
> >
> > That introduces an output FILE pointer as in your patch (logfp), so I
> > adjusted your patch, that ended up like below. I removed -l and made it
> > --log-fd, just like valgrind and added the Documentation bits about the
> > new cmdline option, ok?
> >
> 
> absolutely.
> theres one comment I added (just above output_fd decl)
> that mentions -I, it should be updated to --log-fd
> 
> And probably --output and --log-fd should be mutually exclusive.

With the current implementation if --output is used --log-fd will be
ignored if present, perhaps we should print a warning or plain fail if
the user tries to specify both?
 
> > I'll look at the other 3 patch series that came after, will fix up and
> > post here for your consideration.
> 
> those are the output format refactoring ?
> 
> ah, your new message just arrived.
> I'll take another go at them..

Ok, please apply this reworked --log-fd before, of course :)

> thanks
> 
> >
> > - Arnaldo
> >
> > diff --git a/tools/perf/Documentation/perf-stat.txt b/tools/perf/Documentation/perf-stat.txt
> > index 08394c4..b6bfd1e 100644
> > --- a/tools/perf/Documentation/perf-stat.txt
> > +++ b/tools/perf/Documentation/perf-stat.txt
> > @@ -101,6 +101,9 @@ Print the output into the designated file.
> >  --append::
> >  Append to the output file designated with the -o option. Ignored if -o is not specified.
> >
> > +--log-fd::
> > +Log output to fd, instead of stderr.
> 
> stderr / outputfile ??
> 
> > +
> >  EXAMPLES
> >  --------
> >
> > diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
> > index bec64a9..c991d66 100644
> > --- a/tools/perf/builtin-stat.c
> > +++ b/tools/perf/builtin-stat.c
> > @@ -196,6 +196,8 @@ static bool                 csv_output                      = false;
> >  static bool                    group                           = false;
> >  static const char              *output_name                    = NULL;
> >  static FILE                    *output                         = NULL;
> > +/* stderr by default, override with -l */
> 
> with --log-fd

Can you rework it and put as the first on your new patchset?

Thanks,

- Arnaldo
 
> > +static int                     output_fd                       = 2;
> >
> >  static volatile int done = 0;
> >
> > @@ -1080,6 +1082,8 @@ static const struct option options[] = {
> >        OPT_STRING('o', "output", &output_name, "file",
> >                    "output file name"),
> >        OPT_BOOLEAN(0, "append", &append_file, "append to the output file"),
> > +       OPT_INTEGER(0, "log-fd", &output_fd,
> > +                   "log output to fd, instead of stderr"),
> >        OPT_END()
> >  };
> >
> > @@ -1177,6 +1181,12 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
> >                }
> >                clock_gettime(CLOCK_REALTIME, &tm);
> >                fprintf(output, "# started on %s\n", ctime(&tm.tv_sec));
> > +       } else if (output_fd != 2) {
> > +               output = fdopen(output_fd, "w");
> > +               if (!output) {
> > +                       perror("Failed opening logfd");
> > +                       return -errno;
> > +               }
> >        }
> >
> >        if (csv_sep)
> >

[patch 0/5] perf stat --log-fd=N

[Jim Cromie]

hi Arnaldo,

Heres the "update" to the patchset I promised.

[PATCH 1/5] perf stat: add --log-fd <N> option to redirect stderr
[PATCH 2/5] perf-stat: fix +- nan% in --no-aggr runs
[PATCH 3/5] perf stat: suppress printing std-dev when its 0
[PATCH 4/5] perf stat: allow tab as cvs delimiter
[PATCH 5/5] perf stat: fix spelling in comment

Ive dropped the 'print-ops' patches for a few reasons:

- pretty and cvs outputs have diverged further, pretty has added info,
  cvs has dropped the final timing line (probably cuz it didnt fit in
  the table). I presume there are good reasons for this.

- Id be parsing with perl anyway, so cvs regularity isnt important, and
  the richer info in pretty mode is useful.

- fiddling with output format is just as likely to break somebodys parsing,
  minor aesthetic improvements arent worth it. Its easier to do nothing.

[PATCH 1/5] perf stat: add --log-fd <N> option to redirect stderr elsewhere

[Jim Cromie]

From: Arnaldo Carvalho de Melo <acme@ghostprotocols.net>

This perf stat option emulates valgrind's --log-fd option, allowing
the user to send perf results elsewhere, and leaving stderr for use by
the program under test.  This complements --output file option, and is
mutually exclusive with it.

   3>results  perf stat --log-fd 3          -- $cmd
   3>>results perf stat --log-fd 3 --append -- $cmd

The perl distro's make test.valgrind target uses valgrind's --log-fd
option, I've adapted it to invoke perf also, and tested this patch
there.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>

fold
---
 tools/perf/Documentation/perf-stat.txt |   11 ++++++++++-
 tools/perf/builtin-stat.c              |   14 ++++++++++++++
 2 files changed, 24 insertions(+), 1 deletions(-)

diff --git a/tools/perf/Documentation/perf-stat.txt b/tools/perf/Documentation/perf-stat.txt
index 08394c4..8966b9a 100644
--- a/tools/perf/Documentation/perf-stat.txt
+++ b/tools/perf/Documentation/perf-stat.txt
@@ -95,12 +95,21 @@ corresponding events, i.e., they always refer to events defined earlier on the c
 line.
 
 -o file::
--output file::
+--output file::
 Print the output into the designated file.
 
 --append::
 Append to the output file designated with the -o option. Ignored if -o is not specified.
 
+--log-fd::
+
+Log output to fd, instead of stderr.  Complementary to --output, and mutually exclusive
+with it.  --append may be used here.  Examples:
+     3>results  perf stat --log-fd 3          -- $cmd
+     3>>results perf stat --log-fd 3 --append -- $cmd
+
+
+
 EXAMPLES
 --------
 
diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index bec64a9..5e3206e 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -196,6 +196,7 @@ static bool			csv_output			= false;
 static bool			group				= false;
 static const char		*output_name			= NULL;
 static FILE			*output				= NULL;
+static int			output_fd			=  0;
 
 static volatile int done = 0;
 
@@ -1080,6 +1081,8 @@ static const struct option options[] = {
 	OPT_STRING('o', "output", &output_name, "file",
 		    "output file name"),
 	OPT_BOOLEAN(0, "append", &append_file, "append to the output file"),
+	OPT_INTEGER(0, "log-fd", &output_fd,
+		    "log output to fd, instead of stderr"),
 	OPT_END()
 };
 
@@ -1166,6 +1169,10 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 	if (output_name && strcmp(output_name, "-"))
 		output = NULL;
 
+	if (output_name && output_fd) {
+		fprintf(stderr, "cannot use both --output and --log-fd\n");
+		usage_with_options(stat_usage, options);
+	}
 	if (!output) {
 		struct timespec tm;
 		mode = append_file ? "a" : "w";
@@ -1177,6 +1184,13 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 		}
 		clock_gettime(CLOCK_REALTIME, &tm);
 		fprintf(output, "# started on %s\n", ctime(&tm.tv_sec));
+	} else if (output_fd != 2) {
+		mode = append_file ? "a" : "w";
+		output = fdopen(output_fd, mode);
+		if (!output) {
+			perror("Failed opening logfd");
+			return -errno;
+		}
 	}
 
 	if (csv_sep)
-- 
1.7.4.4

[PATCH 2/5] perf-stat: fix +- nan% in --no-aggr runs

[Jim Cromie]

without this patch, running:
$ sudo ./perf stat -r20 --no-aggr -a perl -e '$i++ for 1..100000'

I get computations like this:

CPU0             12.488247 task-clock                #    1.224 CPUs utilized            ( +-  -nan% )
CPU1             12.488909 task-clock                #    1.225 CPUs utilized            ( +-  -nan% )
CPU2             12.500221 task-clock                #    1.226 CPUs utilized            ( +-  -nan% )
CPU3             12.481713 task-clock                #    1.224 CPUs utilized            ( +-  -nan% )

but with patch, I get:

CPU0              8.233682 task-clock                #    0.754 CPUs utilized            ( +-  0.00% )
CPU1              8.226318 task-clock                #    0.754 CPUs utilized            ( +-  0.00% )
CPU2              8.210737 task-clock                #    0.752 CPUs utilized            ( +-  0.00% )
CPU3              8.201691 task-clock                #    0.751 CPUs utilized            ( +-  0.00% )

Note that without --no-aggr, I get non-0 statistics both before and after patch:

        231.986022 task-clock                #    4.030 CPUs utilized            ( +-  0.97% )
               212 context-switches          #    0.001 M/sec                    ( +- 12.07% )
                 9 CPU-migrations            #    0.000 M/sec                    ( +- 25.80% )
               466 page-faults               #    0.002 M/sec                    ( +-  3.23% )
       174,318,593 cycles                    #    0.751 GHz                      ( +-  1.06% )

I couldnt see anything wrong in the caller, so fixed it in
stddev_stats().  ISTM that 0.00 is better than nan, since perf stat
was passed -A (--no-aggr) so no standard deviation should be expected,
and nan is suggestive of a deeper error.

When running with --no-aggr, perhaps we should suppress the statistics
printing entirely, or do so when they are 0.00.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |    9 +++++++--
 1 files changed, 7 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index 5e3206e..c6e47d2 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -254,8 +254,13 @@ static double avg_stats(struct stats *stats)
  */
 static double stddev_stats(struct stats *stats)
 {
-	double variance = stats->M2 / (stats->n - 1);
-	double variance_mean = variance / stats->n;
+	double variance, variance_mean;
+
+	if (!stats->n)
+		return 0.0;
+
+	variance = stats->M2 / (stats->n - 1);
+	variance_mean = variance / stats->n;
 
 	return sqrt(variance_mean);
 }
-- 
1.7.4.4

[PATCH 3/5] perf stat: suppress printing std-dev when its 0

[Jim Cromie]

For pretty output only (preserve column for cvs output), dont print
std-deviation when its 0.00.  Do this based upon value, instead of
checking for --no-aggr, since the stats could conceivably be computed
over the runs on each CPU, and theres no reason to preclude that.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index c6e47d2..660bed1 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -528,7 +528,7 @@ static void print_noise_pct(double total, double avg)
 
 	if (csv_output)
 		fprintf(output, "%s%.2f%%", csv_sep, pct);
-	else
+	else if (pct)
 		fprintf(output, "  ( +-%6.2f%% )", pct);
 }
 
-- 
1.7.4.4

[PATCH 4/5] perf stat: allow tab as cvs delimiter

[Jim Cromie]

If option -x '\t' is given, convert '\t' to "\t".
This makes cvs printing more flexible.

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |    6 ++++--
 1 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index 660bed1..b3e6e56 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -1198,9 +1198,11 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 		}
 	}
 
-	if (csv_sep)
+	if (csv_sep) {
 		csv_output = true;
-	else
+		if (!strcmp(csv_sep, "\\t"))
+			csv_sep = "\t";
+	} else
 		csv_sep = DEFAULT_SEPARATOR;
 
 	/*
-- 
1.7.4.4

[PATCH 5/5] perf stat: fix spelling in comment

[Jim Cromie]

Signed-off-by: Jim Cromie <jim.cromie@gmail.com>
---
 tools/perf/builtin-stat.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/tools/perf/builtin-stat.c b/tools/perf/builtin-stat.c
index b3e6e56..92c27a2 100644
--- a/tools/perf/builtin-stat.c
+++ b/tools/perf/builtin-stat.c
@@ -1209,7 +1209,7 @@ int cmd_stat(int argc, const char **argv, const char *prefix __used)
 	 * let the spreadsheet do the pretty-printing
 	 */
 	if (csv_output) {
-		/* User explicitely passed -B? */
+		/* User explicitly passed -B? */
 		if (big_num_opt == 1) {
 			fprintf(stderr, "-B option not supported with -x\n");
 			usage_with_options(stat_usage, options);
-- 
1.7.4.4