[PATCH 0/2] tracing, function_graph: signaling very large function execution time

[PATCH 0/2] tracing, function_graph: signaling very large function execution time

[byungchul.park]

From: Byungchul Park <byungchul.park@lge.com>

Hello.

When I analysis the exit_mm() function to find out the reason why the
function spends much time occasionally, this patch was very useful.
I thought this patch cannot be useful only for me, but can be also
useful for anybody who want to be signaled for very large function
execution time, so I decided to submit this patchset.

Is there anybody who have such a demand? :)

Thanks,
Byungchul.

Byungchul Park (2):
  tracing, function_graph: fix micro seconds notation in comment
  tracing, function_graph: add additional marks to signal very large
    function execution time

 kernel/trace/trace_functions_graph.c |   12 +++++++++---
 1 file changed, 9 insertions(+), 3 deletions(-)

-- 
1.7.9.5

[PATCH 1/2] tracing, function_graph: fix micro seconds notation in comment

[byungchul.park]

From: Byungchul Park <byungchul.park@lge.com>

Usually, "msecs" notation means milli-seconds, and "usecs" notation
means micro-seconds. Since the unit used in the code is
micro-seconds, the notation should be replaced from msecs to usecs.
This confusing notation prevents us from understanding the code
correctly.

Signed-off-by: Byungchul Park <byungchul.park@lge.com>
---
 kernel/trace/trace_functions_graph.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index f0a0c98..c18a1e3 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -822,10 +822,10 @@ 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 100 msecs */
+		/* Duration exceeded 100 usecs */
 		if (duration > 100000ULL)
 			ret = trace_seq_puts(s, "! ");
-		/* Duration exceeded 10 msecs */
+		/* Duration exceeded 10 usecs */
 		else if (duration > 10000ULL)
 			ret = trace_seq_puts(s, "+ ");
 	}
-- 
1.7.9.5

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

[byungchul.park]

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 */

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)
-- 
1.7.9.5

Re: [PATCH 1/2] tracing, function_graph: fix micro seconds notation in comment

[Namhyung Kim]

Hi Byungchul,

On Thu, 23 Oct 2014 17:17:21 +0900, byungchul park wrote:
> From: Byungchul Park <byungchul.park@lge.com>
>
> Usually, "msecs" notation means milli-seconds, and "usecs" notation
> means micro-seconds. Since the unit used in the code is
> micro-seconds, the notation should be replaced from msecs to usecs.
> This confusing notation prevents us from understanding the code
> correctly.
>
> Signed-off-by: Byungchul Park <byungchul.park@lge.com>
> ---
>  kernel/trace/trace_functions_graph.c |    4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index f0a0c98..c18a1e3 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -822,10 +822,10 @@ 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 100 msecs */
> +		/* Duration exceeded 100 usecs */
>  		if (duration > 100000ULL)
>  			ret = trace_seq_puts(s, "! ");
> -		/* Duration exceeded 10 msecs */
> +		/* Duration exceeded 10 usecs */
>  		else if (duration > 10000ULL)

I thought the duration was in usec, but it seems not, it's in nsec, hmm.
Then this exceeding 10/100 usec is not meaningful - what about increaing
numbers in the conditional so that it can match to the comment?  That
will eliminate the need of the patch 2.

Also I think msecs_str in trace_print_graph_duration() should be renamed
to usecs_str.

Thanks,
Namhyung


>  			ret = trace_seq_puts(s, "+ ");
>  	}

Re: [PATCH 1/2] tracing, function_graph: fix micro seconds notation in comment

[Byungchul Park]

On Fri, Oct 24, 2014 at 09:20:11AM +0900, Namhyung Kim wrote:
> Hi Byungchul,
> 
> On Thu, 23 Oct 2014 17:17:21 +0900, byungchul park wrote:
> > From: Byungchul Park <byungchul.park@lge.com>
> >
> > Usually, "msecs" notation means milli-seconds, and "usecs" notation
> > means micro-seconds. Since the unit used in the code is
> > micro-seconds, the notation should be replaced from msecs to usecs.
> > This confusing notation prevents us from understanding the code
> > correctly.
> >
> > Signed-off-by: Byungchul Park <byungchul.park@lge.com>
> > ---
> >  kernel/trace/trace_functions_graph.c |    4 ++--
> >  1 file changed, 2 insertions(+), 2 deletions(-)
> >
> > diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> > index f0a0c98..c18a1e3 100644
> > --- a/kernel/trace/trace_functions_graph.c
> > +++ b/kernel/trace/trace_functions_graph.c
> > @@ -822,10 +822,10 @@ 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 100 msecs */
> > +		/* Duration exceeded 100 usecs */
> >  		if (duration > 100000ULL)
> >  			ret = trace_seq_puts(s, "! ");
> > -		/* Duration exceeded 10 msecs */
> > +		/* Duration exceeded 10 usecs */
> >  		else if (duration > 10000ULL)
> 
> I thought the duration was in usec, but it seems not, it's in nsec, hmm.
> Then this exceeding 10/100 usec is not meaningful - what about increaing
> numbers in the conditional so that it can match to the comment?  That
> will eliminate the need of the patch 2.

