Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753673AbcLBVU4 (ORCPT ); Fri, 2 Dec 2016 16:20:56 -0500 Received: from mga05.intel.com ([192.55.52.43]:13792 "EHLO mga05.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750738AbcLBVUo (ORCPT ); Fri, 2 Dec 2016 16:20:44 -0500 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.33,288,1477983600"; d="scan'208";a="1093847542" 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 V2 09/13] perf script: show kernel overhead Date: Fri, 2 Dec 2016 16:19:17 -0500 Message-Id: <1480713561-6617-10-git-send-email-kan.liang@intel.com> X-Mailer: git-send-email 2.5.5 In-Reply-To: <1480713561-6617-1-git-send-email-kan.liang@intel.com> References: <1480713561-6617-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: 6221 Lines: 175 From: Kan Liang Shows kernel overhead in perf script. The output is as below: perf script --show-profiling-cost-events perf 29001 79989.093958: 1 cycles: ffffffff81064ca6 native_write_msr (/lib/ sleep 29001 79989.094282: 7661 cycles: ffffffff810dc433 update_blocked_averages sleep 29001 79989.094294: 7442 cycles: ffffffff81810f60 irq_work_interrupt (/li sleep 29001 79989.094305: 25466 cycles: ffffffff813ca410 radix_tree_next_chunk ( sleep 29001 79989.094340: 94368 cycles: ffffffff8180fa90 page_fault (/lib/module sleep 29001 79989.094459: 167362 cycles: ffffffff811e3f79 alloc_set_pte (/lib/mod sleep 29001 79989.094672: 190283 cycles: 7f5d7c91d8e7 _dl_addr (/usr/lib64/li sleep 29001 79991.094978: 194526 cycles: ffffffff811e0579 __tlb_remove_page_size. sleep 29001 79991.095061: PERF_RECORD_OVERHEAD [SAMPLE] nr: 8 time: 28110 sleep 29001 79991.095062: PERF_RECORD_OVERHEAD [SB] nr: 24 time: 41397 Signed-off-by: Kan Liang --- tools/perf/Documentation/perf-script.txt | 3 +++ tools/perf/builtin-script.c | 32 ++++++++++++++++++++++++++++++++ tools/perf/util/event.c | 29 +++++++++++++++++++++++++++++ tools/perf/util/event.h | 1 + 4 files changed, 65 insertions(+) diff --git a/tools/perf/Documentation/perf-script.txt b/tools/perf/Documentation/perf-script.txt index c01904f..b371023 100644 --- a/tools/perf/Documentation/perf-script.txt +++ b/tools/perf/Documentation/perf-script.txt @@ -289,6 +289,9 @@ include::itrace.txt[] --force:: Don't do ownership validation. +--show-profiling-cost-events:: + Display perf profiling time cost related event (PERF_RECORD_OVERHEAD) + SEE ALSO -------- linkperf:perf-record[1], linkperf:perf-script-perl[1], diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c index e1daff3..af404a4 100644 --- a/tools/perf/builtin-script.c +++ b/tools/perf/builtin-script.c @@ -829,6 +829,7 @@ struct perf_script { bool show_task_events; bool show_mmap_events; bool show_switch_events; + bool show_profiling_cost_events; bool allocated; struct cpu_map *cpus; struct thread_map *threads; @@ -1264,6 +1265,33 @@ static int process_switch_event(struct perf_tool *tool, return 0; } +static int process_overhead_event(struct perf_tool *tool, + union perf_event *event, + struct perf_sample *sample, + struct machine *machine) +{ + struct thread *thread; + struct perf_script *script = container_of(tool, struct perf_script, tool); + struct perf_session *session = script->session; + struct perf_evsel *evsel; + + if (perf_event__process_overhead(tool, event, sample, machine) < 0) + return -1; + + evsel = perf_evlist__id2evsel(session->evlist, sample->id); + thread = machine__findnew_thread(machine, sample->pid, sample->tid); + if (thread == NULL) { + pr_debug("problem processing OVERHEAD event, skipping it.\n"); + return -1; + } + + print_sample_start(sample, thread, evsel); + perf_event__fprintf(event, stdout); + thread__put(thread); + + return 0; +} + static void sig_handler(int sig __maybe_unused) { session_done = 1; @@ -1287,6 +1315,8 @@ static int __cmd_script(struct perf_script *script) } if (script->show_switch_events) script->tool.context_switch = process_switch_event; + if (script->show_profiling_cost_events) + script->tool.overhead = process_overhead_event; ret = perf_session__process_events(script->session); @@ -2172,6 +2202,8 @@ int cmd_script(int argc, const char **argv, const char *prefix __maybe_unused) "Show the mmap events"), OPT_BOOLEAN('\0', "show-switch-events", &script.show_switch_events, "Show context switch events (if recorded)"), + OPT_BOOLEAN('\0', "show-profiling-cost-events", &script.show_profiling_cost_events, + "Show perf profiling time cost events"), OPT_BOOLEAN('f', "force", &file.force, "don't complain, do it"), OPT_BOOLEAN(0, "ns", &nanosecs, "Use 9 decimal places when displaying time"), diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c index 58d095c..e8736dc 100644 --- a/tools/perf/util/event.c +++ b/tools/perf/util/event.c @@ -1189,6 +1189,32 @@ size_t perf_event__fprintf_switch(union perf_event *event, FILE *fp) event->context_switch.next_prev_tid); } +size_t perf_event__fprintf_overhead(union perf_event *event, FILE *fp) +{ + size_t ret; + + switch (event->overhead.type) { + case PERF_PMU_SAMPLE_OVERHEAD: + ret = fprintf(fp, " [SAMPLE] nr: %llu time: %llu\n", + event->overhead.entry.nr, + event->overhead.entry.time); + break; + case PERF_CORE_MUX_OVERHEAD: + ret = fprintf(fp, " [MUX] nr: %llu time: %llu\n", + event->overhead.entry.nr, + event->overhead.entry.time); + break; + case PERF_CORE_SB_OVERHEAD: + ret = fprintf(fp, " [SB] nr: %llu time: %llu\n", + event->overhead.entry.nr, + event->overhead.entry.time); + break; + default: + ret = fprintf(fp, " unhandled!\n"); + } + return ret; +} + size_t perf_event__fprintf(union perf_event *event, FILE *fp) { size_t ret = fprintf(fp, "PERF_RECORD_%s", @@ -1218,6 +1244,9 @@ size_t perf_event__fprintf(union perf_event *event, FILE *fp) case PERF_RECORD_SWITCH_CPU_WIDE: ret += perf_event__fprintf_switch(event, fp); break; + case PERF_RECORD_OVERHEAD: + ret += perf_event__fprintf_overhead(event, fp); + break; default: ret += fprintf(fp, "\n"); } diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h index dd4ec5c..a6c98ce 100644 --- a/tools/perf/util/event.h +++ b/tools/perf/util/event.h @@ -675,6 +675,7 @@ size_t perf_event__fprintf_switch(union perf_event *event, FILE *fp); size_t perf_event__fprintf_thread_map(union perf_event *event, FILE *fp); size_t perf_event__fprintf_cpu_map(union perf_event *event, FILE *fp); size_t perf_event__fprintf(union perf_event *event, FILE *fp); +size_t perf_event__fprintf_overhead(union perf_event *event, FILE *fp); u64 kallsyms__get_function_start(const char *kallsyms_filename, const char *symbol_name); -- 2.5.5