Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 860f9f6b authored by Tom Zanussi's avatar Tom Zanussi Committed by Steven Rostedt (VMware)
Browse files

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: default avatarTom Zanussi <tom.zanussi@linux.intel.com>
Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
parent b559d003

Documentation/trace/histogram.txt

+1 −0
Original line number Diff line number Diff line
@@ -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

kernel/trace/trace.c

+11 −2
Original line number Diff line number Diff line
@@ -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"

kernel/trace/trace.h

+2 −0
Original line number Diff line number Diff line
@@ -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.

kernel/trace/trace_events_hist.c

+22 −6
Original line number Diff line number Diff line
@@ -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;

}