[PATCH 0/5] perf events: Add time-of-day to perf samples

[PATCH 0/5] perf events: Add time-of-day to perf samples

[David Ahern]

Rather than collecting data to correlate the perf_clock timestamps to
time-of-day this approach adds the realtime clock value directly to the
perf sample.

David Ahern (5):
  perf events: add support for realtime clock attribute
  perf events: userspace plumbing for realtime sample attribute
  perf record: add time-of-day option
  perf script: add support for time-of-day strings in output
  perf python: add REALTIME to constants

 include/linux/perf_event.h               |    4 +-
 kernel/perf_event.c                      |   12 ++++
 tools/perf/Documentation/perf-record.txt |    4 ++
 tools/perf/Documentation/perf-script.txt |    8 +++-
 tools/perf/builtin-record.c              |    5 ++
 tools/perf/builtin-script.c              |   84 +++++++++++++++++++++++++++++-
 tools/perf/util/event.c                  |    1 +
 tools/perf/util/event.h                  |    1 +
 tools/perf/util/evsel.c                  |   10 ++++
 tools/perf/util/python.c                 |    1 +
 tools/perf/util/session.c                |    6 ++
 11 files changed, 133 insertions(+), 3 deletions(-)

-- 
1.7.4

[PATCH 1/5] perf events: add support for realtime clock attribute

[David Ahern]

Kernel side plumbing for PERF_SAMPLE_REALTIME.

Signed-off-by: David Ahern <daahern@cisco.com>
---
 include/linux/perf_event.h |    4 +++-
 kernel/perf_event.c        |   12 ++++++++++++
 2 files changed, 15 insertions(+), 1 deletions(-)

