mirror of https://lore.kernel.org/lkml/
 help / color / mirror / Atom feed
* [PATCH v2 0/3] tracing: signaling large duration and delay
@ 2014-11-05  7:18 byungchul.park
  2014-11-05  7:18 ` [PATCH v2 1/3] tracing, function_graph: fix micro seconds notation in comment byungchul.park
                   ` (2 more replies)
  0 siblings, 3 replies; 9+ messages in thread
From: byungchul.park @ 2014-11-05  7:18 UTC (permalink / raw)
  To: rostedt, mingo; +Cc: linux-kernel, seungho1.park, jolsa, Byungchul Park

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

Changes from v1 to v2
* update Document/trace/ftrace.txt
* seperate the implementation as a macro
* apply the implementation to delay printing, too

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.

Nobody who have such a demand? :)

Thanks,
Byungchul.

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

 Documentation/trace/ftrace.txt       |   10 +++++++---
 kernel/trace/trace.h                 |   14 ++++++++++++++
 kernel/trace/trace_functions_graph.c |   23 +++++++++++++----------
 kernel/trace/trace_output.c          |   15 ++++++++++-----
 4 files changed, 44 insertions(+), 18 deletions(-)

-- 
1.7.9.5


^ permalink raw reply	[flat|nested] 9+ messages in thread

* [PATCH v2 1/3] tracing, function_graph: fix micro seconds notation in comment
  2014-11-05  7:18 [PATCH v2 0/3] tracing: signaling large duration and delay byungchul.park
@ 2014-11-05  7:18 ` byungchul.park
  2014-11-14  3:32   ` Steven Rostedt
  2014-11-05  7:18 ` [PATCH v2 2/3] tracing, function_graph: add additional marks to signal very large function execution time byungchul.park
  2014-11-05  7:18 ` [PATCH v2 3/3] tracing: add additional marks to signal very large delay byungchul.park
  2 siblings, 1 reply; 9+ messages in thread
From: byungchul.park @ 2014-11-05  7:18 UTC (permalink / raw)
  To: rostedt, mingo; +Cc: linux-kernel, seungho1.park, jolsa, 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.

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

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index f0a0c98..cb33f46 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -759,19 +759,19 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
 {
 	unsigned long nsecs_rem = do_div(duration, 1000);
 	/* log10(ULONG_MAX) + '\0' */
-	char msecs_str[21];
+	char usecs_str[21];
 	char nsecs_str[5];
 	int ret, len;
 	int i;
 
-	sprintf(msecs_str, "%lu", (unsigned long) duration);
+	sprintf(usecs_str, "%lu", (unsigned long) duration);
 
 	/* Print msecs */
-	ret = trace_seq_printf(s, "%s", msecs_str);
+	ret = trace_seq_printf(s, "%s", usecs_str);
 	if (!ret)
 		return TRACE_TYPE_PARTIAL_LINE;
 
-	len = strlen(msecs_str);
+	len = strlen(usecs_str);
 
 	/* Print nsecs (we don't want to exceed 7 numbers) */
 	if (len < 7) {
@@ -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


^ permalink raw reply	[flat|nested] 9+ messages in thread

* [PATCH v2 2/3] tracing, function_graph: add additional marks to signal very large function execution time
  2014-11-05  7:18 [PATCH v2 0/3] tracing: signaling large duration and delay byungchul.park
  2014-11-05  7:18 ` [PATCH v2 1/3] tracing, function_graph: fix micro seconds notation in comment byungchul.park
@ 2014-11-05  7:18 ` byungchul.park
  2014-11-14  3:32   ` Steven Rostedt
  2014-11-05  7:18 ` [PATCH v2 3/3] tracing: add additional marks to signal very large delay byungchul.park
  2 siblings, 1 reply; 9+ messages in thread
From: byungchul.park @ 2014-11-05  7:18 UTC (permalink / raw)
  To: rostedt, mingo; +Cc: linux-kernel, seungho1.park, jolsa, 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 "\\$" $LOGFILE
 3) $ 22082032 us |                      } /* kernel_map_pages */
 3) $ 22082040 us |                    } /* free_pages_prepare */
 3) $ 22082113 us |                  } /* free_hot_cold_page */
 3) $ 22083455 us |                } /* free_hot_cold_page_list */
 3) $ 22083895 us |              } /* release_pages */
 3) $ 22177873 us |            } /* free_pages_and_swap_cache */
 3) $ 22178929 us |          } /* unmap_single_vma */
 3) $ 22198885 us |        } /* unmap_vmas */
 3) $ 22206949 us |      } /* exit_mmap */
 3) $ 22207659 us |    } /* mmput */
 3) $ 22207793 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 caused by either problematic
