From: Kan Liang <[email protected]> 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 <[email protected]> --- 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
