[PATCH V2 12/13] perf tools: record user space profiling cost

From: kan . liang
Date: Fri Dec 02 2016 - 16:24:01 EST


From: Kan Liang <kan.liang@xxxxxxxxx>

Record the cpu time and elapsed time of perf record.
Show them in perf report.

# To display the perf.data header info, please use
--header/--header-only options.
#
# ========
# Elapsed time: 1199332708(ns)
# Perf record cpu time: 197780038(ns)
#
# CPU SAM SAM cost(ns) MUX MUX cost(ns) SB
SB cost(ns)
# 0 2 13659 12101 6111457 0
0
# 1 1 8160 12101 46062331 0
0

Signed-off-by: Kan Liang <kan.liang@xxxxxxxxx>
---
tools/perf/builtin-record.c | 52 ++++++++++++++++++++++++++++++++++++++++++++-
tools/perf/util/event.h | 4 ++++
tools/perf/util/machine.c | 5 +++++
tools/perf/util/session.c | 8 +++++++
4 files changed, 68 insertions(+), 1 deletion(-)

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index e69099d..405eef4 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -49,6 +49,8 @@ struct record {
struct perf_tool tool;
struct record_opts opts;
u64 bytes_written;
+ u64 record_cpu_time;
+ u64 elapsed_time;
struct perf_data_file file;
struct auxtrace_record *itr;
struct perf_evlist *evlist;
@@ -746,6 +748,47 @@ static const struct perf_event_mmap_page *record__pick_pc(struct record *rec)
return NULL;
}

+static int perf_event__synth_overhead(struct record *rec, u64 type, u64 time,
+ perf_event__handler_t process)
+{
+ union perf_event event = {
+ .overhead = {
+ .header = {
+ .type = PERF_RECORD_USER_OVERHEAD,
+ .size = sizeof(struct perf_overhead),
+ },
+ .type = type,
+ .entry = {
+ .nr = 1,
+ .time = time,
+ },
+ },
+ };
+
+ return process(&rec->tool, &event, NULL, NULL);
+}
+
+static int perf_event__synth_overheads(struct record *rec)
+{
+ int err;
+
+ err = perf_event__synth_overhead(rec, PERF_USER_CPU_TIME,
+ (get_vnsecs() - rec->record_cpu_time),
+ process_synthesized_event);
+ if (err < 0)
+ return err;
+ rec->record_cpu_time = get_vnsecs();
+
+ err = perf_event__synth_overhead(rec, PERF_USER_ELAPSED_TIME,
+ (get_nsecs() - rec->elapsed_time),
+ process_synthesized_event);
+ if (err < 0)
+ return err;
+ rec->elapsed_time = get_nsecs();
+
+ return 0;
+}
+
static int record__synthesize(struct record *rec, bool tail)
{
struct perf_session *session = rec->session;
@@ -757,7 +800,7 @@ static int record__synthesize(struct record *rec, bool tail)
int err = 0;

if (rec->opts.tail_synthesize != tail)
- return 0;
+ goto out;

if (file->is_pipe) {
err = perf_event__synthesize_attrs(tool, session,
@@ -819,6 +862,10 @@ static int record__synthesize(struct record *rec, bool tail)
process_synthesized_event, opts->sample_address,
opts->proc_map_timeout);
out:
+ if (tail && perf_evlist__overhead(session->evlist) &&
+ (perf_event__synth_overheads(rec) < 0))
+ pr_err("Couldn't synthesize user overhead information.\n");
+
return err;
}

@@ -1555,6 +1602,9 @@ int cmd_record(int argc, const char **argv, const char *prefix __maybe_unused)
# undef REASON
#endif

+ rec->record_cpu_time = get_vnsecs();
+ rec->elapsed_time = get_nsecs();
+
rec->evlist = perf_evlist__new();
if (rec->evlist == NULL)
return -ENOMEM;
diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
index 6110f32..9c69c34 100644
--- a/tools/perf/util/event.h
+++ b/tools/perf/util/event.h
@@ -280,6 +280,8 @@ struct events_stats {
u64 total_lost_samples;
u64 total_aux_lost;
u64 total_invalid_chains;
+ u64 cpu_time;
+ u64 elapsed_time;
struct total_overhead overhead;
u32 nr_events[PERF_RECORD_HEADER_MAX];
u32 nr_non_filtered_samples;
@@ -493,6 +495,8 @@ struct time_conv_event {

enum perf_user_overhead_event_type { /* above any possible kernel type */
PERF_USER_OVERHEAD_TYPE_START = 100,
+ PERF_USER_CPU_TIME = 100,
+ PERF_USER_ELAPSED_TIME,
};

struct perf_overhead {
diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
index 72c4412..b95104a 100644
--- a/tools/perf/util/machine.c
+++ b/tools/perf/util/machine.c
@@ -578,6 +578,11 @@ int machine__process_overhead_event(struct machine *machine __maybe_unused,
event->overhead.entry.time,
sample->cpu);
break;
+ case PERF_USER_CPU_TIME:
+ dump_printf(" CPU time: %llu\n", event->overhead.entry.time);
+ break;
+ case PERF_USER_ELAPSED_TIME:
+ dump_printf(" elapsed time: %llu\n", event->overhead.entry.time);
default:
dump_printf("\tUNSUPPORT TYPE 0x%lx!\n", event->overhead.type);
return 0;
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 7745bec..7cf9e1d 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -1233,6 +1233,12 @@ overhead_stats_update(struct perf_tool *tool,
evlist->stats.overhead.total_sb[cpu].nr += event->overhead.entry.nr;
evlist->stats.overhead.total_sb[cpu].time += event->overhead.entry.time;
break;
+ case PERF_USER_CPU_TIME:
+ evlist->stats.cpu_time += event->overhead.entry.time;
+ break;
+ case PERF_USER_ELAPSED_TIME:
+ evlist->stats.elapsed_time += event->overhead.entry.time;
+ break;
default:
break;
}
@@ -2112,6 +2118,8 @@ void perf_session__fprintf_overhead_info(struct perf_session *session,
}

fprintf(fp, "# ========\n");
+ fprintf(fp, "# Elapsed time: %lu(ns)\n", evlist->stats.elapsed_time);
+ fprintf(fp, "# Perf record cpu time: %lu(ns)\n#\n", evlist->stats.cpu_time);
fprintf(fp, "# CPU");
fprintf(fp, " SAM SAM cost(ns)");
fprintf(fp, " MUX MUX cost(ns)");
--
2.5.5