diff --git a/include/linux/perf_event.h b/include/linux/perf_event.h
index f495c01..d64f0fd 100644
--- a/include/linux/perf_event.h
+++ b/include/linux/perf_event.h
@@ -125,8 +125,9 @@ enum perf_event_sample_format {
 	PERF_SAMPLE_PERIOD			= 1U << 8,
 	PERF_SAMPLE_STREAM_ID			= 1U << 9,
 	PERF_SAMPLE_RAW				= 1U << 10,
+	PERF_SAMPLE_REALTIME			= 1U << 11,
 
-	PERF_SAMPLE_MAX = 1U << 11,		/* non-ABI */
+	PERF_SAMPLE_MAX = 1U << 12,		/* non-ABI */
 };
 
 /*
@@ -998,6 +999,7 @@ struct perf_sample_data {
 		u32	cpu;
 		u32	reserved;
 	}				cpu_entry;
+	u64				realtime;
 	u64				period;
 	struct perf_callchain_entry	*callchain;
 	struct perf_raw_record		*raw;
diff --git a/kernel/perf_event.c b/kernel/perf_event.c
index 3472bb1..977a07b 100644
--- a/kernel/perf_event.c
+++ b/kernel/perf_event.c
@@ -903,6 +903,9 @@ static void perf_event__id_header_size(struct perf_event *event)
 	if (sample_type & PERF_SAMPLE_CPU)
 		size += sizeof(data->cpu_entry);
 
+	if (sample_type & PERF_SAMPLE_REALTIME)
+		size += sizeof(data->realtime);
+
 	event->id_header_size = size;
 }
 
@@ -4016,6 +4019,9 @@ static void __perf_event_header__init_id(struct perf_event_header *header,
 		data->cpu_entry.cpu	 = raw_smp_processor_id();
 		data->cpu_entry.reserved = 0;
 	}
+
+	if (sample_type & PERF_SAMPLE_REALTIME)
+		data->realtime = ktime_to_ns(ktime_get_real());
 }
 
 static void perf_event_header__init_id(struct perf_event_header *header,
@@ -4045,6 +4051,9 @@ static void __perf_event__output_id_sample(struct perf_output_handle *handle,
 
 	if (sample_type & PERF_SAMPLE_CPU)
 		perf_output_put(handle, data->cpu_entry);
+
+	if (sample_type & PERF_SAMPLE_REALTIME)
+		perf_output_put(handle, data->realtime);
 }
 
 static void perf_event__output_id_sample(struct perf_event *event,
@@ -4289,6 +4298,9 @@ void perf_output_sample(struct perf_output_handle *handle,
 	if (sample_type & PERF_SAMPLE_CPU)
 		perf_output_put(handle, data->cpu_entry);
 
+	if (sample_type & PERF_SAMPLE_REALTIME)
+		perf_output_put(handle, data->realtime);
+
 	if (sample_type & PERF_SAMPLE_PERIOD)
 		perf_output_put(handle, data->period);
 
-- 
1.7.4

[PATCH 2/5] perf events: userspace plumbing for realtime sample attribute

[David Ahern]

Signed-off-by: David Ahern <daahern@cisco.com>
---
 tools/perf/util/event.c   |    1 +
 tools/perf/util/event.h   |    1 +
 tools/perf/util/evsel.c   |   10 ++++++++++
 tools/perf/util/session.c |    6 ++++++
 4 files changed, 18 insertions(+), 0 deletions(-)

diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
index 2b15c36..8abd33a 100644
--- a/tools/perf/util/event.c
+++ b/tools/perf/util/event.c
@@ -39,6 +39,7 @@ static struct perf_sample synth_sample = {
 	.pid	   = -1,
 	.tid	   = -1,
 	.time	   = -1,
+	.realtime  = -1,
 	.stream_id = -1,
 	.cpu	   = -1,
 	.period	   = 1,
diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
index 9c35170..0c8dc11 100644
--- a/tools/perf/util/event.h
+++ b/tools/perf/util/event.h
@@ -65,6 +65,7 @@ struct perf_sample {
 	u64 ip;
 	u32 pid, tid;
 	u64 time;
+	u64 realtime;
 	u64 addr;
 	u64 id;
 	u64 stream_id;
diff --git a/tools/perf/util/evsel.c b/tools/perf/util/evsel.c
index 662596a..8768ea9 100644
--- a/tools/perf/util/evsel.c
+++ b/tools/perf/util/evsel.c
@@ -286,6 +286,11 @@ static int perf_event__parse_id_sample(const union perf_event *event, u64 type,
 	array += ((event->header.size -
 		   sizeof(event->header)) / sizeof(u64)) - 1;
 
+	if (type & PERF_SAMPLE_REALTIME) {
+		sample->realtime = *array;
+		array--;
+	}
+
 	if (type & PERF_SAMPLE_CPU) {
 		u32 *p = (u32 *)array;
 		sample->cpu = *p;
@@ -371,6 +376,11 @@ int perf_event__parse_sample(const union perf_event *event, u64 type,
 		array++;
 	}
 
+	if (type & PERF_SAMPLE_REALTIME) {
+		data->realtime = *array;
+		array++;
+	}
+
 	if (type & PERF_SAMPLE_PERIOD) {
 		data->period = *array;
 		array++;
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index c68cf40..b220c93 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -90,6 +90,9 @@ static void perf_session__id_header_size(struct perf_session *session)
 
        if (sample_type & PERF_SAMPLE_CPU)
                size += sizeof(data->cpu) * 2;
+
+       if (sample_type & PERF_SAMPLE_REALTIME)
+               size += sizeof(data->realtime);
 out:
        session->id_hdr_size = size;
 }
@@ -658,6 +661,9 @@ static void perf_session__print_tstamp(struct perf_session *session,
 
 	if (session->sample_type & PERF_SAMPLE_TIME)
 		printf("%" PRIu64 " ", sample->time);
+
+	if (session->sample_type & PERF_SAMPLE_REALTIME)
+		printf("%" PRIu64 " ", sample->realtime);
 }
 
 static void dump_event(struct perf_session *session, union perf_event *event,
-- 
1.7.4

[PATCH 3/5] perf record: add time-of-day option

[David Ahern]

Signed-off-by: David Ahern <daahern@cisco.com>
---
 tools/perf/Documentation/perf-record.txt |    4 ++++
 tools/perf/builtin-record.c              |    5 +++++
 2 files changed, 9 insertions(+), 0 deletions(-)

diff --git a/tools/perf/Documentation/perf-record.txt b/tools/perf/Documentation/perf-record.txt
index 5a520f8..b56b5c7 100644
--- a/tools/perf/Documentation/perf-record.txt
+++ b/tools/perf/Documentation/perf-record.txt
@@ -116,6 +116,10 @@ OPTIONS
 	Sample timestamps. Use it with 'perf report -D' to see the timestamps,
 	for instance.
 
+--tod::
+	Collect data for time-of-day strings when printing events. This option
+	adds the realtime attribute to samples.
+
 -n::
 --no-samples::
 	Don't sample.
diff --git a/tools/perf/builtin-record.c b/tools/perf/builtin-record.c
index 6febcc1..df15256 100644
--- a/tools/perf/builtin-record.c
+++ b/tools/perf/builtin-record.c
@@ -53,6 +53,7 @@ static bool			nodelay				=  false;
 static bool			raw_samples			=  false;
 static bool			sample_id_all_avail		=   true;
 static bool			system_wide			=  false;
+static bool			want_tod			=  false;
 static pid_t			target_pid			=     -1;
 static pid_t			target_tid			=     -1;
 static pid_t			child_pid			=     -1;
@@ -214,6 +215,9 @@ static void config_attr(struct perf_evsel *evsel, struct perf_evlist *evlist)
 		attr->sample_type	|= PERF_SAMPLE_CPU;
 	}
 
+	if (want_tod)
+		attr->sample_type |= PERF_SAMPLE_REALTIME;
+
 	if (nodelay) {
 		attr->watermark = 0;
 		attr->wakeup_events = 1;
@@ -764,6 +768,7 @@ const struct option record_options[] = {
 	OPT_BOOLEAN('d', "data", &sample_address,
 		    "Sample addresses"),
 	OPT_BOOLEAN('T', "timestamp", &sample_time, "Sample timestamps"),
+	OPT_BOOLEAN(0, "tod", &want_tod, "Collect data for Time-of-day strings."),
 	OPT_BOOLEAN('n', "no-samples", &no_samples,
 		    "don't sample"),
 	OPT_BOOLEAN('N', "no-buildid-cache", &no_buildid_cache,
-- 
1.7.4

[PATCH 4/5] perf script: add support for time-of-day strings in output

[David Ahern]

Format of time-of-day strings handled through strftime. Any format
recognized by it can be used. Default format is %H:%M:%S with
microseconds appended.

Signed-off-by: David Ahern <daahern@cisco.com>
---
 tools/perf/Documentation/perf-script.txt |    8 +++-
 tools/perf/builtin-script.c              |   84 +++++++++++++++++++++++++++++-
 2 files changed, 90 insertions(+), 2 deletions(-)

diff --git a/tools/perf/Documentation/perf-script.txt b/tools/perf/Documentation/perf-script.txt
index 66f040b..9f04caa 100644
--- a/tools/perf/Documentation/perf-script.txt
+++ b/tools/perf/Documentation/perf-script.txt
@@ -115,7 +115,7 @@ OPTIONS
 -f::
 --fields
         Comma separated list of fields to print. Options are:
-        comm, tid, pid, time, cpu, event, trace, sym. Field
+        tod, comm, tid, pid, time, cpu, event, trace, sym. Field
         list must be prepended with the type, trace, sw or hw,
         to indicate to which event type the field list applies.
         e.g., -f sw:comm,tid,time,sym  and -f trace:time,cpu,trace
@@ -134,6 +134,12 @@ OPTIONS
 --hide-call-graph::
         When printing symbols do not display call chain.
 
+--tod::
+        Format for time-of-day strings. Format string is passed to
+        strftime, so any format recognized by it can be used (see
+        man strftime). Default format is "%H:%M:%S". Microseocnds
+        are appended to the time string.
+
 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 9f5fc54..72c9a34 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -22,6 +22,8 @@ static u64			last_timestamp;
 static u64			nr_unordered;
 extern const struct option	record_options[];
 static bool			no_callchain;
+static char default_tod_fmt[] = "%H:%M:%S";
+static char *tod_fmt = default_tod_fmt;
 
 enum perf_output_field {
 	PERF_OUTPUT_COMM            = 1U << 0,
@@ -32,6 +34,7 @@ enum perf_output_field {
 	PERF_OUTPUT_EVNAME          = 1U << 5,
 	PERF_OUTPUT_TRACE           = 1U << 6,
 	PERF_OUTPUT_SYM             = 1U << 7,
+	PERF_OUTPUT_TIMEOFDAY       = 1U << 8,
 };
 
 struct output_option {
@@ -46,6 +49,7 @@ struct output_option {
 	{.str = "event", .field = PERF_OUTPUT_EVNAME},
 	{.str = "trace", .field = PERF_OUTPUT_TRACE},
 	{.str = "sym",   .field = PERF_OUTPUT_SYM},
+	{.str = "tod",   .field = PERF_OUTPUT_TIMEOFDAY},
 };
 
 /* default set to maintain compatibility with current format */
