[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.
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 <[email protected]>
---
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
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 <[email protected]>
---
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
* Jim Cromie <[email protected]> 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
* Jim Cromie <[email protected]> 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 <[email protected]>
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 <[email protected]>
Thanks,
Ingo
Em Sat, May 21, 2011 at 12:34:18PM +0200, Ingo Molnar escreveu:
>
> * Jim Cromie <[email protected]> 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 <[email protected]>
>
> 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 <[email protected]>
Its ok with me:
Acked-by: Arnaldo Carvalho de Melo <[email protected]>
I will pick it this weekend, if you don't merge it till then.
- Arnaldo
On Sat, May 21, 2011 at 4:33 AM, Ingo Molnar <[email protected]> wrote:
>
> * Jim Cromie <[email protected]> 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
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 <[email protected]>
---
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
* Jim Cromie <[email protected]> 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
On Wed, May 25, 2011 at 6:44 AM, Ingo Molnar <[email protected]> wrote:
>
> * Jim Cromie <[email protected]> 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 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) {
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 <[email protected]>
---
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
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 <[email protected]>
---
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
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 <[email protected]>
---
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