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

Commit 166d3c79 authored by Frederic Weisbecker's avatar Frederic Weisbecker Committed by Ingo Molnar
Browse files

tracing/function-graph-tracer: improve duration output 



Impact: better trace output of duration for long calls

The old duration output didn't exceeded 9999.999 us to fit the column
and the nanosecs were always 3 numbers. As Ingo suggested, it's better
to have the whole microseconds elapsed time and shift the nanosecs precision
if needed to fit the maximum 7 numbers. And usec need more number, the case
should be rare and important enough to break a bit the column alignment to
show it.

So, depending of the duration value, we now have these patterns:

    u.nnn us
   uu.nnn us
  uuu.nnn us
 uuuu.nnn us
 uuuuu.nn us
 uuuuuu.n us
 uuuuuuuu..... us

Signed-off-by: default avatarFrederic Weisbecker <fweisbec@gmail.com>
Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
parent 11e84acc

kernel/trace/trace_functions_graph.c

+43 −12
Original line number Diff line number Diff line
@@ -232,11 +232,50 @@ trace_branch_is_leaf(struct trace_iterator *iter, 
}





static inline int

static enum print_line_t

print_graph_duration(unsigned long long duration, struct trace_seq *s)

{

	unsigned long nsecs_rem = do_div(duration, 1000);

	return trace_seq_printf(s, "%4llu.%3lu us |  ", duration, nsecs_rem);

	/* log10(ULONG_MAX) + '\0' */

	char msecs_str[21];

	char nsecs_str[5];

	int ret, len;

	int i;



	sprintf(msecs_str, "%lu", (unsigned long) duration);



	/* Print msecs */

	ret = trace_seq_printf(s, msecs_str);

	if (!ret)

		return TRACE_TYPE_PARTIAL_LINE;



	len = strlen(msecs_str);



	/* Print nsecs (we don't want to exceed 7 numbers) */

	if (len < 7) {

		snprintf(nsecs_str, 8 - len, "%03lu", nsecs_rem);

		ret = trace_seq_printf(s, ".%s", nsecs_str);

		if (!ret)

			return TRACE_TYPE_PARTIAL_LINE;

		len += strlen(nsecs_str);

	}



	ret = trace_seq_printf(s, " us ");

	if (!ret)

		return TRACE_TYPE_PARTIAL_LINE;



	/* Print remaining spaces to fit the row's width */

	for (i = len; i < 7; i++) {

		ret = trace_seq_printf(s, " ");

		if (!ret)

			return TRACE_TYPE_PARTIAL_LINE;

	}



	ret = trace_seq_printf(s, "|  ");

	if (!ret)

		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;



}



/* Signal a overhead of time execution to the output */
@@ -273,10 +312,6 @@ print_graph_entry_leaf(struct trace_iterator *iter, 
	call = &entry->graph_ent;

	duration = graph_ret->rettime - graph_ret->calltime;



	/* Must not exceed 8 characters: 9999.999 us */

	if (duration > 10000000ULL)

		duration = 9999999ULL;



	/* Overhead */

	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {

		ret = print_graph_overhead(duration, s);
@@ -286,7 +321,7 @@ print_graph_entry_leaf(struct trace_iterator *iter, 


	/* Duration */

	ret = print_graph_duration(duration, s);

	if (!ret)

	if (ret == TRACE_TYPE_PARTIAL_LINE)

		return TRACE_TYPE_PARTIAL_LINE;



	/* Function */
@@ -387,10 +422,6 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s, 
	int ret;

	unsigned long long duration = trace->rettime - trace->calltime;



	/* Must not exceed 8 characters: xxxx.yyy us */

	if (duration > 10000000ULL)

		duration = 9999999ULL;



	/* Pid */

	if (verif_pid(s, ent->pid, cpu) == TRACE_TYPE_PARTIAL_LINE)

		return TRACE_TYPE_PARTIAL_LINE;
@@ -422,7 +453,7 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s, 


	/* Duration */

	ret = print_graph_duration(duration, s);

	if (!ret)

	if (ret == TRACE_TYPE_PARTIAL_LINE)

		return TRACE_TYPE_PARTIAL_LINE;



	/* Closing brace */