Profiling sleep times?

Some of our users want to use perf to profile not just the code that consumes cycles, but also the code that ends up waiting for I/O - otherwise known as wall clock profiling.

I could not find ways of getting this info from the perf tool as-is. Wondering if a software event such as PERF_COUNT_SW_SLEEP_CLOCK below makes sense.

The idea is, if a task sleeps for 1ms, it should generate 1000x more samples vs a task that sleeps for 1us. Also, the callchain emitted should be the user stack.

If such an event is useful to a larger set of users, I could try to work out the details of how to get to event->attr.freq in the context switch path with low overhead and run some tests to verify that the profile that comes out of "perf report" looks sane.

We'll also need ways of combining PERF_COUNT_SW_TASK_CLOCK and PERF_COUNT_SW_SLEEP_CLOCK (in userspace?) to get the full picture.

-Arun

index c2da40d..a3e2fb4 100644
@@ -106,6 +106,7 @@ enum perf_sw_ids {
        PERF_COUNT_SW_PAGE_FAULTS_MAJ           = 6,
        PERF_COUNT_SW_ALIGNMENT_FAULTS          = 7,
        PERF_COUNT_SW_EMULATION_FAULTS          = 8,
+       PERF_COUNT_SW_SLEEP_CLOCK               = 9,
 
        PERF_COUNT_SW_MAX,                      /* non-ABI */
 };

index 7406f36..e973862 100644
@@ -877,8 +877,10 @@ static void enqueue_sleeper(struct cfs_rq *cfs_rq, struct sched_entity *se)
                se->statistics.sum_sleep_runtime += delta;
 
                if (tsk) {
+                       u64 freq = 1000000; /* XXX: Use event->attr.freq ? */
                        account_scheduler_latency(tsk, delta >> 10, 1);
                        trace_sched_stat_sleep(tsk, delta);
+                       perf_sw_event(PERF_COUNT_SW_SLEEP_CLOCK, delta/freq, 0, NULL, 0);
                }
        }
        if (se->statistics.block_start) {

That one should be accessible as a tracepoint and will add delay to count on each occurrence.

Right - the tracepoint seems to work. Was looking for the user stack trace as well. For eg:

# cat foo.c
#include <unistd.h>
#include <time.h>
#include <sys/select.h>

main()

{
        struct timespec ts1;
        struct timeval tv1;
        int i;


        for (i = 0; i < 1000; i++) {
                ts1.tv_sec = 0;
                ts1.tv_nsec = 1000000;
                nanosleep(&ts1, NULL);

                tv1.tv_sec = 0;
                tv1.tv_usec = 4000;
                select(0, NULL, NULL, NULL, &tv1);
        }
}

I want something that gives me 4 times as many samples on select() as nanosleep().

perf record -g -e sched:sched_stat_sleep -- ./foo

doesn't seem to do it. Additionally, if I have a burn_1us_cpu() loop in there, I'd expect to see as many samples as nanosleep() in the wall clock profile.

-Arun

Would you per-chance be suffering from this:

http://lkml.kernel.org/r/[email protected]

Thanks for the pointer. Yes - Andrew's patches help. But looks like we need more user space plumbing like Frederic noted.

perf record -ge sched:sched_stat_sleep -- ./foo

doesn't quite work.

perf record -age sched:sched_stat_sleep -- ./foo

gives me:

58.62% foo [unknown] [k] 0

                       |
                       --- schedule
                          |
                          |--54.99%-- schedule_hrtimeout_range_clock
                          |          schedule_hrtimeout_range
                          |          poll_schedule_timeout
                          |          do_select
                          |          core_sys_select
                          |          sys_select
                          |          system_call_fastpath
                          |
                          |--44.81%-- do_nanosleep
                          |          hrtimer_nanosleep
                          |          sys_nanosleep
                          |          system_call_fastpath
                           --0.20%-- [...]

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?

-Arun

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

From a2d6e0698eebb038b2d8e845137008dc3478cc51 Mon Sep 17 00:00:00 2001
From: Arun Sharma <[email protected]>
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(-)

index d7ff277..6821597 100644
@@ -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) {

index 5d73262..e7179ff 100644
@@ -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"
 

index 0a7ed5b..78b7194 100644
@@ -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);

index f674dda..587b553 100644
@@ -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

But the idea of the __perf_count() thing:

DECLARE_EVENT_CLASS(sched_stat_template,

	TP_PROTO(struct task_struct *tsk, u64 delay),

	TP_ARGS(tsk, delay),

	TP_STRUCT__entry(
		__array( char,	comm,	TASK_COMM_LEN	)
		__field( pid_t,	pid			)
		__field( u64,	delay			)
	),

	TP_fast_assign(
		memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
		__entry->pid	= tsk->pid;
		__entry->delay	= delay;
	)
	TP_perf_assign(
		__perf_count(delay);
	),

	TP_printk("comm=%s pid=%d delay=%Lu [ns]",
			__entry->comm, __entry->pid,
			(unsigned long long)__entry->delay)

);

