tracing: Add usecs modifier for hist trigger timestamps

Appending .usecs onto a common_timestamp field will cause the
timestamp value to be in microseconds instead of the default
nanoseconds.  A typical latency histogram using usecs would look like
this:

   # echo 'hist:keys=pid,prio:ts0=common_timestamp.usecs ...
   # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 ...

This also adds an external trace_clock_in_ns() to trace.c for the
timestamp conversion.

Link: http://lkml.kernel.org/r/4e813705a170b3e13e97dc3135047362fb1a39f3.1516069914.git.tom.zanussi@linux.intel.com
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index a4143f04a097a0139f49f04e67c09e61c7befeb0..25c94730d3fe9a408006ec72744425059020e00f 100644 (file)
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -74,6 +74,7 @@
        .syscall    display a syscall id as a system call name
        .execname   display a common_pid as a program name
        .log2       display log2 value rather than raw number
+       .usecs      display a common_timestamp in microseconds
 
   Note that in general the semantics of a given field aren't
   interpreted when applying a modifier to it, but there are some

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 988d94a05e8123b22eca4f1ef11a3c7ed2612b6e..82cc8891fda6f6d7e80d3ac0498919bed210cdf9 100644 (file)
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1168,6 +1168,14 @@ static struct {
        ARCH_TRACE_CLOCKS
 };
 
+bool trace_clock_in_ns(struct trace_array *tr)
+{
+       if (trace_clocks[tr->clock_id].in_ns)
+               return true;
+
+       return false;
+}
+
 /*
  * trace_parser_get_init - gets the buffer for trace parser
  */
@@ -4694,8 +4702,9 @@ static const char readme_msg[] =
        "\t            .sym        display an address as a symbol\n"
        "\t            .sym-offset display an address as a symbol and offset\n"
        "\t            .execname   display a common_pid as a program name\n"
-       "\t            .syscall    display a syscall id as a syscall name\n\n"
-       "\t            .log2       display log2 value rather than raw number\n\n"
+       "\t            .syscall    display a syscall id as a syscall name\n"
+       "\t            .log2       display log2 value rather than raw number\n"
+       "\t            .usecs      display a common_timestamp in microseconds\n\n"
        "\t    The 'pause' parameter can be used to pause an existing hist\n"
        "\t    trigger or to start a hist trigger but not log any events\n"
        "\t    until told to do so.  'continue' can be used to start or\n"

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 99060f7eebbd60756e1ceac2203d068ccb1b9cc3..89771b4f16df76da573b25799ddc1e21f505546c 100644 (file)
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -289,6 +289,8 @@ extern void trace_array_put(struct trace_array *tr);
 
 extern int tracing_set_time_stamp_abs(struct trace_array *tr, bool abs);
 
+extern bool trace_clock_in_ns(struct trace_array *tr);
+
 /*
  * The global tracer (top) should be the first trace array added,
  * but we check the flag anyway.

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 77ebe6b410ba8783810956674d8b1bf60971bf9e..7f5f0b8f65589591a5eb6c0656e2dda3babd0c54 100644 (file)
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -90,12 +90,6 @@ static u64 hist_field_log2(struct hist_field *hist_field, void *event,
        return (u64) ilog2(roundup_pow_of_two(val));
 }
 
-static u64 hist_field_timestamp(struct hist_field *hist_field, void *event,
-                               struct ring_buffer_event *rbe)
-{
-       return ring_buffer_event_time_stamp(rbe);
-}
-
 #define DEFINE_HIST_FIELD_FN(type)                                     \
        static u64 hist_field_##type(struct hist_field *hist_field,     \
                                     void *event,                       \
@@ -143,6 +137,7 @@ enum hist_field_flags {
        HIST_FIELD_FL_STACKTRACE        = 1 << 8,
        HIST_FIELD_FL_LOG2              = 1 << 9,
        HIST_FIELD_FL_TIMESTAMP         = 1 << 10,
+       HIST_FIELD_FL_TIMESTAMP_USECS   = 1 << 11,
 };
 
 struct hist_trigger_attrs {
@@ -153,6 +148,7 @@ struct hist_trigger_attrs {
        bool            pause;
        bool            cont;
        bool            clear;
+       bool            ts_in_usecs;
        unsigned int    map_bits;
 };
 
@@ -170,6 +166,20 @@ struct hist_trigger_data {
        bool                            enable_timestamps;
 };
 
+static u64 hist_field_timestamp(struct hist_field *hist_field, void *event,
+                               struct ring_buffer_event *rbe)
+{
+       struct hist_trigger_data *hist_data = hist_field->hist_data;
+       struct trace_array *tr = hist_data->event_file->tr;
+
+       u64 ts = ring_buffer_event_time_stamp(rbe);
+
+       if (hist_data->attrs->ts_in_usecs && trace_clock_in_ns(tr))
+               ts = ns2usecs(ts);
+
+       return ts;
+}
+
 static const char *hist_field_name(struct hist_field *field,
                                   unsigned int level)
 {
@@ -634,6 +644,8 @@ static int create_key_field(struct hist_trigger_data *hist_data,
                                flags |= HIST_FIELD_FL_SYSCALL;
                        else if (strcmp(field_str, "log2") == 0)
                                flags |= HIST_FIELD_FL_LOG2;
+                       else if (strcmp(field_str, "usecs") == 0)
+                               flags |= HIST_FIELD_FL_TIMESTAMP_USECS;
                        else {
                                ret = -EINVAL;
                                goto out;
@@ -643,6 +655,8 @@ static int create_key_field(struct hist_trigger_data *hist_data,
                if (strcmp(field_name, "common_timestamp") == 0) {
                        flags |= HIST_FIELD_FL_TIMESTAMP;
                        hist_data->enable_timestamps = true;
+                       if (flags & HIST_FIELD_FL_TIMESTAMP_USECS)
+                               hist_data->attrs->ts_in_usecs = true;
                        key_size = sizeof(u64);
                } else {
                        field = trace_find_event_field(file->event_call, field_name);
@@ -1241,6 +1255,8 @@ static const char *get_hist_field_flags(struct hist_field *hist_field)
                flags_str = "syscall";
        else if (hist_field->flags & HIST_FIELD_FL_LOG2)
                flags_str = "log2";
+       else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP_USECS)
+               flags_str = "usecs";
 
        return flags_str;
 }