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

[kan.liang@intel.com]

From: Kan Liang <kan.liang@intel.com>

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@intel.com>
---
 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