@@ -102,9 +106,35 @@ static int perf_session__check_attr(struct perf_session *session,
 		return -EINVAL;
 	}
 
+	if (PRINT_FIELD(TIMEOFDAY) &&
+		!(session->sample_type & PERF_SAMPLE_REALTIME)) {
+		pr_err("Samples do not contain realtime attribute.\n");
+		pr_err("Was --tod used with perf-record?\n");
+		return -EINVAL;
+	}
+
 	return 0;
 }
 
+static const char *timeofday_str(u64 realtime)
+{
+	static char buf[64];
+	struct tm ltime;
+	struct timeval tv;
+
+	buf[0] = '\0';
+
+	tv.tv_sec = realtime / NSEC_PER_SEC;
+	tv.tv_usec = (realtime - tv.tv_sec * NSEC_PER_SEC) / 1000;
+	if (localtime_r(&tv.tv_sec, &ltime) != NULL) {
+		char date[128];
+		strftime(date, sizeof(date), tod_fmt, &ltime);
+		snprintf(buf, sizeof(buf), "%s.%06ld", date, tv.tv_usec);
+	}
+
+	return buf;
+}
+
 static void print_sample_start(struct perf_sample *sample,
 			       struct thread *thread,
 			       struct perf_event_attr *attr)
@@ -116,6 +146,9 @@ static void print_sample_start(struct perf_sample *sample,
 	unsigned long usecs;
 	unsigned long long nsecs;
 
+	if (PRINT_FIELD(TIMEOFDAY))
+		printf("%s ", timeofday_str(sample->realtime));
+
 	if (PRINT_FIELD(COMM)) {
 		if (latency_format)
 			printf("%8.8s ", thread->comm);
@@ -515,6 +548,49 @@ static int parse_output_fields(const struct option *opt __used,
 	return rc;
 }
 
+static int parse_tod_format(const struct option *opt __used,
+			    const char *arg, int unset __used)
+{
+	int i;
+	char date[128];
+	size_t rc;
+	struct tm ltime;
+
+	if (strlen(arg) == 0) {
+		pr_debug("Time-of-day strings will be suppressed\n");
+		goto out;
+	}
+
+	/* test input string for validity and length of output */
+	localtime_r(0, &ltime);
+	rc = strftime(date, sizeof(date), arg, &ltime);
+	if (rc == 0) {
+		fprintf(stderr, "Invalid format string for time-of-day\n");
+		return -EINVAL;
+	}
+
+out:
+	for (i = 0; i < PERF_TYPE_MAX; ++i) {
+		if (output_fields[i] == 0)
+			continue;
+		if (strlen(arg))
+			output_fields[i] |= PERF_OUTPUT_TIMEOFDAY;
+		else
+			output_fields[i] &= ~PERF_OUTPUT_TIMEOFDAY;
+	}
+
+	if (tod_fmt != default_tod_fmt)
+		free(tod_fmt);
+
+	tod_fmt = strdup(arg);
+	if (!tod_fmt) {
+		fprintf(stderr, "Failed to copy time-of-day format string\n");
+		return -ENOMEM;
+	}
+
+	return 0;
+}
+
 /* Helper function for filesystems that return a dent->d_type DT_UNKNOWN */
 static int is_directory(const char *base_path, const struct dirent *dent)
 {
@@ -836,8 +912,11 @@ static const struct option options[] = {
 	OPT_STRING(0, "symfs", &symbol_conf.symfs, "directory",
 		    "Look for files with symbols relative to this directory"),
 	OPT_CALLBACK('f', "fields", NULL, "str",
-		     "comma separated output fields prepend with 'type:'. Valid types: hw,sw,trace. Fields: comm,tid,pid,time,cpu,event,trace,sym",
+		     "comma separated output fields prepend with 'type:'. Valid types: hw,sw,trace. Fields: tod,comm,tid,pid,time,cpu,event,trace,sym",
 		     parse_output_fields),
+	OPT_CALLBACK(0, "tod", NULL, "str",
+		     "Format for time-of-day strings. Option is passed to strftime; microseconds are appended. Default is %H:%M:%S.",
+		     parse_tod_format),
 
 	OPT_END()
 };
@@ -1071,6 +1150,9 @@ int cmd_script(int argc, const char **argv, const char *prefix __used)
 
 	perf_session__delete(session);
 	cleanup_scripting();
+
+	if (tod_fmt != default_tod_fmt)
+		free(tod_fmt);
 out:
 	return err;
 }
-- 
1.7.4

[PATCH 5/5] perf python: add REALTIME to constants

[David Ahern]

Signed-off-by: David Ahern <daahern@cisco.com>
---
 tools/perf/util/python.c |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/tools/perf/util/python.c b/tools/perf/util/python.c
index a9f2d7e..a3e9183 100644
--- a/tools/perf/util/python.c
+++ b/tools/perf/util/python.c
@@ -827,6 +827,7 @@ static struct {
 	{ "SAMPLE_CALLCHAIN", PERF_SAMPLE_CALLCHAIN },
 	{ "SAMPLE_ID",	      PERF_SAMPLE_ID },
 	{ "SAMPLE_CPU",	      PERF_SAMPLE_CPU },
+	{ "SAMPLE_REALTIME",  PERF_SAMPLE_REALTIME },
 	{ "SAMPLE_PERIOD",    PERF_SAMPLE_PERIOD },
 	{ "SAMPLE_STREAM_ID", PERF_SAMPLE_STREAM_ID },
 	{ "SAMPLE_RAW",	      PERF_SAMPLE_RAW },
-- 
1.7.4

Re: [PATCH 1/5] perf events: add support for realtime clock attribute

[Thomas Gleixner]

On Sun, 20 Mar 2011, David Ahern wrote:
> +
> +	if (sample_type & PERF_SAMPLE_REALTIME)
> +		data->realtime = ktime_to_ns(ktime_get_real());

That's going to live lock on any sample which happens to hit in a
xtime_lock write locked section. I knew why I suggested adding
tracepoints to the timekeeping code :)

Thanks,

	tglx

Re: [PATCH 1/5] perf events: add support for realtime clock attribute

[David Ahern]

On 03/20/11 13:08, Thomas Gleixner wrote:
> On Sun, 20 Mar 2011, David Ahern wrote:
>> +
>> +	if (sample_type & PERF_SAMPLE_REALTIME)
>> +		data->realtime = ktime_to_ns(ktime_get_real());
> 
> That's going to live lock on any sample which happens to hit in a
> xtime_lock write locked section. I knew why I suggested adding
> tracepoints to the timekeeping code :)

Hmmm.... Can you give an example of when perf samples could be generated
with xtime write locked? What are the rules for when ktime_get_real can
be invoked?

David

> 
> Thanks,
> 
> 	tglx

Re: [PATCH 1/5] perf events: add support for realtime clock attribute

[Thomas Gleixner]

On Sun, 20 Mar 2011, David Ahern wrote:

> 
> 
> On 03/20/11 13:08, Thomas Gleixner wrote:
> > On Sun, 20 Mar 2011, David Ahern wrote:
> >> +
> >> +	if (sample_type & PERF_SAMPLE_REALTIME)
> >> +		data->realtime = ktime_to_ns(ktime_get_real());
> > 
> > That's going to live lock on any sample which happens to hit in a
> > xtime_lock write locked section. I knew why I suggested adding
> > tracepoints to the timekeeping code :)
> 
> Hmmm.... Can you give an example of when perf samples could be generated
> with xtime write locked?

NMI triggered samples can hit at any time.

Any tracepoint which we might add to the time keeping code inside the
xtime locked regions. And I don't want to see a restriction there.

> What are the rules for when ktime_get_real can be invoked?

Outside of xtime write locked regions.

Thanks,

	tglx