function implementation or scheduling issues, this patch can be useful.

Signed-off-by: Byungchul Park <byungchul.park@lge.com>
---
 Documentation/trace/ftrace.txt       |    2 ++
 kernel/trace/trace.h                 |   14 ++++++++++++++
 kernel/trace/trace_functions_graph.c |   15 +++++++++------
 3 files changed, 25 insertions(+), 6 deletions(-)

diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
index 4da4261..f827e2f 100644
--- a/Documentation/trace/ftrace.txt
+++ b/Documentation/trace/ftrace.txt
@@ -1951,6 +1951,8 @@ want, depending on your needs.
 
   + means that the function exceeded 10 usecs.
   ! means that the function exceeded 100 usecs.
+  # means that the function exceeded 1000 usecs.
+  $ means that the function exceeded 1 sec.
 
 
 - The task/pid field displays the thread cmdline and pid which
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 385391f..4b7252a 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -331,6 +331,20 @@ struct tracer_flags {
 /* Makes more easy to define a tracer opt */
 #define TRACER_OPT(s, b)	.name = #s, .bit = b
 
+/* trace overhead mark */
+struct trace_mark {
+	unsigned long long val; /* unit: nsec */
+	char sym;
+};
+
+#define DEFINE_MARK_STRUCT static const struct trace_mark mark[]
+#define DEFINE_MARK(v, s) {.val = v, .sym = s}
+#define MARK(d) 							\
+({									\
+	int i = ARRAY_SIZE(mark);					\
+	while ((unsigned long long)(d) <= mark[--i].val && i > 0);	\
+	mark[i].sym;							\
+})
 
 /**
  * struct tracer - a specific tracer and its callbacks to interact with debugfs
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index cb33f46..8a62907 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -797,6 +797,14 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
 	return TRACE_TYPE_HANDLED;
 }
 
+DEFINE_MARK_STRUCT = {
+	DEFINE_MARK(0ULL		, ' '), /* 0 usecs */
+	DEFINE_MARK(10000ULL		, '+'), /* 10 usecs */
+	DEFINE_MARK(100000ULL		, '!'), /* 100 usecs */
+	DEFINE_MARK(1000000ULL		, '#'), /* 1000 usecs */
+	DEFINE_MARK(1000000000ULL	, '$'), /* 1 sec */
+};
+
 static enum print_line_t
 print_graph_duration(unsigned long long duration, struct trace_seq *s,
 		     u32 flags)
