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
Signed-off-by: David Ahern <[email protected]>
---
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
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 <[email protected]>
---
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, <ime) != NULL) {
+ char date[128];
+ strftime(date, sizeof(date), tod_fmt, <ime);
+ 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, <ime);
+ rc = strftime(date, sizeof(date), arg, <ime);
+ 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
Signed-off-by: David Ahern <[email protected]>
---
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
Signed-off-by: David Ahern <[email protected]>
---
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
Kernel side plumbing for PERF_SAMPLE_REALTIME.
Signed-off-by: David Ahern <[email protected]>
---
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
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
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
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