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

Commit 8be0709f authored by David Sharp's avatar David Sharp Committed by Steven Rostedt
Browse files

tracing: Format non-nanosec times from tsc clock without a decimal point. 

With the addition of the "tsc" clock, formatting timestamps to look like
fractional seconds is misleading. Mark clocks as either in nanoseconds or
not, and format non-nanosecond timestamps as decimal integers.

Tested:
$ cd /sys/kernel/debug/tracing/
$ cat trace_clock
[local] global tsc
$ echo sched_switch > set_event
$ echo 1 > tracing_on ; sleep 0.0005 ; echo 0 > tracing_on
$ cat trace
          <idle>-0     [000]  6330.555552: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120
           sleep-29964 [000]  6330.555628: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
  ...
$ echo 1 > options/latency-format
$ cat trace
  <idle>-0       0 4104553247us+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=29964 next_prio=120
   sleep-29964   0 4104553322us+: sched_switch: prev_comm=bash prev_pid=29964 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
  ...
$ echo tsc > trace_clock
$ cat trace
$ echo 1 > tracing_on ; sleep 0.0005 ; echo 0 > tracing_on
$ echo 0 > options/latency-format
$ cat trace
          <idle>-0     [000] 16490053398357: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120
           sleep-31128 [000] 16490053588518: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
  ...
echo 1 > options/latency-format
$ cat trace
  <idle>-0       0 91557653238+: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=bash next_pid=31128 next_prio=120
   sleep-31128   0 91557843399+: sched_switch: prev_comm=bash prev_pid=31128 prev_prio=120 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
  ...

v2:
Move arch-specific bits out of generic code.
v4:
Fix x86_32 build due to 64-bit division.

Google-Bug-Id: 6980623
Link: http://lkml.kernel.org/r/1352837903-32191-2-git-send-email-dhsharp@google.com



Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
Signed-off-by: default avatarDavid Sharp <dhsharp@google.com>
Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
parent 8cbd9cc6

arch/x86/include/asm/trace_clock.h

+1 −1
Original line number Diff line number Diff line
@@ -9,7 +9,7 @@ 
extern u64 notrace trace_clock_x86_tsc(void);



# define ARCH_TRACE_CLOCKS \

	{ trace_clock_x86_tsc,	"x86-tsc" },

	{ trace_clock_x86_tsc,	"x86-tsc",	.in_ns = 0 },



#else /* !CONFIG_X86_TSC */

include/linux/ftrace_event.h

+6 −0
Original line number Diff line number Diff line
@@ -86,6 +86,12 @@ struct trace_iterator { 
	cpumask_var_t		started;

};



enum trace_iter_flags {

	TRACE_FILE_LAT_FMT	= 1,

	TRACE_FILE_ANNOTATE	= 2,

	TRACE_FILE_TIME_IN_NS	= 4,

};





struct trace_event;

kernel/trace/trace.c

+12 −3
Original line number Diff line number Diff line
@@ -484,10 +484,11 @@ static const char *trace_options[] = { 
static struct {

	u64 (*func)(void);

	const char *name;

	int in_ns;		/* is this clock in nanoseconds? */

} trace_clocks[] = {

	{ trace_clock_local,	"local" },

	{ trace_clock_global,	"global" },

	{ trace_clock_counter,	"counter" },

	{ trace_clock_local,	"local",	1 },

	{ trace_clock_global,	"global",	1 },

	{ trace_clock_counter,	"counter",	0 },

	ARCH_TRACE_CLOCKS

};
@@ -2478,6 +2479,10 @@ __tracing_open(struct inode *inode, struct file *file) 
	if (ring_buffer_overruns(iter->tr->buffer))

		iter->iter_flags |= TRACE_FILE_ANNOTATE;



	/* Output in nanoseconds only if we are using a clock in nanoseconds. */

	if (trace_clocks[trace_clock_id].in_ns)

		iter->iter_flags |= TRACE_FILE_TIME_IN_NS;



	/* stop the trace while dumping */

	tracing_stop();
@@ -3339,6 +3344,10 @@ static int tracing_open_pipe(struct inode *inode, struct file *filp) 
	if (trace_flags & TRACE_ITER_LATENCY_FMT)

		iter->iter_flags |= TRACE_FILE_LAT_FMT;



	/* Output in nanoseconds only if we are using a clock in nanoseconds. */

	if (trace_clocks[trace_clock_id].in_ns)

		iter->iter_flags |= TRACE_FILE_TIME_IN_NS;



	iter->cpu_file = cpu_file;

	iter->tr = &global_trace;

	mutex_init(&iter->mutex);

kernel/trace/trace.h

+0 −4
Original line number Diff line number Diff line
@@ -406,10 +406,6 @@ void tracing_stop_sched_switch_record(void); 
void tracing_start_sched_switch_record(void);

int register_tracer(struct tracer *type);

int is_tracing_stopped(void);

enum trace_file_type {

	TRACE_FILE_LAT_FMT	= 1,

	TRACE_FILE_ANNOTATE	= 2,

};



extern cpumask_var_t __read_mostly tracing_buffer_mask;

kernel/trace/trace_output.c

+53 −25
Original line number Diff line number Diff line
@@ -610,24 +610,54 @@ lat_print_generic(struct trace_seq *s, struct trace_entry *entry, int cpu) 
	return trace_print_lat_fmt(s, entry);

}



