From f21d8b2f7329785da27548e61152d7cd542d9ee1 Mon Sep 17 00:00:00 2001 From: Mengting Zhang Date: Fri, 1 Dec 2017 13:43:57 +0800 Subject: [PATCH] perf record: add execution time check code "record_open_RUN" means the time of record__open(); "Record_RUN" means the time of cmd_record(); "pollfd_RUN" means the time of main part of __cmd_record() polling fds; Test it: $perf record sleep 1 $record_open_RUN is 1.4294047351s pollfd_RUN is 1.8617s [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.014 MB perf.data (28 samples) ] Record_RUN is 2.4294628690s Signed-off-by: Mengting Zhang --- tools/perf/builtin-record.c | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c index 56f8142..f0f0dab 100644 --- a/tools/perf/builtin-record.c +++ b/tools/perf/builtin-record.c @@ -50,6 +50,7 @@ #include #include #include +#include #include #include @@ -432,6 +433,8 @@ static int record__open(struct record *rec) struct record_opts *opts = &rec->opts; struct perf_evsel_config_term *err_term; int rc = 0; + struct timeval start, end; + gettimeofday(&start, NULL); perf_evlist__config(evlist, opts, &callchain_param); @@ -475,6 +478,10 @@ static int record__open(struct record *rec) session->evlist = evlist; perf_session__set_id_hdr_size(session); out: + gettimeofday(&end, NULL); + printf("record_open_RUN is %u.%us\n", + (unsigned int)(end.tv_sec - start.tv_sec), + (unsigned int)(end.tv_usec - start.tv_usec)); return rc; } @@ -881,6 +888,7 @@ static int __cmd_record(struct record *rec, int argc, const char **argv) struct perf_session *session; bool disabled = false, draining = false; int fd; + struct timeval start, end; rec->progname = argv[0]; @@ -1051,6 +1059,7 @@ static int __cmd_record(struct record *rec, int argc, const char **argv) trigger_ready(&auxtrace_snapshot_trigger); trigger_ready(&switch_output_trigger); perf_hooks__invoke_record_start(); + gettimeofday(&start, NULL); for (;;) { unsigned long long hits = rec->samples; @@ -1148,6 +1157,11 @@ static int __cmd_record(struct record *rec, int argc, const char **argv) disabled = true; } } + gettimeofday(&end, NULL); + printf("pollfd_RUN is %u.%us\n", + (unsigned int)(end.tv_sec - start.tv_sec), + (unsigned int)(end.tv_usec - start.tv_usec)); + trigger_off(&auxtrace_snapshot_trigger); trigger_off(&switch_output_trigger); @@ -1688,6 +1702,8 @@ int cmd_record(int argc, const char **argv) int err; struct record *rec = &record; char errbuf[BUFSIZ]; + struct timeval start, end; + gettimeofday(&start, NULL); #ifndef HAVE_LIBBPF_SUPPORT # define set_nobuild(s, l, c) set_option_nobuild(record_options, s, l, "NO_LIBBPF=1", c) @@ -1884,6 +1900,12 @@ int cmd_record(int argc, const char **argv) perf_evlist__delete(rec->evlist); symbol__exit(); auxtrace_record__free(rec->itr); + + gettimeofday(&end, NULL); + printf("Record_RUN is %u.%us\n", + (unsigned int)(end.tv_sec - start.tv_sec), + (unsigned int)(end.tv_usec - start.tv_usec)); + return err; } -- 1.7.12.4