lkml.org 
[lkml]   [2014]   [Nov]   [2]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH 2/2] tracing, function_graph: add additional marks to signal very large function execution time
Hello,

On Fri, Oct 31, 2014 at 01:01:29PM -0400, Steven Rostedt wrote:
> On Thu, 23 Oct 2014 17:17:22 +0900
> byungchul.park@lge.com wrote:
>
> > From: Byungchul Park <byungchul.park@lge.com>
> >
> > 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 */
>
> Hmm, I wonder if a "s!" is better. Having the 's' next to the number
> seems to make it look like some strange number.

Yes, what you suggest looks better.

>
> Maybe we should still keep this cryptic. We can update the
> debugfs/tracing/README to add the meanings as well.

I missed updating document, it should be done, and I will add it.

>
> But perhaps have:
>
> + == > 10usec
> ! == > 100usec
> * == > 1msec
> $ == > 1sec
>

To be honest, this is what I did at first implementation and I changed it
to inform the scale like s(=second) or like m(=millisecond). Do you think
'+' '!' '*' '$' notation is better? :)

>
> >
> > 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@lge.com>
> > ---
> > 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)
>
> also, the documentation in Documentation/trace/ftrace.txt must be
> updated with this patch. Make sure you update the function graph part
> and not the "time:" and "delay:" section.

OK. I will do it.

>
> Come to think of it. Could you make another patch that adds this to the
> normal delay as well? And we should make the "normal" '+' mean 10usecs
> instead of 1usec. 1 is rather meaningless and inconsistent with the
> graph tracer.

Why not? I will try it.

Thanks,
Byungchul.

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


\
 
 \ /
  Last update: 2014-11-03 02:21    [W:1.687 / U:0.020 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site