static unsigned long preempt_mark_thresh = 100;

static unsigned long preempt_mark_thresh_us = 100;



static int

lat_print_timestamp(struct trace_seq *s, u64 abs_usecs,

		    unsigned long rel_usecs)

lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)

{

	return trace_seq_printf(s, " %4lldus%c: ", abs_usecs,

				rel_usecs > preempt_mark_thresh ? '!' :

				  rel_usecs > 1 ? '+' : ' ');

	unsigned long verbose = trace_flags & TRACE_ITER_VERBOSE;

	unsigned long in_ns = iter->iter_flags & TRACE_FILE_TIME_IN_NS;

	unsigned long long abs_ts = iter->ts - iter->tr->time_start;

	unsigned long long rel_ts = next_ts - iter->ts;

	struct trace_seq *s = &iter->seq;



	if (in_ns) {

		abs_ts = ns2usecs(abs_ts);

		rel_ts = ns2usecs(rel_ts);

	}



	if (verbose && in_ns) {

		unsigned long abs_usec = do_div(abs_ts, USEC_PER_MSEC);

		unsigned long abs_msec = (unsigned long)abs_ts;

		unsigned long rel_usec = do_div(rel_ts, USEC_PER_MSEC);

		unsigned long rel_msec = (unsigned long)rel_ts;



		return trace_seq_printf(

				s, "[%08llx] %ld.%03ldms (+%ld.%03ldms): ",

				ns2usecs(iter->ts),

				abs_msec, abs_usec,

				rel_msec, rel_usec);

	} else if (verbose && !in_ns) {

		return trace_seq_printf(

				s, "[%016llx] %lld (+%lld): ",

				iter->ts, abs_ts, rel_ts);

	} else if (!verbose && in_ns) {

		return trace_seq_printf(

				s, " %4lldus%c: ",

				abs_ts,

				rel_ts > preempt_mark_thresh_us ? '!' :

				  rel_ts > 1 ? '+' : ' ');

	} else { /* !verbose && !in_ns */

		return trace_seq_printf(s, " %4lld: ", abs_ts);

	}

}



int trace_print_context(struct trace_iterator *iter)

{

	struct trace_seq *s = &iter->seq;

	struct trace_entry *entry = iter->ent;

	unsigned long long t = ns2usecs(iter->ts);

	unsigned long usec_rem = do_div(t, USEC_PER_SEC);

	unsigned long secs = (unsigned long)t;

	unsigned long long t;

	unsigned long secs, usec_rem;

	char comm[TASK_COMM_LEN];

	int ret;
@@ -644,8 +674,13 @@ int trace_print_context(struct trace_iterator *iter) 
			return 0;

	}



	return trace_seq_printf(s, " %5lu.%06lu: ",

				secs, usec_rem);

	if (iter->iter_flags & TRACE_FILE_TIME_IN_NS) {

		t = ns2usecs(iter->ts);

		usec_rem = do_div(t, USEC_PER_SEC);

		secs = (unsigned long)t;

		return trace_seq_printf(s, " %5lu.%06lu: ", secs, usec_rem);

	} else

		return trace_seq_printf(s, " %12llu: ", iter->ts);

}



int trace_print_lat_context(struct trace_iterator *iter)
@@ -659,36 +694,29 @@ int trace_print_lat_context(struct trace_iterator *iter) 
			   *next_entry = trace_find_next_entry(iter, NULL,

							       &next_ts);

	unsigned long verbose = (trace_flags & TRACE_ITER_VERBOSE);

	unsigned long abs_usecs = ns2usecs(iter->ts - iter->tr->time_start);

	unsigned long rel_usecs;



	/* Restore the original ent_size */

	iter->ent_size = ent_size;



	if (!next_entry)

		next_ts = iter->ts;

	rel_usecs = ns2usecs(next_ts - iter->ts);



	if (verbose) {

		char comm[TASK_COMM_LEN];



		trace_find_cmdline(entry->pid, comm);



		ret = trace_seq_printf(s, "%16s %5d %3d %d %08x %08lx [%08llx]"

				       " %ld.%03ldms (+%ld.%03ldms): ", comm,

				       entry->pid, iter->cpu, entry->flags,

				       entry->preempt_count, iter->idx,

				       ns2usecs(iter->ts),

				       abs_usecs / USEC_PER_MSEC,

				       abs_usecs % USEC_PER_MSEC,

				       rel_usecs / USEC_PER_MSEC,

				       rel_usecs % USEC_PER_MSEC);

		ret = trace_seq_printf(

				s, "%16s %5d %3d %d %08x %08lx ",

				comm, entry->pid, iter->cpu, entry->flags,

				entry->preempt_count, iter->idx);

	} else {

		ret = lat_print_generic(s, entry, iter->cpu);

		if (ret)

			ret = lat_print_timestamp(s, abs_usecs, rel_usecs);

	}



	if (ret)

		ret = lat_print_timestamp(iter, next_ts);



	return ret;

}