[PATCH 09/13] perf script: show kernel overhead
From: Kan Liang
Date: Mon Dec 05 2016 - 08:56:28 EST
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 <kan.liang@xxxxxxxxx>
---
tools/perf/Documentation/perf-script.txt | 3 +++
tools/perf/builtin-script.c | 36 ++++++++++++++++++++++++++++++++
tools/perf/util/event.c | 29 +++++++++++++++++++++++++
tools/perf/util/event.h | 1 +
4 files changed, 69 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..01019de 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,37 @@ 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;
+
+ /* No sample for user overhead event. Not support. */
+ if (!sample)
+ return 0;
+
+ 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 +1319,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 +2206,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