is that the counter is incremented with the delay, so the event should get weighted right.

So having to get the delay out of the raw tracepoint data shouldn't be needed.

__perf_count() doesn't work now and I have sent the patch, which fixes it. Could you commit it? It's subject:
[PATCH 1/4] perf: fix counter of ftrace events

but it's not all.
By default perf doesn't use SAMPLE_PERIOD, it bases on events count. Each "trace" event is divided on some "perf" events in perf_swevent_overflow().

The number of perf events should be proportional __perf_count(), but the number of perf events restricted by sysctl_perf_event_sample_rate / HZ. In my case it's 100 events.

....

if (hwc->interrupts != MAX_INTERRUPTS) {
    hwc->interrupts++;
    if (HZ * hwc->interrupts > (u64)sysctl_perf_event_sample_rate) {

....

So Arun Sharma probably has perf.data which contains packages of events and each package contains 100 events irrespective of "delay".

tip/master:

commit 92e51938f5d005026ba4bb5b1fae5a86dc195b86

Author: Andrew Vagin <[email protected]>
Date:   Mon Sep 26 19:55:32 2011 +0400

perf: Fix counter of ftrace events

How does this work for dynamic tracepoints? Or tracepoints with multiple dimensions where the user might want to query each dimension separately?

Andrew: what do you think about generalizing my patch to accept a command line option(s) to specify which fields to use for the purpose of computing the histogram?

For static tracepoints, TP_perf_assign() could act as a hint on which field to default to.

-Arun

Hello Arun,

I have no objection, but I don't think, that we really need that.

Now we have not got a real use case. All events which I've seen have not more than one parameters, which may be used as weight and for this one we already have parameter "period".

I already said, that you have trouble with sched_stat_sleed due to some issues in kernel.

The first issue is that __perf_cout doesn't work and I sent the patch, which fixes it. ([PATCH] perf: fix counter of ftrace events)

And the second issue is that the trace events are divided on some perf events and their number is restricted by sysctl_perf_event_sample_rate/HZ. I don't sure, that we should generate more than one "perf" event on each "trace" event. I think the better way to use SAMPLE_PERIOD and now I think in this direction.

If you want to fix the bug with sched_stat_sleep, you need to fix the second issue. I found workaround for your case:

#./perf record -age sched:sched_stat_sleep --filter="comm == foo" -c 100000 -F 100000 -- ~/foo

# ./perf report
# Events: 5K sched:sched_stat_sleep
#
# Overhead  Command      Shared Object  Symbol
# ........  .......  .................  ......
#
    99.98%      foo  [unknown]          [k] 0
                |
                --- schedule
                   |
                   |--80.20%-- schedule_hrtimeout_range_clock
                   |          schedule_hrtimeout_range
                   |          poll_schedule_timeout
                   |          do_select
                   |          core_sys_select
                   |          sys_select
                   |          system_call_fastpath
                   |
                    --19.80%-- do_nanosleep
                              hrtimer_nanosleep
                              sys_nanosleep
                              system_call_fastpath

Yes, I'm working. I've attached the draft version.

The example of usage:
#./perf record -ag -e sched:sched_switch --filter "prev_state == 1" -e sched:sched_process_exit -e sched:sched_stat_sleep --filter "comm == foo" ~/foo

#./perf inject -s -i perf.data -o perf.data.d

#./perf report -i perf.data.d

I will be glad to receive any comments.

From c2cd0d73c11687fbc67884aba337f497e13890f9 Mon Sep 17 00:00:00 2001
From: Andrew Vagin <[email protected]>
Date: Tue, 4 Oct 2011 16:10:23 +0400
Subject: [PATCH 1/3] perf: teach "perf inject" to work with files

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.

---
 tools/perf/builtin-inject.c |   33 +++++++++++++++++++++++++++++++--
 1 files changed, 31 insertions(+), 2 deletions(-)

index 8dfc12b..8df8b71 100644
@@ -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

From e08809ba075d92e60f669fc62c48128e06c834fb Mon Sep 17 00:00:00 2001
From: Andrew Vagin <[email protected]>
Date: Thu, 6 Oct 2011 12:18:44 +0400
Subject: [PATCH 3/3] perf: add scripts for collecting D-state statistics

---
 .../perf/scripts/python/bin/task-in-d-state-record |    2 ++
 .../perf/scripts/python/bin/task-in-d-state-report |    6 ++++++
 2 files changed, 8 insertions(+), 0 deletions(-)
 create mode 100644 tools/perf/scripts/python/bin/task-in-d-state-record
 create mode 100644 tools/perf/scripts/python/bin/task-in-d-state-report

new file mode 100644
index 0000000..d70bed0
@@ -0,0 +1,2 @@
+#!/bin/bash
+perf record -ag -e sched:sched_switch --filter "prev_state == 2" -e sched:sched_stat_iowait -e sched:sched_process_exit $@

new file mode 100644
index 0000000..f1ab71e
@@ -0,0 +1,6 @@
+#!/bin/bash
+# description: D-state statistics
+# args:
+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

From 7a3152c03d07d30f47ab4fe9295212330bf821e4 Mon Sep 17 00:00:00 2001
From: Andrew Vagin <[email protected]>
Date: Tue, 4 Oct 2011 16:54:15 +0400
Subject: [PATCH 2/3] perf: teach perf inject to merge sched_stat_* and sched_switch events

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 it contains a correct callchain. By another words it replaces all stat_iowait events on proper sched_switch events.

My code doesn't change events.

---
 tools/perf/builtin-inject.c |   87 +++++++++++++++++++++++++++++++++++++++++++
 1 files changed, 87 insertions(+), 0 deletions(-)

1.7.1

Generally I'm happy with the direction of these patches. For doing wall time based profiling we'll need support in perf inject to merge sleep + cycles events.

Re: examples of why one might need histograms based on various fields in a dynamic kernel probe:

I might want to add a probe such as:

perf probe --add 'sys_read fd=%di'
perf probe --add 'sys_read%return bytes=$retval'

and expect to find stack traces that are responsible for most I/O calls based on bytes vs fd vs number of syscalls.

-Arun

Ok, will someone please send an updated series of all missing patches, with all acks included, for potential v3.2 pickup?

Sleep time profiling is obviously a very hot feature ...

Thanks,

Ingo

I'm in vacation now, so I'm going to send my patches in two-three weeks.

Sorry for delay.

I acked two of Andrew's patches. The third one is the most important one. I haven't had a chance to review that carefully yet - although it's working well for me.

We still need to figure out what's the best way to munge all this data in user space to implement wall clock profiling.

-Arun

Well, if 'perf report' can show sleep time ordered entries just fine by default (if a proper perf record was done), which also works in call graph recording mode then i'm a happy camper.

Sleep time should really just be a different notion of 'cost of the function/callchain' and fit into the existing scheme, right?

Thanks,

Ingo

The problem with andrew's patches is that it wrecks the callchain semantics. The waittime tracepoint is in the wakeup path (and hence generates the wakee's callchain) whereas they really want the callchain of the woken task to show where it spend time.

We could of course try to move the tracepoint into the schedule path, so we issue it the first time the task gets scheduled after the wakeup, but I suspect that will just add more overhead, and we really could do without that.

Do we need to define new tracepoints? I suspect we could make the existing ones:

trace_sched_stat_wait()
trace_sched_stat_sleep()

work for this purpose. The length of time the task was not on the cpu could then be computed as: sleep+wait. The downside is that the complexity moves to user space.

perf record -e sched:sched_stat_sleep,sched:sched_stat_wait,...

Re: changing the semantics of tracepoint callchains

Yeah - this could be surprising. Luckily, most tracepoints retain their semantics, but a few special ones don't. I guess we just need to document the new behavior.

-Arun

That's not only a problem of semantics although that alone is a problem, people will seldom read the documentation for corner cases, we should really stay consistant here: if remote callchains are really needed, we want a specific interface for that, not abusing the existing one that would only confuse people.

Now I still think doing remote callchains is asking for troubles: we need to ensure the target is really sleeping and is not going to be scheduled concurrently otherwise you might get weird or stale results. So the user needs to know which tracepoints are safe to perform this.
Then comes the problem to deal with remote callchains in userspace: the event comes from a task but the callchain is from another. You need the perf tools to handle remote dsos/mapping/sym etc...

That's a lot of unnecessary complications.

I think we should use something like a perf report plugin: perhaps something that can create a virtual event on top of real ones: compute the sched:sched_switch events, find the time tasks are sleeping and create virtual sleep events on top of that with a period weighted with the sleep time.
Just a thought.

Hi, All.

Sorry for late response. I have vacation.

I see the miscomuniction. You explained me, that remote callchains was not a good idea and now I think the same. I added plugin to "perf inject".

The example of usage:
#./perf record -ag -e sched:sched_switch --filter "prev_state == 1" -e sched:sched_process_exit -e sched:sched_stat_sleep --filter "comm == foo" ~/foo

#./perf inject -s -i perf.data -o perf.data.d

#./perf report -i perf.data.d

I'm going to send patches soon.

2011/10/22 Frederic Weisbecker <[email protected]>:

A separate interface sounds good.

I expect this interface to be used in a small number of well known places in the kernel.

[...]

Right - whether we're doing wall-clock profiling or sleep profiling, it'll involve looking at multiple real events.

I still see one problem with doing: perf record -ag -e <bunch of events> and trying to sort through what happened. Unprivileged users who don't have permissions to system wide profiling, but have privileges to profile their own processes get locked out of this feature.

-Arun