Skip to content

Commit

Permalink
tracing: Add usecs modifier for hist trigger timestamps
Browse files Browse the repository at this point in the history
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>
  • Loading branch information
Tom Zanussi authored and Steven Rostedt (VMware) committed Mar 10, 2018
1 parent b559d00 commit 860f9f6
Show file tree
Hide file tree
Showing 4 changed files with 36 additions and 8 deletions.
1 change: 1 addition & 0 deletions Documentation/trace/histogram.txt
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
13 changes: 11 additions & 2 deletions kernel/trace/trace.c
Original file line number Diff line number Diff line change
Expand Up @@ -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
*/
Expand Down Expand Up @@ -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"
Expand Down
2 changes: 2 additions & 0 deletions kernel/trace/trace.h
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
28 changes: 22 additions & 6 deletions kernel/trace/trace_events_hist.c
Original file line number Diff line number Diff line change
Expand Up @@ -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, \
Expand Down Expand Up @@ -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 {
Expand All @@ -153,6 +148,7 @@ struct hist_trigger_attrs {
bool pause;
bool cont;
bool clear;
bool ts_in_usecs;
unsigned int map_bits;
};

Expand All @@ -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)
{
Expand Down Expand Up @@ -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;
Expand All @@ -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);
Expand Down Expand Up @@ -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;
}
Expand Down

0 comments on commit 860f9f6

Please sign in to comment.