@@ -822,12 +830,7 @@ 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 usecs */
-		if (duration > 100000ULL)
-			ret = trace_seq_puts(s, "! ");
-		/* Duration exceeded 10 usecs */
-		else if (duration > 10000ULL)
-			ret = trace_seq_puts(s, "+ ");
+		ret = trace_seq_printf(s, "%c ", MARK(duration));
 	}
 
 	/*
-- 
1.7.9.5


^ permalink raw reply	[flat|nested] 9+ messages in thread

* [PATCH v2 3/3] tracing: add additional marks to signal very large delay
  2014-11-05  7:18 [PATCH v2 0/3] tracing: signaling large duration and delay byungchul.park
  2014-11-05  7:18 ` [PATCH v2 1/3] tracing, function_graph: fix micro seconds notation in comment byungchul.park
  2014-11-05  7:18 ` [PATCH v2 2/3] tracing, function_graph: add additional marks to signal very large function execution time byungchul.park
@ 2014-11-05  7:18 ` byungchul.park
  2014-11-14  3:38   ` Steven Rostedt
  2 siblings, 1 reply; 9+ messages in thread
From: byungchul.park @ 2014-11-05  7:18 UTC (permalink / raw)
  To: rostedt, mingo; +Cc: linux-kernel, seungho1.park, jolsa, Byungchul Park

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

Currently, some tracers tracing latency print "!" or "+" just after time
to signal overhead, depending on the interval between events. Even it is
usually enough to do that, we sometimes need to be signaled for bigger
interval than 100 micro seconds.

Signed-off-by: Byungchul Park <byungchul.park@lge.com>
---
 Documentation/trace/ftrace.txt |    8 +++++---
 kernel/trace/trace_output.c    |   15 ++++++++++-----
 2 files changed, 15 insertions(+), 8 deletions(-)

diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
index f827e2f..64efb3e 100644
--- a/Documentation/trace/ftrace.txt
+++ b/Documentation/trace/ftrace.txt
@@ -680,9 +680,11 @@ The above is mostly meaningful for kernel developers.
 	 needs to be fixed to be only relative to the same CPU.
 	 The marks are determined by the difference between this
 	 current trace and the next trace.
-	  '!' - greater than preempt_mark_thresh (default 100)
-	  '+' - greater than 1 microsecond
-	  ' ' - less than or equal to 1 microsecond.
+	  '$' - greater than 1 second
+	  '#' - greater than 1000 microsecond
+	  '!' - greater than 100 microsecond
+	  '+' - greater than 10 microsecond
+	  ' ' - less than or equal to 10 microsecond.
 
   The rest is the same as the 'trace' file.
 
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index c6977d5..e63fac3 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -124,7 +124,7 @@ ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
 
 	if (ret == (const char *)(trace_seq_buffer_ptr(p)))
 		trace_seq_printf(p, "0x%lx", val);
-		
+
 	trace_seq_putc(p, 0);
 
 	return ret;
@@ -471,7 +471,13 @@ 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_us = 100;
+DEFINE_MARK_STRUCT = {
+	DEFINE_MARK(0ULL		, ' '), /* 0 usecs */
+	DEFINE_MARK(10000ULL		, '+'), /* 10 usecs */
+	DEFINE_MARK(100000ULL		, '!'), /* 100 usecs */
+	DEFINE_MARK(1000000ULL		, '#'), /* 1000 usecs */
+	DEFINE_MARK(1000000000ULL	, '$'), /* 1 sec */
+};
 
 static int
 lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
@@ -506,8 +512,7 @@ lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
 		return trace_seq_printf(
 				s, " %4lldus%c: ",
 				abs_ts,
-				rel_ts > preempt_mark_thresh_us ? '!' :
-				  rel_ts > 1 ? '+' : ' ');
+				MARK(rel_ts * NSEC_PER_USEC));
 	} else { /* !verbose && !in_ns */
 		return trace_seq_printf(s, " %4lld: ", abs_ts);
 	}
@@ -692,7 +697,7 @@ int register_ftrace_event(struct trace_event *event)
 				goto out;
 
 		} else {
-			
+
 			event->type = next_event_type++;
 			list = &ftrace_event_list;
 		}
