Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S965002AbcKWRp5 (ORCPT ); Wed, 23 Nov 2016 12:45:57 -0500 Received: from mga14.intel.com ([192.55.52.115]:40678 "EHLO mga14.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S938750AbcKWRpB (ORCPT ); Wed, 23 Nov 2016 12:45:01 -0500 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.31,539,1473145200"; d="scan'208";a="1072652980" From: kan.liang@intel.com To: peterz@infradead.org, mingo@redhat.com, acme@kernel.org, linux-kernel@vger.kernel.org Cc: alexander.shishkin@linux.intel.com, tglx@linutronix.de, namhyung@kernel.org, jolsa@kernel.org, adrian.hunter@intel.com, wangnan0@huawei.com, mark.rutland@arm.com, andi@firstfloor.org, Kan Liang Subject: [PATCH 11/14] perf tools: record write data overhead Date: Wed, 23 Nov 2016 04:44:49 -0500 Message-Id: <1479894292-16277-12-git-send-email-kan.liang@intel.com> X-Mailer: git-send-email 2.5.5 In-Reply-To: <1479894292-16277-1-git-send-email-kan.liang@intel.com> References: <1479894292-16277-1-git-send-email-kan.liang@intel.com> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 5623 Lines: 187 From: Kan Liang perf record writes all kinds of events to file, which brings overhead as well. Introducing PERF_USER_WRITE_OVERHEAD to save the overhead information. The overhead is measured by the time taken by the write itself, not the elapsed system time. Caculate the total user write overhead on each CPU, and display them in perf report Signed-off-by: Kan Liang --- tools/perf/builtin-record.c | 61 +++++++++++++++++++++++++++++++++++++++++++-- tools/perf/util/event.h | 9 +++++++ tools/perf/util/machine.c | 5 ++++ tools/perf/util/session.c | 4 +++ 4 files changed, 77 insertions(+), 2 deletions(-) diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c index 67d2a90..492058e 100644 --- a/tools/perf/builtin-record.c +++ b/tools/perf/builtin-record.c @@ -45,6 +45,11 @@ #include #include +struct write_overhead{ + u64 nr; + u64 time; +}; + struct record { struct perf_tool tool; struct record_opts opts; @@ -63,17 +68,40 @@ struct record { bool timestamp_filename; bool switch_output; unsigned long long samples; + struct write_overhead overhead[MAX_NR_CPUS]; }; +static u64 get_vnsecs(void) +{ + struct timespec ts; + + clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &ts); + + return ts.tv_sec * NSEC_PER_SEC + ts.tv_nsec; +} + static int record__write(struct record *rec, void *bf, size_t size) { + int cpu = sched_getcpu(); + u64 start, end; + int ret = 0; + + start = get_vnsecs(); if (perf_data_file__write(rec->session->file, bf, size) < 0) { pr_err("failed to write perf data, error: %m\n"); - return -1; + ret = -1; + goto done; } rec->bytes_written += size; - return 0; +done: + end = get_vnsecs(); + if (cpu >= 0) { + rec->overhead[cpu].nr++; + rec->overhead[cpu].time += (end - start); + } + + return ret; } static int process_synthesized_event(struct perf_tool *tool, @@ -813,6 +841,33 @@ static int record__synthesize(struct record *rec, bool tail) return err; } +static void perf_event__synth_overhead(struct record *rec, perf_event__handler_t process) +{ + int cpu; + + union perf_event event = { + .overhead = { + .header = { + .type = PERF_RECORD_USER_OVERHEAD, + .size = sizeof(struct perf_overhead), + }, + }, + }; + + event.overhead.type = PERF_USER_WRITE_OVERHEAD; + + for (cpu = 0; cpu < MAX_NR_CPUS; cpu++) { + if (!rec->overhead[cpu].nr) + continue; + + event.overhead.entry.cpu = cpu; + event.overhead.entry.nr = rec->overhead[cpu].nr; + event.overhead.entry.time = rec->overhead[cpu].time; + + (void)process(&rec->tool, &event, NULL, NULL); + } +} + static int __cmd_record(struct record *rec, int argc, const char **argv) { int err; @@ -1074,6 +1129,8 @@ static int __cmd_record(struct record *rec, int argc, const char **argv) goto out_child; } + perf_event__synth_overhead(rec, process_synthesized_event); + if (!quiet) fprintf(stderr, "[ perf record: Woken up %ld times to write data ]\n", waking); diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h index 1ef1a9d..9927cf9 100644 --- a/tools/perf/util/event.h +++ b/tools/perf/util/event.h @@ -272,6 +272,9 @@ enum auxtrace_error_type { * events on each CPU. * The total number of accessing side-band events handler function is stored * in [0], while the accumulated processing time is in [1]. + * The total_user_write_overhead tells exactly the overhead to write data in + * perf record. + * The total write# is stored in [0], while the accumulated time is in [1]. */ struct events_stats { u64 total_period; @@ -283,6 +286,7 @@ struct events_stats { u64 total_nmi_overhead[MAX_NR_CPUS][2]; u64 total_mux_overhead[MAX_NR_CPUS][2]; u64 total_sb_overhead[MAX_NR_CPUS][2]; + u64 total_user_write_overhead[MAX_NR_CPUS][2]; u32 nr_events[PERF_RECORD_HEADER_MAX]; u32 nr_non_filtered_samples; u32 nr_lost_warned; @@ -493,6 +497,11 @@ struct time_conv_event { u64 time_zero; }; +enum perf_user_overhead_event_type { /* above any possible kernel type */ + PERF_USER_OVERHEAD_TYPE_START = 100, + PERF_USER_WRITE_OVERHEAD = 100, +}; + struct perf_overhead { struct perf_event_header header; u32 type; diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c index d8cde21..ce7a0ea 100644 --- a/tools/perf/util/machine.c +++ b/tools/perf/util/machine.c @@ -573,6 +573,11 @@ int machine__process_overhead_event(struct machine *machine __maybe_unused, event->overhead.entry.nr, event->overhead.entry.time, event->overhead.entry.cpu); + } else if (event->overhead.type == PERF_USER_WRITE_OVERHEAD) { + dump_printf(" User write nr: %llu time: %llu cpu %u\n", + event->overhead.entry.nr, + event->overhead.entry.time, + event->overhead.entry.cpu); } else { dump_printf("\tUNSUPPORT OVERHEAD TYPE 0x%x!\n", event->overhead.type); } diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c index 27a5c8a..a72992b 100644 --- a/tools/perf/util/session.c +++ b/tools/perf/util/session.c @@ -1227,6 +1227,10 @@ overhead_stats_update(struct perf_tool *tool, evlist->stats.total_sb_overhead[event->overhead.entry.cpu][0] += event->overhead.entry.nr; evlist->stats.total_sb_overhead[event->overhead.entry.cpu][1] += event->overhead.entry.time; break; + case PERF_USER_WRITE_OVERHEAD: + evlist->stats.total_user_write_overhead[event->overhead.entry.cpu][0] += event->overhead.entry.nr; + evlist->stats.total_user_write_overhead[event->overhead.entry.cpu][1] += event->overhead.entry.time; + break; default: break; } -- 2.5.5