[PATCH 0/4] Profiling sleep times

[PATCH 0/4] Profiling sleep times

[Andrew Vagin]

The problem is that events sched_stat_* contain call-chains of
non-target tasks.
About month ago I sent series of patches:

[PATCH 0/3] trace: add ability to collect call chains of non current task.

Peter and Frederic explained me, that this solve isn't good and will be
better to make it in userspace.

Now it's in userspace. This series expands "perf inject" to be able to
merge sched_switch events and sched_stat* events. sched_switch events
contain correct call-chains and sched_stat contains a correct time
slices.

Known issues:
Now some samples may be lost due to throttling. The number of samples is
restricted by sysctl_perf_event_sample_rate/HZ.  A trace event is divided on
some samples according to event's period.  I don't sure, that we should
generate more than one sample on each trace event. I think the better way to
use SAMPLE_PERIOD and now I think in this direction.
This problem isn't in my patches, so you can review it, while I'm working on
this issue.

Andrew Vagin:
  perf: teach "perf inject" to work with files
  perf: teach perf inject to merge sched_stat_* and sched_switch events
  perf: add scripts for profiling sleep times

 tools/perf/builtin-inject.c                     |  120 ++++++++++++++++++++++-
 tools/perf/scripts/python/bin/sched-stat-record |    2 +
 tools/perf/scripts/python/bin/sched-stat-report |    6 +
 3 files changed, 126 insertions(+), 2 deletions(-)
 create mode 100644 tools/perf/scripts/python/bin/sched-stat-record
 create mode 100644 tools/perf/scripts/python/bin/sched-stat-report

[PATCH 1/4] perf: use event_name() to get an event name

[Andrew Vagin]

perf_evsel.name may be not initialized

Signed-off-by: Andrew Vagin <avagin@openvz.org>
---
 tools/perf/util/header.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/tools/perf/util/header.c b/tools/perf/util/header.c