-- 
1.7.9.5


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH v2 2/3] tracing, function_graph: add additional marks to signal very large function execution time
  2014-11-05  7:18 ` [PATCH v2 2/3] tracing, function_graph: add additional marks to signal very large function execution time byungchul.park
@ 2014-11-14  3:32   ` Steven Rostedt
  2014-11-14  6:18     ` Byungchul Park
  0 siblings, 1 reply; 9+ messages in thread
From: Steven Rostedt @ 2014-11-14  3:32 UTC (permalink / raw)
  To: byungchul.park; +Cc: mingo, linux-kernel, seungho1.park, jolsa

On Wed,  5 Nov 2014 16:18:45 +0900
byungchul.park@lge.com wrote:
  
> +/* trace overhead mark */
> +struct trace_mark {
> +	unsigned long long val; /* unit: nsec */
> +	char sym;
> +};

Please format the above to:

struct trace_mark {
	unsigned long long		val;
	char				sym;
};

> +
> +#define DEFINE_MARK_STRUCT static const struct trace_mark mark[]

Why is this a macro?

> +#define DEFINE_MARK(v, s) {.val = v, .sym = s}
> +#define MARK(d) 							\
> +({									\
> +	int i = ARRAY_SIZE(mark);					\
> +	while ((unsigned long long)(d) <= mark[--i].val && i > 0);	\
> +	mark[i].sym;							\
> +})

Why is this a macro and not a static inline?

static inline char find_trace_mark(unsigned long long duration)
{
	int i = ARRAY_SIZE(mark);

	while (duration <= mark[--i].val && i > 0)
		;

	return make[i]. sym;
}

That's much more readable.

>  
>  /**
>   * struct tracer - a specific tracer and its callbacks to interact with debugfs
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index cb33f46..8a62907 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -797,6 +797,14 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
>  	return TRACE_TYPE_HANDLED;
>  }
>  
> +DEFINE_MARK_STRUCT = {
> +	DEFINE_MARK(0ULL		, ' '), /* 0 usecs */
> +	DEFINE_MARK(10000ULL		, '+'), /* 10 usecs */
> +	DEFINE_MARK(100000ULL		, '!'), /* 100 usecs */
> +	DEFINE_MARK(1000000ULL		, '#'), /* 1000 usecs */
> +	DEFINE_MARK(1000000000ULL	, '$'), /* 1 sec */
> +};

Don't need to use a name as big as DEFINE_MARK. Just have:

#undef MARK
#define MARK(v, s) { .val = v, .sym = s }

struct trace_mark mark[] = {
	MARK(0ULL			, ' '), /* 0 usecs */
[...]
};

With the define directly above the call, we don't need need to be that
descriptive.

> +
>  static enum print_line_t
>  print_graph_duration(unsigned long long duration, struct trace_seq *s,
>  		     u32 flags)
> @@ -822,12 +830,7 @@ 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 usecs */
> -		if (duration > 100000ULL)
> -			ret = trace_seq_puts(s, "! ");
> -		/* Duration exceeded 10 usecs */
> -		else if (duration > 10000ULL)
> -			ret = trace_seq_puts(s, "+ ");
> +		ret = trace_seq_printf(s, "%c ", MARK(duration));

Then this could just be:

		ret = trace_seq_printf(s, "%c ",
				       find_trace_mark(duration));

-- Steve

>  	}
>  
>  	/*


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH v2 1/3] tracing, function_graph: fix micro seconds notation in comment
  2014-11-05  7:18 ` [PATCH v2 1/3] tracing, function_graph: fix micro seconds notation in comment byungchul.park
@ 2014-11-14  3:32   ` Steven Rostedt
  0 siblings, 0 replies; 9+ messages in thread
From: Steven Rostedt @ 2014-11-14  3:32 UTC (permalink / raw)
  To: byungchul.park; +Cc: mingo, linux-kernel, seungho1.park, jolsa

On Wed,  5 Nov 2014 16:18:44 +0900
byungchul.park@lge.com 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.
> 
> Signed-off-by: Byungchul Park <byungchul.park@lge.com>

This looks good. I pulled it into my queue.

Thanks!

-- Steve

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH v2 3/3] tracing: add additional marks to signal very large delay
  2014-11-05  7:18 ` [PATCH v2 3/3] tracing: add additional marks to signal very large delay byungchul.park
@ 2014-11-14  3:38   ` Steven Rostedt
  2014-11-14  6:22     ` Byungchul Park
  0 siblings, 1 reply; 9+ messages in thread
From: Steven Rostedt @ 2014-11-14  3:38 UTC (permalink / raw)
  To: byungchul.park; +Cc: mingo, linux-kernel, seungho1.park, jolsa

On Wed,  5 Nov 2014 16:18:46 +0900
byungchul.park@lge.com wrote:

> -static unsigned long preempt_mark_thresh_us = 100;
> +DEFINE_MARK_STRUCT = {
> +	DEFINE_MARK(0ULL		, ' '), /* 0 usecs */
> +	DEFINE_MARK(10000ULL		, '+'), /* 10 usecs */
> +	DEFINE_MARK(100000ULL		, '!'), /* 100 usecs */
> +	DEFINE_MARK(1000000ULL		, '#'), /* 1000 usecs */
> +	DEFINE_MARK(1000000000ULL	, '$'), /* 1 sec */
> +};

OK, I see why you did the macro magic here. But it's still obfuscates
the code.

Instead of having that find_trace_mark() be a static function, just
make it defined in trace_output.c that function_graph calls. This code
is used for outputting to userspace and a function call is not going to
be noticed.

As it would now be a global function (although only defined in
kernel/trace), we need to make the name a bit more specific. Instead of
calling it find_trace_mark(), call it trace_duration_mark().

-- Steve

