[PATCH V2 09/13] perf script: show kernel overhead

[kan.liang@intel.com]

From: Kan Liang <kan.liang@intel.com>

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@intel.com>
---
 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