The approach you suggested also looks good to me. But I just wonder if it
would be ok even if it changes meaning of the marks, "!", "+", because the
marks have used with the meaning of exceeding 10/100 usec until now.

Isn't there anything wrong with increasing numbers in the conditions? :)

> 
> Also I think msecs_str in trace_print_graph_duration() should be renamed
> to usecs_str.

I agree. It should be also renamed. Such words made me hard to understand
the code correctly. :(

> 
> Thanks,
> Namhyung
> 
> 
> >  			ret = trace_seq_puts(s, "+ ");
> >  	}
> --
> 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/

Re: [PATCH 1/2] tracing, function_graph: fix micro seconds notation in comment

[Steven Rostedt]

On Fri, 24 Oct 2014 10:07:42 +0900
Byungchul Park <byungchul.park@lge.com> wrote:

 
> > >  	/* Signal a overhead of time execution to the output */
> > >  	if (flags & TRACE_GRAPH_PRINT_OVERHEAD) {
> > > -		/* Duration exceeded 100 msecs */
> > > +		/* Duration exceeded 100 usecs */
> > >  		if (duration > 100000ULL)
> > >  			ret = trace_seq_puts(s, "! ");
> > > -		/* Duration exceeded 10 msecs */
> > > +		/* Duration exceeded 10 usecs */
> > >  		else if (duration > 10000ULL)
> > 
> > I thought the duration was in usec, but it seems not, it's in nsec, hmm.
> > Then this exceeding 10/100 usec is not meaningful - what about increaing
> > numbers in the conditional so that it can match to the comment?  That
> > will eliminate the need of the patch 2.

No, please keep this to 10/100 usecs. I do analyze functions that take
that little of time.

> 
> The approach you suggested also looks good to me. But I just wonder if it
> would be ok even if it changes meaning of the marks, "!", "+", because the
> marks have used with the meaning of exceeding 10/100 usec until now.
> 
> Isn't there anything wrong with increasing numbers in the conditions? :)
> 
> > 
> > Also I think msecs_str in trace_print_graph_duration() should be renamed
> > to usecs_str.
> 
> I agree. It should be also renamed. Such words made me hard to understand
> the code correctly. :(
> 

Yeah, this code has been here forever. It came from the original
latency-tracer in the -rt patch. I was so use to calling 'msecs' as
microseconds in this code, that I didn't realize the problem ;-)

Anyway, feel free to resend this patch fixing the msecs_str.

Thanks!

-- Steve


> > 
> > Thanks,
> > Namhyung
> > 
> > 
> > >  			ret = trace_seq_puts(s, "+ ");
> > >  	}
> > --
> > 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/

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

[Steven Rostedt]

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.

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

But perhaps have:

 + == > 10usec
 ! == > 100usec
 * == > 1msec
 $ == > 1sec


> 
> 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.

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.

Thanks!

-- Steve

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

[Steven Rostedt]

BTW, what is this vanilla@blackduck.lge.com address? It prevents
claws-mail from sending my email.

If it is some internal mailing list at lge, please 'bcc' it so that it
doesn't cause problems for those in the public mailing lists replying
to you.

Thanks,

-- Steve

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

[Byungchul Park]

Hello,

On Fri, Oct 31, 2014 at 01:04:49PM -0400, Steven Rostedt wrote:
> BTW, what is this vanilla@blackduck.lge.com address? It prevents
> claws-mail from sending my email.
> 
> If it is some internal mailing list at lge, please 'bcc' it so that it
> doesn't cause problems for those in the public mailing lists replying
> to you.

Thank you very much for informing.

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/

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

[Byungchul Park]

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/