index 76c0b2c..95ea64d 100644
--- a/tools/perf/util/header.c
+++ b/tools/perf/util/header.c
@@ -388,7 +388,7 @@ static int write_event_desc(int fd, struct perf_header *h __used,
 		/*
 		 * write event string as passed on cmdline
 		 */
-		ret = do_write_string(fd, attr->name);
+		ret = do_write_string(fd, event_name(attr));
 		if (ret < 0)
 			return ret;
 		/*
-- 
1.7.1

[PATCH 2/4] perf: teach "perf inject" to work with files

[Andrew Vagin]

Before this patch "perf inject" can only handle data from pipe.

I want to use "perf inject" for reworking events. Look at my following patch.

Signed-off-by: Andrew Vagin <avagin@openvz.org>
---
 tools/perf/builtin-inject.c |   33 +++++++++++++++++++++++++++++++--
 1 files changed, 31 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-inject.c b/tools/perf/builtin-inject.c
index 8dfc12b..8df8b71 100644
--- a/tools/perf/builtin-inject.c
+++ b/tools/perf/builtin-inject.c
@@ -13,7 +13,12 @@
 
 #include "util/parse-options.h"
 
-static char		const *input_name = "-";
+static char		const *input_name	= "-";
+static const char	*output_name		= "-";
+static int		pipe_output		= 0;
+static int		output;
+static u64		bytes_written		= 0;
+
 static bool		inject_build_ids;
 
 static int perf_event__repipe_synth(union perf_event *event,
@@ -25,12 +30,14 @@ static int perf_event__repipe_synth(union perf_event *event,
 	size = event->header.size;
 
 	while (size) {
-		int ret = write(STDOUT_FILENO, buf, size);
+		int ret = write(output, buf, size);
 		if (ret < 0)
 			return -errno;
 
 		size -= ret;
 		buf += ret;
+
+		bytes_written += ret;
 	}
 
 	return 0;
@@ -213,8 +220,14 @@ static int __cmd_inject(void)
 	if (session == NULL)
 		return -ENOMEM;
 
+	if (!pipe_output)
+		lseek(output, session->header.data_offset, SEEK_SET);
 	ret = perf_session__process_events(session, &inject_ops);
 
+	if (!pipe_output) {
+		session->header.data_size += bytes_written;
+		perf_session__write_header(session, session->evlist, output, true);
+	}
 	perf_session__delete(session);
 
 	return ret;
@@ -228,6 +241,10 @@ static const char * const report_usage[] = {
 static const struct option options[] = {
 	OPT_BOOLEAN('b', "build-ids", &inject_build_ids,
 		    "Inject build-ids into the output stream"),
+	OPT_STRING('i', "input", &input_name, "file",
+		    "input file name"),
+	OPT_STRING('o', "output", &output_name, "file",
+		    "output file name"),
 	OPT_INCR('v', "verbose", &verbose,
 		 "be more verbose (show build ids, etc)"),
 	OPT_END()
@@ -243,6 +260,18 @@ int cmd_inject(int argc, const char **argv, const char *prefix __used)
 	if (argc)
 		usage_with_options(report_usage, options);
 
+	if (!strcmp(output_name, "-")) {
+		pipe_output = 1;
+		output = STDOUT_FILENO;
+	} else {
+		output = open(output_name, O_CREAT| O_WRONLY | O_TRUNC,
+							S_IRUSR | S_IWUSR);
+		if (output < 0) {
+			perror("failed to create output file");
+			exit(-1);
+		}
+	}
+
 	if (symbol__init() < 0)
 		return -1;
 
-- 
1.7.1

[PATCH 3/4] perf: teach perf inject to merge sched_stat_* and sched_switch events

[Andrew Vagin]

You may want to know where and how long a task is sleeping. A callchain
may be found in sched_switch and a time slice in stat_iowait, so I add
handler in perf inject for merging this events.

My code saves sched_switch event for each process and when it meets
stat_iowait, it reports the sched_switch event, because this event
contains a correct callchain. By another words it replaces all
stat_iowait events on proper sched_switch events.

Signed-off-by: Andrew Vagin <avagin@openvz.org>
---
 tools/perf/builtin-inject.c |   85 +++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 85 insertions(+), 0 deletions(-)

diff --git a/tools/perf/builtin-inject.c b/tools/perf/builtin-inject.c
index 8df8b71..fd1e4e4 100644
--- a/tools/perf/builtin-inject.c
+++ b/tools/perf/builtin-inject.c
@@ -12,6 +12,8 @@
 #include "util/debug.h"
 
 #include "util/parse-options.h"
+#include "util/trace-event.h"
+
 
 static char		const *input_name	= "-";
 static const char	*output_name		= "-";
@@ -20,6 +22,7 @@ static int		output;
 static u64		bytes_written		= 0;
 
 static bool		inject_build_ids;
+static bool		inject_sched_stat;
 
 static int perf_event__repipe_synth(union perf_event *event,
 				    struct perf_session *session __used)
@@ -179,6 +182,83 @@ repipe:
 	return 0;
 }
 
+struct event_entry
+{
+	struct list_head list;
+	u32 pid;
+	char header[0];
+};
+
+static LIST_HEAD(samples);
+
+static int perf_event__sched_stat(union perf_event *event,
+				      struct perf_sample *sample,
+				      struct perf_evsel *evsel __used,
+				      struct perf_session *session)
+{
+	int type;
+	struct event *e;
+	const char *evname = NULL;
+	uint32_t size;
+	void *buf = event;
+	struct event_entry *ent;
+	union perf_event *event_sw = NULL;
+	struct perf_sample sample_sw;
+	int sched_process_exit;
+
+	size = event->header.size;
+
+	type = trace_parse_common_type(sample->raw_data);
+	e = trace_find_event(type);
+	if (e)
+		evname = e->name;
+
+	sched_process_exit = !strcmp(evname, "sched_process_exit");
+
+	if (!strcmp(evname, "sched_switch") ||  sched_process_exit) {
+		list_for_each_entry(ent, &samples, list)
+			if (sample->pid == ent->pid)
+				break;
+
+		if (&ent->list != &samples) {
+			list_del(&ent->list);
+			free(ent);
+		}
+
+		if (sched_process_exit)
+			return 0;
+
+		ent = malloc(size + sizeof(struct event_entry));
+		ent->pid = sample->pid;
+		memcpy(&ent->header, buf, size);
+		list_add(&ent->list, &samples);
+		return 0;
+
+	} else if (!strncmp(evname, "sched_stat_", 11)) {
+		u32 pid;
+
+		pid = raw_field_value(e, "pid", sample->raw_data);
+
+		list_for_each_entry(ent, &samples, list) {
+			if (pid == ent->pid)
+				break;
+		}
+
+		if (&ent->list == &samples) {
+			pr_warning("Could not find sched_switch for pid %u\n", pid);
+			return 0;
+		}
+
+		event_sw = (union perf_event *) &ent->header;
+		perf_session__parse_sample(session, event_sw, &sample_sw);
+		perf_event__repipe(event_sw, &sample_sw, session);
+		return 0;
+	}
+
+	perf_event__repipe(event, sample, session);
+
+	return 0;
+}
 struct perf_event_ops inject_ops = {
 	.sample		= perf_event__repipe_sample,
 	.mmap		= perf_event__repipe,
@@ -214,6 +294,9 @@ static int __cmd_inject(void)
 		inject_ops.mmap		= perf_event__repipe_mmap;
 		inject_ops.fork		= perf_event__repipe_task;
 		inject_ops.tracing_data	= perf_event__repipe_tracing_data;
+	} else if (inject_sched_stat) {
+		inject_ops.sample	= perf_event__sched_stat;
+		inject_ops.ordered_samples = true;
 	}
 
 	session = perf_session__new(input_name, O_RDONLY, false, true, &inject_ops);
@@ -241,6 +324,8 @@ static const char * const report_usage[] = {
 static const struct option options[] = {
 	OPT_BOOLEAN('b', "build-ids", &inject_build_ids,
 		    "Inject build-ids into the output stream"),
+	OPT_BOOLEAN('s', "sched-stat", &inject_sched_stat,
+		    "correct call-chains for shed-stat-*"),
 	OPT_STRING('i', "input", &input_name, "file",
 		    "input file name"),
 	OPT_STRING('o', "output", &output_name, "file",
-- 
1.7.1

[PATCH 4/4] perf: add scripts for profiling sleep times

[Andrew Vagin]

E.g.:
 # ./perf script record sched-stat -- -e sched:sched_stat_sleep &
 # ./foo;
 # killall -SIGINT perf
 ./perf script report sched-stat

Signed-off-by: Andrew Vagin <avagin@openvz.org>
---
 tools/perf/scripts/python/bin/sched-stat-record |    2 ++
 tools/perf/scripts/python/bin/sched-stat-report |    6 ++++++
 2 files changed, 8 insertions(+), 0 deletions(-)
 create mode 100644 tools/perf/scripts/python/bin/sched-stat-record
 create mode 100644 tools/perf/scripts/python/bin/sched-stat-report

diff --git a/tools/perf/scripts/python/bin/sched-stat-record b/tools/perf/scripts/python/bin/sched-stat-record
new file mode 100644
index 0000000..b9873d9
--- /dev/null
+++ b/tools/perf/scripts/python/bin/sched-stat-record
@@ -0,0 +1,2 @@
+#!/bin/bash
+perf record -ag -e sched:sched_switch --filter "prev_state == 1 || prev_state == 2" -e sched:sched_process_exit ${@/--/}
diff --git a/tools/perf/scripts/python/bin/sched-stat-report b/tools/perf/scripts/python/bin/sched-stat-report
new file mode 100644
index 0000000..d225a37
--- /dev/null
+++ b/tools/perf/scripts/python/bin/sched-stat-report
@@ -0,0 +1,6 @@
+#!/bin/bash
+# description: profiling sleep times
+# args: -e sched:sched_stat_[smth]
+perf inject -s -i perf.data -o perf.data.d || exit
+perf report -i perf.data.d || exit
+unlink perf.data.d
-- 
1.7.1

Re: [PATCH 4/4] perf: add scripts for profiling sleep times

[Arun Sharma]

On 11/2/11 3:59 PM, Andrew Vagin wrote:
> +perf record -ag -e sched:sched_switch --filter "prev_state == 1 || prev_state == 2" -e sched:sched_process_exit ${@/--/}

Like I said on the other thread: it'd be good to have this feature 
available to normal users without requiring root or
perf_event_paranoid <= 0.

But having it available to root users would be a good first step. Thanks 
for doing this work.

  -Arun

Re: [PATCH 3/4] perf: teach perf inject to merge sched_stat_* and sched_switch events

[Arun Sharma]

On 11/2/11 3:59 PM, Andrew Vagin wrote:

> +		event_sw = (union perf_event *)&ent->header;

This causes problems with -Wstrict-aliasing=3.

I noticed that the suggested cmdline is:

perf script record sched-stat -- -e sched:sched_stat_sleep

I'd much prefer something along the lines of:

perf script record sched-stat -e <events> -- sleep 1

Also, the perf inject command is a bit unforgiving when the user makes 
some mistakes (eg: didn't specify -e sched:sched_stat_sleep). The 
failure mode is hard to understand (perf report -i perf.data.d fails 
with "no samples").

Doing it directly:

# perf record -ag -e sched:sched_switch --filter "prev_state == 1 || 
prev_state == 2" -e 
sched:sched_process_exit,sched:sched_stat_sleep,sched:sched_stat_iowait 
-- sleep 1
# perf inject -v -s -i perf.data -o perf.data.d

results in a whole bunch of:

Could not find sched_switch for pid 16188
Could not find sched_switch for pid 16212
Could not find sched_switch for pid 1500
Could not find sched_switch for pid 16195
Could not find sched_switch for pid 16179

I think this is the same issue you referenced in "Known issues".

Although I'm able to get some profiling info out of perf.data.d, the 
process I really wanted to trace got zero samples.

  -Arun

Re: [PATCH 3/4] perf: teach perf inject to merge sched_stat_* and sched_switch events

[Andrew Vagin]

Hi Arun,

On 11/04/2011 04:08 AM, Arun Sharma wrote:
> On 11/2/11 3:59 PM, Andrew Vagin wrote:
>
>> + event_sw = (union perf_event *)&ent->header;
>
> This causes problems with -Wstrict-aliasing=3.
I didn't see any warning, but I reworked this part a bit.
>
> I noticed that the suggested cmdline is:
>
> perf script record sched-stat -- -e sched:sched_stat_sleep
>
> I'd much prefer something along the lines of:
>
> perf script record sched-stat -e <events> -- sleep 1
>
> Also, the perf inject command is a bit unforgiving when the user makes
> some mistakes (eg: didn't specify -e sched:sched_stat_sleep). The
> failure mode is hard to understand (perf report -i perf.data.d fails
> with "no samples").

I see the problem. It's not in "perf inject". Look at new version I 
improved "perf script sched_stat". Now it may be executed for specific 
command and it reports an error if you forgot to set a sched_stat_* event.

> Could not find sched_switch for pid 16179
>
> I think this is the same issue you referenced in "Known issues".
Actually It isn't. Now I print this message as debug information.
>
> Although I'm able to get some profiling info out of perf.data.d, the
> process I really wanted to trace got zero samples.
It's strange. Can you check new versions and describe the experiment if 
it will be reproduces.
>
> -Arun
>