>  
>  static int
>  lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
> @@ -506,8 +512,7 @@ lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
>  		return trace_seq_printf(
>  				s, " %4lldus%c: ",
>  				abs_ts,
> -				rel_ts > preempt_mark_thresh_us ? '!' :
> -				  rel_ts > 1 ? '+' : ' ');
> +				MARK(rel_ts * NSEC_PER_USEC));
>  	} else { /* !verbose && !in_ns */
>  		return trace_seq_printf(s, " %4lld: ", abs_ts);
>  	}
> @@ -692,7 +697,7 @@ int register_ftrace_event(struct trace_event *event)
>  				goto out;
>  
>  		} else {
> -			
> +
>  			event->type = next_event_type++;
>  			list = &ftrace_event_list;
>  		}


^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH v2 2/3] tracing, function_graph: add additional marks to signal very large function execution time
  2014-11-14  3:32   ` Steven Rostedt
@ 2014-11-14  6:18     ` Byungchul Park
  0 siblings, 0 replies; 9+ messages in thread
From: Byungchul Park @ 2014-11-14  6:18 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: mingo, linux-kernel, seungho1.park, jolsa

Hello,

On Thu, Nov 13, 2014 at 10:32:06PM -0500, Steven Rostedt wrote:
> On Wed,  5 Nov 2014 16:18:45 +0900
> byungchul.park@lge.com wrote:
>   
> > +/* trace overhead mark */
> > +struct trace_mark {
> > +	unsigned long long val; /* unit: nsec */
> > +	char sym;
> > +};
> 
> Please format the above to:
> 
> struct trace_mark {
> 	unsigned long long		val;
> 	char				sym;
> };

Thank you, I will do it.

> 
> > +
> > +#define DEFINE_MARK_STRUCT static const struct trace_mark mark[]
> 
> Why is this a macro?

Because I want to hide the 'mark' variable so that user dont need to know it.
If this macro wouldn't be used, the function or macro to find and get a symbol
must know what the variable is. And I didnt want to take an additional arg
'mark' to the function or macro.

I will explicitly define the variable 'mark' in the c file and use it in
the function to find and get a corresponding symbol, if it would be ok.

> 
> > +#define DEFINE_MARK(v, s) {.val = v, .sym = s}
> > +#define MARK(d) 							\
> > +({									\
> > +	int i = ARRAY_SIZE(mark);					\
> > +	while ((unsigned long long)(d) <= mark[--i].val && i > 0);	\
> > +	mark[i].sym;							\
> > +})
> 
> Why is this a macro and not a static inline?

I wanted to couple static data 'mark' and macro 'MARK' only in .h and 
abstract its details. But I will move it to .c explicitly if it looks better.

> 
> static inline char find_trace_mark(unsigned long long duration)
> {
> 	int i = ARRAY_SIZE(mark);
> 
> 	while (duration <= mark[--i].val && i > 0)
> 		;
> 
> 	return make[i]. sym;
> }
> 
> That's much more readable.
> 
> >  
> >  /**
> >   * struct tracer - a specific tracer and its callbacks to interact with debugfs
> > diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> > index cb33f46..8a62907 100644
> > --- a/kernel/trace/trace_functions_graph.c
> > +++ b/kernel/trace/trace_functions_graph.c
> > @@ -797,6 +797,14 @@ trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
> >  	return TRACE_TYPE_HANDLED;
> >  }
> >  
> > +DEFINE_MARK_STRUCT = {
> > +	DEFINE_MARK(0ULL		, ' '), /* 0 usecs */
> > +	DEFINE_MARK(10000ULL		, '+'), /* 10 usecs */
> > +	DEFINE_MARK(100000ULL		, '!'), /* 100 usecs */
> > +	DEFINE_MARK(1000000ULL		, '#'), /* 1000 usecs */
> > +	DEFINE_MARK(1000000000ULL	, '$'), /* 1 sec */
> > +};
> 
> Don't need to use a name as big as DEFINE_MARK. Just have:
> 
> #undef MARK
> #define MARK(v, s) { .val = v, .sym = s }
> 

Thank you, I will do it.

> struct trace_mark mark[] = {
> 	MARK(0ULL			, ' '), /* 0 usecs */
> [...]
> };
> 
> With the define directly above the call, we don't need need to be that
> descriptive.
> 

I still wonder if it's better to define 'mark' explicitly in .c. Anyway
I'll fix it. :)

