[PATCH 2/2] tracing, function_graph: add additional marks to signal very large function execution time

From: byungchul . park
Date: Thu Oct 23 2014 - 04:18:01 EST


From: Byungchul Park <byungchul.park@xxxxxxx>

Currently, function graph tracer prints "!" or "+" just before
function execution time to signal a function overhead, depending
on the time. Even it is usually enough to do that, we sometimes
need to be signaled for bigger execution time than 100 micro seconds.

For example, I used function graph tracer to detect if there is
any case that exit_mm() takes too much time. I did following steps
in /sys/kernel/debug/tracing. It was easier to detect very big
excution time with patched kernel than with original kernel.

$ echo exit_mm > set_graph_function
$ echo function_graph > current_tracer
$ echo > trace
$ cat trace_pipe > $LOGFILE
... (do something and terminate logging)
$ grep "!s" $LOGFILE
3) !s22082032 us | } /* kernel_map_pages */
3) !s22082040 us | } /* free_pages_prepare */
3) !s22082113 us | } /* free_hot_cold_page */
3) !s22083455 us | } /* free_hot_cold_page_list */
3) !s22083895 us | } /* release_pages */
3) !s22177873 us | } /* free_pages_and_swap_cache */
3) !s22178929 us | } /* unmap_single_vma */
3) !s22198885 us | } /* unmap_vmas */
3) !s22206949 us | } /* exit_mmap */
3) !s22207659 us | } /* mmput */
3) !s22207793 us | } /* exit_mm */

And then, it was easy to find out that a schedule-out occured by
sub_preempt_count() within kernel_map_pages().

To detect very large function exection time either by problematic
function implementation or by scheduling issues, this patch can be
useful.

Signed-off-by: Byungchul Park <byungchul.park@xxxxxxx>
---
kernel/trace/trace_functions_graph.c | 8 +++++++-
1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index c18a1e3..ea8b7e7 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -822,8 +822,14 @@ print_graph_duration(unsigned long long duration, struct trace_seq *s,

/* Signal a overhead of time execution to the output */
if (flags & TRACE_GRAPH_PRINT_OVERHEAD) {
+ /* Duration exceeded 1 secs */
+ if (duration > 1000000000ULL)
+ ret = trace_seq_puts(s, "!s");
+ /* Duration exceeded 1 msecs */
+ else if (duration > 1000000ULL)
+ ret = trace_seq_puts(s, "!m");
/* Duration exceeded 100 usecs */
- if (duration > 100000ULL)
+ else if (duration > 100000ULL)
ret = trace_seq_puts(s, "! ");
/* Duration exceeded 10 usecs */
else if (duration > 10000ULL)
--
1.7.9.5

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/