[PATCH 0/7] Profiling sleep times (v2)

[PATCH 0/7] Profiling sleep times (v2)

[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.

v2:
* Removed all known issues. Now it works completely.
* Improved usability of sched-stat scripts according with Arun's comments.

Andrew Vagin (7):
  perf: use event_name() to get an event name
  event: don't divide events if it has field period
  perf: add ability to record event period
  perf: add ability to change event according to sample
  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

 kernel/events/core.c                            |    7 +-
 tools/perf/builtin-inject.c                     |  120 ++++++++++++++++++++++-
 tools/perf/builtin-record.c                     |    5 +
 tools/perf/scripts/python/bin/sched-stat-record |   65 ++++++++++++
 tools/perf/scripts/python/bin/sched-stat-report |    5 +
 tools/perf/util/event.h                         |    2 +
 tools/perf/util/evsel.c                         |   74 ++++++++++++++
 tools/perf/util/header.c                        |    2 +-
 tools/perf/util/session.h                       |    9 ++
 9 files changed, 285 insertions(+), 4 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/7] 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/7] event: don't divide events if it has field period

[Andrew Vagin]

This patch solves the following problem:

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.

E.g.: I want to trace when a process sleeps. I created a process, which
sleeps for 1ms and for 4ms.  perf got 100 events in both cases.

swapper     0 [000]  1141.371830: sched_stat_sleep: comm=foo pid=1801 delay=1386750 [ns]
swapper     0 [000]  1141.369444: sched_stat_sleep: comm=foo pid=1801 delay=4499585 [ns]

In the first case a kernel want to send 4499585 events and
in the second case it wants to send 1386750 events.
perf-reports shows that process sleeps in both places equal time. It's
bug.

With this patch kernel generates one event on each "sleep" and the time
slice is saved in the field "period". Perf know how handle it.

Signed-off-by: Andrew Vagin <avagin@openvz.org>
---
 kernel/events/core.c |    7 ++++++-
 1 files changed, 6 insertions(+), 1 deletions(-)