> > +
> >  static enum print_line_t
> >  print_graph_duration(unsigned long long duration, struct trace_seq *s,
> >  		     u32 flags)
> > @@ -822,12 +830,7 @@ 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 usecs */
> > -		if (duration > 100000ULL)
> > -			ret = trace_seq_puts(s, "! ");
> > -		/* Duration exceeded 10 usecs */
> > -		else if (duration > 10000ULL)
> > -			ret = trace_seq_puts(s, "+ ");
> > +		ret = trace_seq_printf(s, "%c ", MARK(duration));
> 
> Then this could just be:
> 
> 		ret = trace_seq_printf(s, "%c ",
> 				       find_trace_mark(duration));
> 

Thank you very much for your kindness!

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

^ permalink raw reply	[flat|nested] 9+ messages in thread

* Re: [PATCH v2 3/3] tracing: add additional marks to signal very large delay
  2014-11-14  3:38   ` Steven Rostedt
@ 2014-11-14  6:22     ` Byungchul Park
  0 siblings, 0 replies; 9+ messages in thread
From: Byungchul Park @ 2014-11-14  6:22 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: mingo, linux-kernel, seungho1.park, jolsa

On Thu, Nov 13, 2014 at 10:38:01PM -0500, Steven Rostedt wrote:
> On Wed,  5 Nov 2014 16:18:46 +0900
> byungchul.park@lge.com wrote:
> 
> > -static unsigned long preempt_mark_thresh_us = 100;
> > +DEFINE_MARK_STRUCT = {
> > +	DEFINE_MARK(0ULL		, ' '), /* 0 usecs */
> > +	DEFINE_MARK(10000ULL		, '+'), /* 10 usecs */
> > +	DEFINE_MARK(100000ULL		, '!'), /* 100 usecs */
> > +	DEFINE_MARK(1000000ULL		, '#'), /* 1000 usecs */
> > +	DEFINE_MARK(1000000000ULL	, '$'), /* 1 sec */
> > +};
> 
> OK, I see why you did the macro magic here. But it's still obfuscates
> the code.
> 
> Instead of having that find_trace_mark() be a static function, just
> make it defined in trace_output.c that function_graph calls. This code
> is used for outputting to userspace and a function call is not going to
> be noticed.

OK, I will make it global function and use it.

> 
> As it would now be a global function (although only defined in
> kernel/trace), we need to make the name a bit more specific. Instead of
> calling it find_trace_mark(), call it trace_duration_mark().
> 

OK, I'll rename it.

Thank you,
Byungchul.

> -- Steve
> 
> >  
> >  static int
> >  lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
> > @@ -506,8 +512,7 @@ lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
> >  		return trace_seq_printf(
> >  				s, " %4lldus%c: ",
> >  				abs_ts,
> > -				rel_ts > preempt_mark_thresh_us ? '!' :
> > -				  rel_ts > 1 ? '+' : ' ');
> > +				MARK(rel_ts * NSEC_PER_USEC));
> >  	} else { /* !verbose && !in_ns */
> >  		return trace_seq_printf(s, " %4lld: ", abs_ts);
> >  	}
> > @@ -692,7 +697,7 @@ int register_ftrace_event(struct trace_event *event)
> >  				goto out;
> >  
> >  		} else {
> > -			
> > +
> >  			event->type = next_event_type++;
> >  			list = &ftrace_event_list;
> >  		}
> 
> --
> 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/

^ permalink raw reply	[flat|nested] 9+ messages in thread

end of thread, other threads:[~2014-11-14  6:22 UTC | newest]

Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2014-11-05  7:18 [PATCH v2 0/3] tracing: signaling large duration and delay byungchul.park
2014-11-05  7:18 ` [PATCH v2 1/3] tracing, function_graph: fix micro seconds notation in comment byungchul.park
2014-11-14  3:32   ` Steven Rostedt
2014-11-05  7:18 ` [PATCH v2 2/3] tracing, function_graph: add additional marks to signal very large function execution time byungchul.park
2014-11-14  3:32   ` Steven Rostedt
2014-11-14  6:18     ` Byungchul Park
2014-11-05  7:18 ` [PATCH v2 3/3] tracing: add additional marks to signal very large delay byungchul.park
2014-11-14  3:38   ` Steven Rostedt
2014-11-14  6:22     ` Byungchul Park

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox

all inboxes | Powered by JetHome®