diff mbox series

[18/54] tracing: Add usecs modifier for hist trigger timestamps

Message ID TY1PR01MB1692BE186772534B837CDDE396090@TY1PR01MB1692.jpnprd01.prod.outlook.com (mailing list archive)
State New, archived
Headers show
Series None | expand

Commit Message

Motai.Hirotaka@aj.MitsubishiElectric.co.jp Aug. 29, 2018, 12:17 p.m. UTC
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>
(cherry picked from commit 860f9f6b02e9e846c4cfb3505efed331a910d0b7)
Signed-off-by: Hirotaka MOTAI <Motai.Hirotaka@aj.MitsubishiElectric.co.jp>
---
 Documentation/trace/histogram.txt |  1 +
 kernel/trace/trace.c              | 13 +++++++++++--
 kernel/trace/trace.h              |  2 ++
 kernel/trace/trace_events_hist.c  | 28 ++++++++++++++++++++++------
 4 files changed, 36 insertions(+), 8 deletions(-)
diff mbox series

Patch

diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt
index a4143f04a..25c94730 100644
--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -69,16 +69,17 @@ 
   name:
 
         .hex        display a number as a hex value
 	.sym        display an address as a symbol
 	.sym-offset display an address as a symbol and offset
 	.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
   restrictions to be aware of in this regard:
 
     - only the 'hex' modifier can be used for values (because values
       are essentially sums, and the other modifiers don't make sense
       in that context).
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index ef1489d4..f743fe19 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -1165,16 +1165,24 @@  static struct {
 	{ trace_clock_jiffies,		"uptime",	0 },
 	{ trace_clock,			"perf",		1 },
 	{ ktime_get_mono_fast_ns,	"mono",		1 },
 	{ ktime_get_raw_fast_ns,	"mono_raw",	1 },
 	{ ktime_get_boot_fast_ns,	"boot",		1 },
 	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
  */
 int trace_parser_get_init(struct trace_parser *parser, int size)
 {
 	memset(parser, 0, sizeof(*parser));
 
 	parser->buffer = kmalloc(size, GFP_KERNEL);
@@ -4697,18 +4705,19 @@  static const char readme_msg[] =
 	"\t    trigger will be the same as any other instance having the\n"
 	"\t    same name.  The default format used to display a given field\n"
 	"\t    can be modified by appending any of the following modifiers\n"
 	"\t    to the field name, as applicable:\n\n"
 	"\t            .hex        display a number as a hex value\n"
 	"\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"
 	"\t    restart a paused hist trigger.\n\n"
 	"\t    The 'clear' parameter will clear the contents of a running\n"
 	"\t    hist trigger and leave its current paused/active state\n"
 	"\t    unchanged.\n\n"
 	"\t    The enable_hist and disable_hist triggers can be used to\n"
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 5f1d4ae5..a94cc69b 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -284,16 +284,18 @@  extern struct list_head ftrace_trace_arrays;
 
 extern struct mutex trace_types_lock;
 
 extern int trace_array_get(struct trace_array *tr);
 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.
  */
 static inline struct trace_array *top_trace_array(void)
 {
 	struct trace_array *tr;
 
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 77ebe6b4..7f5f0b8f 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -85,22 +85,16 @@  static u64 hist_field_log2(struct hist_field *hist_field, void *event,
 {
 	struct hist_field *operand = hist_field->operands[0];
 
 	u64 val = operand->fn(operand, event, rbe);
 
 	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,			\
 				     struct ring_buffer_event *rbe)	\
 {									\
 	type *addr = (type *)(event + hist_field->field->offset);	\
 									\
 	return (u64)(unsigned long)*addr;				\
@@ -138,26 +132,28 @@  enum hist_field_flags {
 	HIST_FIELD_FL_HEX		= 1 << 3,
 	HIST_FIELD_FL_SYM		= 1 << 4,
 	HIST_FIELD_FL_SYM_OFFSET	= 1 << 5,
 	HIST_FIELD_FL_EXECNAME		= 1 << 6,
 	HIST_FIELD_FL_SYSCALL		= 1 << 7,
 	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 {
 	char		*keys_str;
 	char		*vals_str;
 	char		*sort_key_str;
 	char		*name;
 	bool		pause;
 	bool		cont;
 	bool		clear;
+	bool		ts_in_usecs;
 	unsigned int	map_bits;
 };
 
 struct hist_trigger_data {
 	struct hist_field               *fields[TRACING_MAP_FIELDS_MAX];
 	unsigned int			n_vals;
 	unsigned int			n_keys;
 	unsigned int			n_fields;
@@ -165,16 +161,30 @@  struct hist_trigger_data {
 	struct tracing_map_sort_key	sort_keys[TRACING_MAP_SORT_KEYS_MAX];
 	unsigned int			n_sort_keys;
 	struct trace_event_file		*event_file;
 	struct hist_trigger_attrs	*attrs;
 	struct tracing_map		*map;
 	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)
 {
 	const char *field_name = "";
 
 	if (level > 1)
 		return field_name;
 
@@ -629,25 +639,29 @@  static int create_key_field(struct hist_trigger_data *hist_data,
 				flags |= HIST_FIELD_FL_SYM_OFFSET;
 			else if ((strcmp(field_str, "execname") == 0) &&
 				 (strcmp(field_name, "common_pid") == 0))
 				flags |= HIST_FIELD_FL_EXECNAME;
 			else if (strcmp(field_str, "syscall") == 0)
 				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;
 			}
 		}
 
 		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);
 			if (!field || !field->size) {
 				ret = -EINVAL;
 				goto out;
 			}
 
@@ -1236,16 +1250,18 @@  static const char *get_hist_field_flags(struct hist_field *hist_field)
 	else if (hist_field->flags & HIST_FIELD_FL_SYM_OFFSET)
 		flags_str = "sym-offset";
 	else if (hist_field->flags & HIST_FIELD_FL_EXECNAME)
 		flags_str = "execname";
 	else if (hist_field->flags & HIST_FIELD_FL_SYSCALL)
 		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;
 }
 
 static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
 {
 	const char *field_name = hist_field_name(hist_field, 0);