Re: Profiling sleep times?

[Arun Sharma <asharma@fb.com>]

[-- Attachment #1: Type: text/plain, Size: 1979 bytes --]

On 10/6/11 2:56 PM, Arun Sharma wrote:

> i.e. select() should be weighted by 4x vs nanosleep() as confirmed via:
>
> perf script | grep comm=foo
>
> foo 15516 [006] 2291.187831: sched_stat_sleep: comm=foo pid=15516
> delay=4054262 [ns]
> foo 15516 [006] 2291.187832: sched_stat_sleep: comm=foo pid=15516
> delay=4054262 [ns]
> foo 15516 [006] 2291.188895: sched_stat_sleep: comm=foo pid=15516
> delay=1053565 [ns]
> foo 15516 [006] 2291.188896: sched_stat_sleep: comm=foo pid=15516
> delay=1053565 [ns]
> foo 15516 [006] 2291.188897: sched_stat_sleep: comm=foo pid=15516
> delay=1053565 [ns]
>
> Andrew, are you already working on user space patches?

Attached is a quick hack (mainly meant as a RFC to get the discussion 
going).

After the patch I get the expected result:

      0.16%              foo  [unknown]          [k] 0
                        |
                        --- schedule
                           |
                           |--79.26%-- schedule_hrtimeout_range_clock
                           |          schedule_hrtimeout_range
                           |          poll_schedule_timeout
                           |          do_select
                           |          core_sys_select
                           |          sys_select
                           |          system_call_fastpath
                           |
                           |--16.87%-- do_nanosleep
                           |          hrtimer_nanosleep
                           |          sys_nanosleep
                           |          system_call_fastpath
                           |
                            --3.88%-- pipe_wait
                                      pipe_read
                                      do_sync_read
                                      vfs_read
                                      sys_read
                                      system_call_fastpath

We still have the issue that per-process profiling doesn't work.

  -Arun

[-- Attachment #2: 0001-Use-delay-instead-of-sample-period.patch --]
[-- Type: text/plain, Size: 3309 bytes --]

From a2d6e0698eebb038b2d8e845137008dc3478cc51 Mon Sep 17 00:00:00 2001
From: Arun Sharma <asharma@fb.com>
Date: Thu, 6 Oct 2011 16:48:44 -0700
Subject: [PATCH] Use delay instead of sample->period

---
 tools/perf/builtin-report.c         |    6 ++++++
 tools/perf/util/probe-finder.c      |    6 ++++--
 tools/perf/util/trace-event-parse.c |   20 ++++++++++++++++++++
 tools/perf/util/trace-event.h       |    1 +
 4 files changed, 31 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index d7ff277..6821597 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -25,6 +25,7 @@
 #include "util/evsel.h"
 #include "util/header.h"
 #include "util/session.h"
+#include "util/trace-event.h"
 
 #include "util/parse-options.h"
 #include "util/parse-events.h"
@@ -111,6 +112,11 @@ static int process_sample_event(union perf_event *event,
 				struct perf_session *session)
 {
 	struct addr_location al;
+	struct perf_event_attr *attr = &evsel->attr;
+              
+	if (attr->type == PERF_TYPE_TRACEPOINT) { 
+		sample->period = trace_get_delay(sample->raw_data, sample->raw_size);
+	}
 
 	if (perf_event__preprocess_sample(event, session, &al, sample,
 					  annotate_init) < 0) {
diff --git a/tools/perf/util/probe-finder.c b/tools/perf/util/probe-finder.c
index 5d73262..e7179ff 100644
--- a/tools/perf/util/probe-finder.c
+++ b/tools/perf/util/probe-finder.c
@@ -19,9 +19,11 @@
  *
  */
 
+#define _GNU_SOURCE
 #include <sys/utsname.h>
 #include <sys/types.h>
 #include <sys/stat.h>
+#include <ctype.h>
 #include <fcntl.h>
 #include <errno.h>
 #include <stdio.h>
@@ -30,13 +32,13 @@
 #include <stdlib.h>
 #include <string.h>
 #include <stdarg.h>
-#include <ctype.h>
 #include <dwarf-regs.h>
+#undef _GNU_SOURCE
 
 #include <linux/bitops.h>
+#include "util.h"
 #include "event.h"
 #include "debug.h"
-#include "util.h"
 #include "symbol.h"
 #include "probe-finder.h"
 
diff --git a/tools/perf/util/trace-event-parse.c b/tools/perf/util/trace-event-parse.c
index 0a7ed5b..78b7194 100644
--- a/tools/perf/util/trace-event-parse.c
+++ b/tools/perf/util/trace-event-parse.c
@@ -2944,6 +2944,26 @@ void print_trace_event(int cpu, void *data, int size)
 	pretty_print(data, size, event);
 }
 
+size_t trace_get_delay(void *data, int size __unused)
+{
+	struct event *event;
+	int type;
+	struct format_field *field;
+
+	type = trace_parse_common_type(data);
+
+	event = trace_find_event(type);
+	if (!event) {
+		warning("ug! no event found for type %d", type);
+		return 0;
+	}
+
+	field = find_field(event, "delay");
+	if (!field)
+		die("can't find delay field in trace");
+	return read_size(data + field->offset, field->size);
+}
+
 static void print_fields(struct print_flag_sym *field)
 {
 	printf("{ %s, %s }", field->value, field->str);
diff --git a/tools/perf/util/trace-event.h b/tools/perf/util/trace-event.h
index f674dda..587b553 100644
--- a/tools/perf/util/trace-event.h
+++ b/tools/perf/util/trace-event.h
@@ -264,6 +264,7 @@ unsigned long long eval_flag(const char *flag);
 
 int read_tracing_data(int fd, struct list_head *pattrs);
 ssize_t read_tracing_data_size(int fd, struct list_head *pattrs);
+size_t trace_get_delay(void *data, int size);
 
 /* taken from kernel/trace/trace.h */
 enum trace_flag_type {
-- 
1.7.4