diff --git a/kernel/events/core.c b/kernel/events/core.c
index 12a0287..298702d 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -4737,7 +4737,6 @@ static void perf_swevent_overflow(struct perf_event *event, u64 overflow,
 	struct hw_perf_event *hwc = &event->hw;
 	int throttle = 0;
 
-	data->period = event->hw.last_period;
 	if (!overflow)
 		overflow = perf_swevent_set_period(event);
 
@@ -4771,6 +4770,12 @@ static void perf_swevent_event(struct perf_event *event, u64 nr,
 	if (!is_sampling_event(event))
 		return;
 
+	if (event->attr.sample_type & PERF_SAMPLE_PERIOD && !event->attr.freq) {
+		data->period = nr;
+		return perf_swevent_overflow(event, 1, data, regs);
+	} else
+		data->period = event->hw.last_period;
+
 	if (nr == 1 && hwc->sample_period == 1 && !event->attr.freq)
 		return perf_swevent_overflow(event, 1, data, regs);
 
-- 
1.7.1

Re: [PATCH 2/7] event: don't divide events if it has field period

[Peter Zijlstra]

On Mon, 2011-11-07 at 15:54 +0300, Andrew Vagin wrote:
> This patch solves the following problem:
> 
> 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.

It would be yes, but this code predates that, also it needs to work even
if the user doesn't provide SAMPLE_PERIOD.

> E.g.: I want to trace when a process sleeps. I created a process, which
> sleeps for 1ms and for 4ms.  perf got 100 events in both cases.
> 
> swapper     0 [000]  1141.371830: sched_stat_sleep: comm=foo pid=1801 delay=1386750 [ns]
> swapper     0 [000]  1141.369444: sched_stat_sleep: comm=foo pid=1801 delay=4499585 [ns]
> 
> In the first case a kernel want to send 4499585 events and
> in the second case it wants to send 1386750 events.
> perf-reports shows that process sleeps in both places equal time. It's
> bug.
> 
> With this patch kernel generates one event on each "sleep" and the time
> slice is saved in the field "period". Perf know how handle it.

Yeah, looks about right, would be awesome if we could strip some
branches out, but nothing obvious comes to mind.

> Signed-off-by: Andrew Vagin <avagin@openvz.org>
> ---
>  kernel/events/core.c |    7 ++++++-
>  1 files changed, 6 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/events/core.c b/kernel/events/core.c
> index 12a0287..298702d 100644
> --- a/kernel/events/core.c
> +++ b/kernel/events/core.c
> @@ -4737,7 +4737,6 @@ static void perf_swevent_overflow(struct perf_event *event, u64 overflow,
>  	struct hw_perf_event *hwc = &event->hw;
>  	int throttle = 0;
>  
> -	data->period = event->hw.last_period;
>  	if (!overflow)
>  		overflow = perf_swevent_set_period(event);
>  
> @@ -4771,6 +4770,12 @@ static void perf_swevent_event(struct perf_event *event, u64 nr,
>  	if (!is_sampling_event(event))
>  		return;
>  
> +	if (event->attr.sample_type & PERF_SAMPLE_PERIOD && !event->attr.freq) {
> +		data->period = nr;
> +		return perf_swevent_overflow(event, 1, data, regs);
> +	} else
> +		data->period = event->hw.last_period;
> +
>  	if (nr == 1 && hwc->sample_period == 1 && !event->attr.freq)
>  		return perf_swevent_overflow(event, 1, data, regs);
>  

Re: [PATCH 2/7] event: don't divide events if it has field period

[Andrew Vagin]

On 11/09/2011 03:55 PM, Peter Zijlstra wrote:
> On Mon, 2011-11-07 at 15:54 +0300, Andrew Vagin wrote:
>> This patch solves the following problem:
>>
>> 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.
> It would be yes, but this code predates that, also it needs to work even
> if the user doesn't provide SAMPLE_PERIOD.

Actually it's another task. Your task requires more time to think over. 
It would be good, if someone will suggest me a good use case for this 
scenario.
My code works well and I think we should have this functional in the kernel.

When I think how to fix working without SAMPLE_PERIOD, only one idea is 
appeared, it's adjusting of a sample period. In this case we will have 
many other questions. E.g.:
1. When a sample period should be adjusted. Do we need a warm up load?
2. If we adjust a sample period during measuring load, how will we 
compare samples before and after adjustments. We can send an event, that 
a sample period has been adjusted.

>> E.g.: I want to trace when a process sleeps. I created a process, which
>> sleeps for 1ms and for 4ms.  perf got 100 events in both cases.
>>
>> swapper     0 [000]  1141.371830: sched_stat_sleep: comm=foo pid=1801 delay=1386750 [ns]
>> swapper     0 [000]  1141.369444: sched_stat_sleep: comm=foo pid=1801 delay=4499585 [ns]
>>
>> In the first case a kernel want to send 4499585 events and
>> in the second case it wants to send 1386750 events.
>> perf-reports shows that process sleeps in both places equal time. It's
>> bug.
>>
>> With this patch kernel generates one event on each "sleep" and the time
>> slice is saved in the field "period". Perf know how handle it.
> Yeah, looks about right, would be awesome if we could strip some
> branches out, but nothing obvious comes to mind.
>
>> Signed-off-by: Andrew Vagin<avagin@openvz.org>
>> ---
>>   kernel/events/core.c |    7 ++++++-
>>   1 files changed, 6 insertions(+), 1 deletions(-)
>>
>> diff --git a/kernel/events/core.c b/kernel/events/core.c
>> index 12a0287..298702d 100644
>> --- a/kernel/events/core.c
>> +++ b/kernel/events/core.c
>> @@ -4737,7 +4737,6 @@ static void perf_swevent_overflow(struct perf_event *event, u64 overflow,
>>   	struct hw_perf_event *hwc =&event->hw;
>>   	int throttle = 0;
>>
>> -	data->period = event->hw.last_period;
>>   	if (!overflow)
>>   		overflow = perf_swevent_set_period(event);
>>
>> @@ -4771,6 +4770,12 @@ static void perf_swevent_event(struct perf_event *event, u64 nr,
>>   	if (!is_sampling_event(event))
>>   		return;
>>
>> +	if (event->attr.sample_type&  PERF_SAMPLE_PERIOD&&  !event->attr.freq) {
>> +		data->period = nr;
>> +		return perf_swevent_overflow(event, 1, data, regs);
>> +	} else
>> +		data->period = event->hw.last_period;
>> +
>>   	if (nr == 1&&  hwc->sample_period == 1&&  !event->attr.freq)
>>   		return perf_swevent_overflow(event, 1, data, regs);
>>

Re: [PATCH 2/7] event: don't divide events if it has field period

[Andrew Wagin]

Hello Peter,

11 ноября 2011 г. 13:54 пользователь Andrew Vagin <avagin@gmail.com> написал:
> On 11/09/2011 03:55 PM, Peter Zijlstra wrote:
>>
>> On Mon, 2011-11-07 at 15:54 +0300, Andrew Vagin wrote:
>>>
>>> This patch solves the following problem:
>>>
>>> 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.
>>
>> It would be yes, but this code predates that, also it needs to work even
>> if the user doesn't provide SAMPLE_PERIOD.

I have not understood exactly what I should do now.
I'm going to send the third version of this patches. New version
contains only a small fix according with the comment for path 4/7.
In new version I am not going to fix the problem about which we
discussed early. I have some reasons for it:

*  It's another task. My decision is more effective for my task and  I
believe that exists many cases where my decision may be suitable. I
want to say, that it may be in kernel, event if the problem would not
exist at all.
* __perf_count() has been broken for a long time and nobody reports
this problem, so we can say, that the problem isn't urgent.
* Only few events sched:sched_stat_* are affected by this problem.
* I am not sure, that we should to solve this problem. The "problem"
may be not a problem at all. We have ability to customize
sample_period and we have events about that some events were
throttled.

If you have any objection, send them to me.

Re: [PATCH 2/7] event: don't divide events if it has field period

[Peter Zijlstra]

On Thu, 2011-11-17 at 11:22 +0300, Andrew Wagin wrote:
> Hello Peter,
> 
> 11 ноября 2011 г. 13:54 пользователь Andrew Vagin <avagin@gmail.com> написал:
> > On 11/09/2011 03:55 PM, Peter Zijlstra wrote:
> >>
> >> On Mon, 2011-11-07 at 15:54 +0300, Andrew Vagin wrote:
> >>>
> >>> This patch solves the following problem:
> >>>
> >>> 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.
> >>
> >> It would be yes, but this code predates that, also it needs to work even
> >> if the user doesn't provide SAMPLE_PERIOD.
> 
> I have not understood exactly what I should do now.
> I'm going to send the third version of this patches. New version
> contains only a small fix according with the comment for path 4/7.
> In new version I am not going to fix the problem about which we
> discussed early. I have some reasons for it:

I already merged your previous version, it can be found in tip.

[tip:perf/core] events: Don't divide events if it has field period

[tip-bot for Andrew Vagin]

Commit-ID:  5d81e5cfb37a174e8ddc0413e2e70cdf05807ace
Gitweb:     http://git.kernel.org/tip/5d81e5cfb37a174e8ddc0413e2e70cdf05807ace
Author:     Andrew Vagin <avagin@openvz.org>
AuthorDate: Mon, 7 Nov 2011 15:54:12 +0300
Committer:  Ingo Molnar <mingo@elte.hu>
CommitDate: Mon, 14 Nov 2011 13:31:28 +0100

events: Don't divide events if it has field period

This patch solves the following problem:

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.

E.g.: I want to trace when a process sleeps. I created a process, which
sleeps for 1ms and for 4ms.  perf got 100 events in both cases.

swapper     0 [000]  1141.371830: sched_stat_sleep: comm=foo pid=1801 delay=1386750 [ns]
swapper     0 [000]  1141.369444: sched_stat_sleep: comm=foo pid=1801 delay=4499585 [ns]

In the first case a kernel want to send 4499585 events and
in the second case it wants to send 1386750 events.
perf-reports shows that process sleeps in both places equal time. It's
bug.

With this patch kernel generates one event on each "sleep" and the time
slice is saved in the field "period". Perf knows how handle it.

Signed-off-by: Andrew Vagin <avagin@openvz.org>
Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
Link: http://lkml.kernel.org/r/1320670457-2633428-3-git-send-email-avagin@openvz.org
Signed-off-by: Ingo Molnar <mingo@elte.hu>
---
 kernel/events/core.c |    7 ++++++-
 1 files changed, 6 insertions(+), 1 deletions(-)

diff --git a/kernel/events/core.c b/kernel/events/core.c
index eadac69..8d9dea5 100644
--- a/kernel/events/core.c
+++ b/kernel/events/core.c
@@ -4528,7 +4528,6 @@ static void perf_swevent_overflow(struct perf_event *event, u64 overflow,
 	struct hw_perf_event *hwc = &event->hw;
 	int throttle = 0;
 
-	data->period = event->hw.last_period;
 	if (!overflow)
 		overflow = perf_swevent_set_period(event);
 
@@ -4562,6 +4561,12 @@ static void perf_swevent_event(struct perf_event *event, u64 nr,
 	if (!is_sampling_event(event))
 		return;
 
+	if ((event->attr.sample_type & PERF_SAMPLE_PERIOD) && !event->attr.freq) {
+		data->period = nr;
+		return perf_swevent_overflow(event, 1, data, regs);
+	} else
+		data->period = event->hw.last_period;
+
 	if (nr == 1 && hwc->sample_period == 1 && !event->attr.freq)
 		return perf_swevent_overflow(event, 1, data, regs);
 

[PATCH 3/7] perf: add ability to record event period

[Andrew Vagin]

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

diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index f82480f..b62701a 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -62,6 +62,7 @@ static bool			no_samples			=  false;
 static bool			sample_address			=  false;
 static bool			sample_time			=  false;
 static bool			no_buildid			=  false;
+static bool			period				=  false;
 static bool			no_buildid_cache		=  false;
 static struct perf_evlist	*evsel_list;
 
@@ -185,6 +186,9 @@ static void config_attr(struct perf_evsel *evsel, struct perf_evlist *evlist)
 	if (evlist->nr_entries > 1)
 		attr->sample_type |= PERF_SAMPLE_ID;
 
+	if (period)
+		attr->sample_type |= PERF_SAMPLE_PERIOD;
+
 	/*
 	 * We default some events to a 1 default interval. But keep
 	 * it a weak assumption overridable by the user.
@@ -796,6 +800,7 @@ const struct option record_options[] = {
 	OPT_BOOLEAN('d', "data", &sample_address,
 		    "Sample addresses"),
 	OPT_BOOLEAN('T', "timestamp", &sample_time, "Sample timestamps"),
+	OPT_BOOLEAN('P', "period", &period, "Sample period"),
 	OPT_BOOLEAN('n', "no-samples", &no_samples,
 		    "don't sample"),
 	OPT_BOOLEAN('N', "no-buildid-cache", &no_buildid_cache,
-- 
1.7.1

[PATCH 4/7] perf: add ability to change event according to sample

[Andrew Vagin]

It's opposition of perf_session__parse_sample.

Signed-off-by: Andrew Vagin <avagin@openvz.org>
---
 tools/perf/util/event.h   |    2 +
 tools/perf/util/evsel.c   |   74 +++++++++++++++++++++++++++++++++++++++++++++
 tools/perf/util/session.h |    9 +++++
 3 files changed, 85 insertions(+), 0 deletions(-)

diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
index 357a85b..0493101 100644
--- a/tools/perf/util/event.h
+++ b/tools/perf/util/event.h
@@ -187,5 +187,7 @@ const char *perf_event__name(unsigned int id);
 int perf_event__parse_sample(const union perf_event *event, u64 type,
 			     int sample_size, bool sample_id_all,
 			     struct perf_sample *sample, bool swapped);
+int perf_event__change_sample(union perf_event *event, u64 type,
+			     const struct perf_sample *data, bool swapped);
 
 #endif /* __PERF_RECORD_H */
diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
index b46f6e4..9274e08 100644
--- a/tools/perf/util/evsel.c
+++ b/tools/perf/util/evsel.c
@@ -475,3 +475,77 @@ int perf_event__parse_sample(const union perf_event *event, u64 type,
 
 	return 0;
 }
+
+int perf_event__change_sample(union perf_event *event, u64 type,
+			     const struct perf_sample *data, bool swapped)
+{
+	u64 *array;
+
+	/*
+	 * used for cross-endian analysis. See git commit 65014ab3
+	 * for why this goofiness is needed.
+	 */
+	union {
+		u64 val64;
+		u32 val32[2];
+	} u;
+
+	array = event->sample.array;
+
+	if (type & PERF_SAMPLE_IP) {
+		event->ip.ip = data->ip;
+		array++;
+	}
+
+	if (type & PERF_SAMPLE_TID) {
+		u.val32[0] = data->pid;
+		u.val32[1] = data->tid;
+		if (swapped) {
+			/* undo swap of u64, then swap on individual u32s */
+			u.val64 = bswap_64(u.val64);
+			u.val32[0] = bswap_32(u.val32[0]);
+			u.val32[1] = bswap_32(u.val32[1]);
+		}
+
+		*array = u.val64;
+		array++;
+	}
+
+	if (type & PERF_SAMPLE_TIME) {
+		*array = data->time;
+		array++;
+	}
+
+	if (type & PERF_SAMPLE_ADDR) {
+		*array = data->addr;
+		array++;
+	}
+
+	if (type & PERF_SAMPLE_ID) {
+		*array = data->id;
+		array++;
+	}
+
+	if (type & PERF_SAMPLE_STREAM_ID) {
+		*array = data->stream_id;
+		array++;
+	}
+
+	if (type & PERF_SAMPLE_CPU) {
+		u.val32[0] = data->cpu;
+		if (swapped) {
+			/* undo swap of u64, then swap on individual u32s */
+			u.val64 = bswap_64(u.val64);
+			u.val32[0] = bswap_32(u.val32[0]);
+		}
+		*array = u.val64;
+		array++;
+	}
+
+	if (type & PERF_SAMPLE_PERIOD) {
+		*array = data->period;
+		array++;
+	}
+
+	return 0;
+}
diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
index 514b06d..5a36d10 100644
--- a/tools/perf/util/session.h
+++ b/tools/perf/util/session.h
@@ -166,6 +166,15 @@ static inline int perf_session__parse_sample(struct perf_session *session,
 					session->header.needs_swap);
 }
 
+static inline int perf_session__change_sample(struct perf_session *session,
+					     union perf_event *event,
+					     const struct perf_sample *sample)
+{
+	return perf_event__change_sample(event, session->sample_type,
+					sample,
+					session->header.needs_swap);
+}
+
 struct perf_evsel *perf_session__find_first_evtype(struct perf_session *session,
 					    unsigned int type);
 
-- 
1.7.1

Re: [PATCH 4/7] perf: add ability to change event according to sample

[David Ahern]

On 11/07/2011 05:54 AM, Andrew Vagin wrote:
> It's opposition of perf_session__parse_sample.
> 
> Signed-off-by: Andrew Vagin <avagin@openvz.org>
> ---
>  tools/perf/util/event.h   |    2 +
>  tools/perf/util/evsel.c   |   74 +++++++++++++++++++++++++++++++++++++++++++++
>  tools/perf/util/session.h |    9 +++++
>  3 files changed, 85 insertions(+), 0 deletions(-)
> 
> diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
> index 357a85b..0493101 100644
> --- a/tools/perf/util/event.h
> +++ b/tools/perf/util/event.h
> @@ -187,5 +187,7 @@ const char *perf_event__name(unsigned int id);
>  int perf_event__parse_sample(const union perf_event *event, u64 type,
>  			     int sample_size, bool sample_id_all,
>  			     struct perf_sample *sample, bool swapped);
> +int perf_event__change_sample(union perf_event *event, u64 type,
> +			     const struct perf_sample *data, bool swapped);
>  
>  #endif /* __PERF_RECORD_H */
> diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
> index b46f6e4..9274e08 100644
> --- a/tools/perf/util/evsel.c
> +++ b/tools/perf/util/evsel.c
> @@ -475,3 +475,77 @@ int perf_event__parse_sample(const union perf_event *event, u64 type,
>  
>  	return 0;
>  }
> +
> +int perf_event__change_sample(union perf_event *event, u64 type,
> +			     const struct perf_sample *data, bool swapped)
> +{
> +	u64 *array;
> +
> +	/*
> +	 * used for cross-endian analysis. See git commit 65014ab3
> +	 * for why this goofiness is needed.
> +	 */
> +	union {
> +		u64 val64;
> +		u32 val32[2];
> +	} u;
> +
> +	array = event->sample.array;
> +
> +	if (type & PERF_SAMPLE_IP) {
> +		event->ip.ip = data->ip;
> +		array++;
> +	}
> +
> +	if (type & PERF_SAMPLE_TID) {
> +		u.val32[0] = data->pid;
> +		u.val32[1] = data->tid;
> +		if (swapped) {
> +			/* undo swap of u64, then swap on individual u32s */
> +			u.val64 = bswap_64(u.val64);
> +			u.val32[0] = bswap_32(u.val32[0]);
> +			u.val32[1] = bswap_32(u.val32[1]);

If this is meant to be the reverse direction of parse_sample then I
think you need the bswap_64 after the bswap_32.


> +		}
> +
> +		*array = u.val64;
> +		array++;
> +	}
> +
> +	if (type & PERF_SAMPLE_TIME) {
> +		*array = data->time;
> +		array++;
> +	}
> +
> +	if (type & PERF_SAMPLE_ADDR) {
> +		*array = data->addr;
> +		array++;
> +	}
> +
> +	if (type & PERF_SAMPLE_ID) {
> +		*array = data->id;
> +		array++;
> +	}
> +
> +	if (type & PERF_SAMPLE_STREAM_ID) {
> +		*array = data->stream_id;
> +		array++;
> +	}
> +
> +	if (type & PERF_SAMPLE_CPU) {
> +		u.val32[0] = data->cpu;
> +		if (swapped) {
> +			/* undo swap of u64, then swap on individual u32s */
> +			u.val64 = bswap_64(u.val64);
> +			u.val32[0] = bswap_32(u.val32[0]);
> +		}

Ditto here too.

This really should be tested for cross-endian analysis to verify it
works properly.

David


> +		*array = u.val64;
> +		array++;
> +	}
> +
> +	if (type & PERF_SAMPLE_PERIOD) {
> +		*array = data->period;
> +		array++;
> +	}
> +
> +	return 0;
> +}
> diff --git a/tools/perf/util/session.h b/tools/perf/util/session.h
> index 514b06d..5a36d10 100644
> --- a/tools/perf/util/session.h
> +++ b/tools/perf/util/session.h
> @@ -166,6 +166,15 @@ static inline int perf_session__parse_sample(struct perf_session *session,
>  					session->header.needs_swap);
>  }
>  
> +static inline int perf_session__change_sample(struct perf_session *session,
> +					     union perf_event *event,
> +					     const struct perf_sample *sample)
> +{
> +	return perf_event__change_sample(event, session->sample_type,
> +					sample,
> +					session->header.needs_swap);
> +}
> +
>  struct perf_evsel *perf_session__find_first_evtype(struct perf_session *session,
>  					    unsigned int type);
>  

[PATCH 5/7] 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 6/7] 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 |   87 +++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 87 insertions(+), 0 deletions(-)

diff --git a/tools/perf/builtin-inject.c b/tools/perf/builtin-inject.c
index 8df8b71..d0af19d 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,85 @@ repipe:
 	return 0;
 }
 
+struct event_entry
+{
+	struct list_head list;
+	u32 pid;
+	union perf_event event[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;
+	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->event, event, 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_debug("Could not find sched_switch for pid %u\n", pid);
+			return 0;
+		}
+
+		event_sw = &ent->event[0];
+		perf_session__parse_sample(session, event_sw, &sample_sw);
+		sample_sw.period = sample->period;
+		sample_sw.time = sample->time;
+		perf_session__change_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 +296,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 +326,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 7/7] 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 |   65 +++++++++++++++++++++++
 tools/perf/scripts/python/bin/sched-stat-report |    5 ++
 2 files changed, 70 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..5e0bd97
--- /dev/null
+++ b/tools/perf/scripts/python/bin/sched-stat-record
@@ -0,0 +1,65 @@
+#!/bin/bash
+# perf script record -- sched:sched_stat_[smth] -- CMD
+# perf script record -- -e sched:sched_stat_[smth]
+#
+set -o monitor
+
+usage()
+{
+	echo "Usage:"
+	echo "	perf script record -- sched:sched_stat_[smth] -- CMD"
+	echo "	perf script record -- [PERF OPTS] -e sched:sched_stat_[smth]"
+	exit 1;
+}
+
+declare -a opt
+declare -a cmd
+f=0;
+for i in "${@:2}"; do
+	if [ "$i" == "--" ]; then
+		f=1
+		continue
+	fi
+	if [ $f -eq 1 ]; then
+		cmd[${#cmd[*]}]="$i"
+	else
+		opt[${#opt[*]}]="$i"
+	fi
+done
+
+if [[ "${opt[@]}" != *sched_stat_* ]]; then
+	usage;
+fi
+
+if [ ${#cmd[@]} -eq 0 ]; then
+	if [ ${#opt[@]} -eq 0 ]; then
+		usage;
+	fi
+	exec perf record -agP \
+		-e sched:sched_switch \
+		--filter "prev_state == 1 || prev_state == 2" \
+		"${opt[@]}"
+fi
+
+if [ ${#opt[@]} -ne 1 ]; then
+	usage;
+fi
+
+# Wait until a target process is stopped.
+bash -c 'kill -STOP $$; exec "$@"' -- "${cmd[@]}" &
+pid=$!
+wait %1
+[ $? -eq 147 ] || exit 1;
+
+perf record -agP \
+		-e sched:sched_switch \
+		--filter "prev_pid == $pid && prev_state == 1 || prev_state == 2" \
+		-e sched:sched_process_exit -e "${opt[@]}" --filter "pid == $pid" &
+pid_perf=$!
+kill -CONT %1
+while :; do
+	wait %1
+	[ $? -eq 127 ] && break;
+done
+kill -INT %2
+wait %2
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..e5114ce
--- /dev/null
+++ b/tools/perf/scripts/python/bin/sched-stat-report
@@ -0,0 +1,5 @@
+#!/bin/bash
+# description: profiling sleep times
+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

[PATCH 0/7] Profiling sleep times (v3)

[Andrew Vagin]

Do you want to know where your code waits locks for a long time?
Yes! It's for you. This feature helps you to find bottlenecks.

It's not artificial task. Once one of my colleague was investigating a
scalability problem. He pressed sysrq-t some times and tried to merge
call-chains by hand. But perf can do that.

Problem:
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.

v2:
* Removed all known issues. Now it works completely.
* Improved usability of sched-stat scripts according with Arun's comments.
v3: fixed accoding to comments from David Ahem

Andrew Vagin (7):
  perf: use event_name() to get an event name
  perf: add ability to record event period
  perf: add ability to change event according to sample (v2)
  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 (v2)
  event: add tracepoint for accounting block time

 include/trace/events/sched.h                    |    7 ++
 kernel/sched_fair.c                             |    2 +
 tools/perf/builtin-inject.c                     |  120 ++++++++++++++++++++++-
 tools/perf/builtin-record.c                     |    5 +
 tools/perf/scripts/python/bin/sched-stat-record |   65 ++++++++++++
 tools/perf/scripts/python/bin/sched-stat-report |    5 +
 tools/perf/util/event.h                         |    2 +
 tools/perf/util/evsel.c                         |   74 ++++++++++++++
 tools/perf/util/header.c                        |    2 +-
 tools/perf/util/session.h                       |    9 ++
 10 files changed, 288 insertions(+), 3 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/7] 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 bcd05d0..33c17a2 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

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

[Arnaldo Carvalho de Melo]

Em Mon, Nov 28, 2011 at 12:03:29PM +0300, Andrew Vagin escreveu:
> perf_evsel.name may be not initialized

I'm applying this one to my perf/urgent branch and will ask Ingo to
merge it today.
 
> 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 bcd05d0..33c17a2 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