[PATCH v5 0/2] tracing: signaling large duration and delay

[PATCH v5 0/2] tracing: signaling large duration and delay

[byungchul.park]

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

Changes since v4
* move implementing from .h to .c

Changes since v3
* re-position define macro and undef explicitly
* enhance readablity

Changes since v2
* use inline function instead of macro
* enhance readablity

Changes since v1
* 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 (2):
  tracing, function_graph: fix micro seconds notation in comment
  tracing: add additional marks to signal very large time

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

-- 
1.7.9.5

[PATCH v5 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.

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

[PATCH v5 2/2] tracing: add additional marks to signal very large 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. And some tracers tracing latency also 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 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       |   10 +++++++---
 kernel/trace/trace.h                 |    2 ++
 kernel/trace/trace_functions_graph.c |    7 +------
 kernel/trace/trace_output.c          |   35 +++++++++++++++++++++++++++++-----
 4 files changed, 40 insertions(+), 14 deletions(-)

diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
index 4da4261..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.
 
@@ -1951,6 +1953,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..0aaf10d 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -719,6 +719,8 @@ enum print_line_t print_trace_line(struct trace_iterator *iter);
 
 extern unsigned long trace_flags;
 
+extern char trace_find_mark(unsigned long long duration);
+
 /* Standard output formatting function used for function return traces */
 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
 
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index cb33f46..1ecb1ad 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -822,12 +822,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 ", trace_find_mark(duration));
 	}
 
 	/*
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index c6977d5..8d19f3d 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,33 @@ 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;
+#undef MARK
+#define MARK(v, s) {.val = v, .sym = s}
+/* trace overhead mark */
+static const struct trace_mark {
+	unsigned long long	val; /* unit: nsec */
+	char			sym;
+} mark[] = {
+	MARK(1000000000ULL	, '$'), /* 1 sec */
+	MARK(1000000ULL		, '#'), /* 1000 usecs */
+	MARK(100000ULL		, '!'), /* 100 usecs */
+	MARK(10000ULL		, '+'), /* 10 usecs */
+	MARK(0ULL		, ' '), /* 0 usecs */
+};
+#undef MARK
+
+char trace_find_mark(unsigned long long d)
+{
+	int i;
+	int size = ARRAY_SIZE(mark);
+
+	for (i = 0; i < size; i++) {
+		if (d >= mark[i].val)
+			break;
+	}
+
+	return (i == size)? ' ' : mark[i].sym;
+}
 
 static int
 lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
@@ -506,8 +532,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 ? '+' : ' ');
+				trace_find_mark(rel_ts * NSEC_PER_USEC));
 	} else { /* !verbose && !in_ns */
 		return trace_seq_printf(s, " %4lld: ", abs_ts);
 	}
@@ -692,7 +717,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

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

[Steven Rostedt]

On Thu, 20 Nov 2014 09:15:34 +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.

Hi,

You don't need to resend this patch because I already applied it. You
may have seen my 'for-next' patch series with it.

If this is different than what I applied, let me know.

Thanks,

-- Steve

Re: [PATCH v5 2/2] tracing: add additional marks to signal very large time

[Steven Rostedt]

On Thu, 20 Nov 2014 09:15:35 +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. And some tracers tracing latency also 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 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.

Hi,

Can you rebase this off of my for-next branch at:

 git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git


Also some comments below.

> 
> Signed-off-by: Byungchul Park <byungchul.park@lge.com>
> ---
>  Documentation/trace/ftrace.txt       |   10 +++++++---
>  kernel/trace/trace.h                 |    2 ++
>  kernel/trace/trace_functions_graph.c |    7 +------
>  kernel/trace/trace_output.c          |   35 +++++++++++++++++++++++++++++-----
>  4 files changed, 40 insertions(+), 14 deletions(-)
> 
> diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt
> index 4da4261..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.
>  
> @@ -1951,6 +1953,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..0aaf10d 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -719,6 +719,8 @@ enum print_line_t print_trace_line(struct trace_iterator *iter);
>  
>  extern unsigned long trace_flags;
>  
> +extern char trace_find_mark(unsigned long long duration);
> +
>  /* Standard output formatting function used for function return traces */
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>  
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index cb33f46..1ecb1ad 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -822,12 +822,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 ", trace_find_mark(duration));
>  	}

The brackets are no longer necessary. Also if you base this off of my
for-next branch, you'll see this code changed.

But you can get rid of the "duration_printed" and make the code look
like this:

	if (flags & TRACE_GRAPH_PRINT_OVERHEAD)
		trace_seq_printf(s, "%c ", trace_find_mark(duration);
	else
		trace_seq_puts(s, "  ");


>  
>  	/*
> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
> index c6977d5..8d19f3d 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);
> -		
> +

Thanks for the white space clean up :-)

>  	trace_seq_putc(p, 0);
>  
>  	return ret;
> @@ -471,7 +471,33 @@ 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;
> +#undef MARK
> +#define MARK(v, s) {.val = v, .sym = s}
> +/* trace overhead mark */
> +static const struct trace_mark {
> +	unsigned long long	val; /* unit: nsec */
> +	char			sym;
> +} mark[] = {
> +	MARK(1000000000ULL	, '$'), /* 1 sec */
> +	MARK(1000000ULL		, '#'), /* 1000 usecs */
> +	MARK(100000ULL		, '!'), /* 100 usecs */
> +	MARK(10000ULL		, '+'), /* 10 usecs */
> +	MARK(0ULL		, ' '), /* 0 usecs */
> +};
> +#undef MARK
> +
> +char trace_find_mark(unsigned long long d)
> +{
> +	int i;
> +	int size = ARRAY_SIZE(mark);
> +
> +	for (i = 0; i < size; i++) {
> +		if (d >= mark[i].val)
> +			break;
> +	}
> +
> +	return (i == size)? ' ' : mark[i].sym;

Change this to:

	/* The break from loop must have been hit */
	if (WARN_ON_ONCE(i == size))
		return ' ';

	return mark[i].sym;

-- Steve


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

Re: [PATCH v5 2/2] tracing: add additional marks to signal very large time

[Namhyung Kim]

Hi Steve and Byungchul,

On Wed, 19 Nov 2014 20:06:04 -0500, Steven Rostedt wrote:
> On Thu, 20 Nov 2014 09:15:35 +0900
> byungchul.park@lge.com wrote:
>> -static unsigned long preempt_mark_thresh_us = 100;
>> +#undef MARK
>> +#define MARK(v, s) {.val = v, .sym = s}
>> +/* trace overhead mark */
>> +static const struct trace_mark {
>> +	unsigned long long	val; /* unit: nsec */
>> +	char			sym;
>> +} mark[] = {
>> +	MARK(1000000000ULL	, '$'), /* 1 sec */
>> +	MARK(1000000ULL		, '#'), /* 1000 usecs */
>> +	MARK(100000ULL		, '!'), /* 100 usecs */
>> +	MARK(10000ULL		, '+'), /* 10 usecs */
>> +	MARK(0ULL		, ' '), /* 0 usecs */
>> +};
>> +#undef MARK
>> +
>> +char trace_find_mark(unsigned long long d)
>> +{
>> +	int i;
>> +	int size = ARRAY_SIZE(mark);
>> +
>> +	for (i = 0; i < size; i++) {
>> +		if (d >= mark[i].val)
>> +			break;
>> +	}
>> +
>> +	return (i == size)? ' ' : mark[i].sym;
>
> Change this to:
>
> 	/* The break from loop must have been hit */
> 	if (WARN_ON_ONCE(i == size))
> 		return ' ';

I think it's impossible since it's always true that 'd >= 0'.

Thanks,
Namhyung

>
> 	return mark[i].sym;
>
> -- Steve
>
>
>> +}
>>  
>>  static int
>>  lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
>> @@ -506,8 +532,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 ? '+' : ' ');
>> +				trace_find_mark(rel_ts * NSEC_PER_USEC));
>>  	} else { /* !verbose && !in_ns */
>>  		return trace_seq_printf(s, " %4lld: ", abs_ts);
>>  	}
>> @@ -692,7 +717,7 @@ int register_ftrace_event(struct trace_event *event)
>>  				goto out;
>>  
>>  		} else {
>> -			
>> +
>>  			event->type = next_event_type++;
>>  			list = &ftrace_event_list;
>>  		}

Re: [PATCH v5 2/2] tracing: add additional marks to signal very large time

[Byungchul Park]

Hello,

On Thu, Nov 20, 2014 at 03:05:43PM +0900, Namhyung Kim wrote:
> Hi Steve and Byungchul,
> 
> On Wed, 19 Nov 2014 20:06:04 -0500, Steven Rostedt wrote:
> > On Thu, 20 Nov 2014 09:15:35 +0900
> > byungchul.park@lge.com wrote:
> >> -static unsigned long preempt_mark_thresh_us = 100;
> >> +#undef MARK
> >> +#define MARK(v, s) {.val = v, .sym = s}
> >> +/* trace overhead mark */
> >> +static const struct trace_mark {
> >> +	unsigned long long	val; /* unit: nsec */
> >> +	char			sym;
> >> +} mark[] = {
> >> +	MARK(1000000000ULL	, '$'), /* 1 sec */
> >> +	MARK(1000000ULL		, '#'), /* 1000 usecs */
> >> +	MARK(100000ULL		, '!'), /* 100 usecs */
> >> +	MARK(10000ULL		, '+'), /* 10 usecs */
> >> +	MARK(0ULL		, ' '), /* 0 usecs */
> >> +};
> >> +#undef MARK
> >> +
> >> +char trace_find_mark(unsigned long long d)
> >> +{
> >> +	int i;
> >> +	int size = ARRAY_SIZE(mark);
> >> +
> >> +	for (i = 0; i < size; i++) {
> >> +		if (d >= mark[i].val)
> >> +			break;
> >> +	}
> >> +
> >> +	return (i == size)? ' ' : mark[i].sym;
> >
> > Change this to:
> >
> > 	/* The break from loop must have been hit */
> > 	if (WARN_ON_ONCE(i == size))
> > 		return ' ';
> 
> I think it's impossible since it's always true that 'd >= 0'.
> 

If someone won't define "MARK(0ULL, ' ')", then i think it can happen. :)

Thanks,
Byungchul

> Thanks,
> Namhyung
> 
> >
> > 	return mark[i].sym;
> >
> > -- Steve
> >
> >
> >> +}
> >>  
> >>  static int
> >>  lat_print_timestamp(struct trace_iterator *iter, u64 next_ts)
> >> @@ -506,8 +532,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 ? '+' : ' ');
> >> +				trace_find_mark(rel_ts * NSEC_PER_USEC));
> >>  	} else { /* !verbose && !in_ns */
> >>  		return trace_seq_printf(s, " %4lld: ", abs_ts);
> >>  	}
> >> @@ -692,7 +717,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/

Re: [PATCH v5 2/2] tracing: add additional marks to signal very large time

[Steven Rostedt]

On Thu, 20 Nov 2014 15:05:43 +0900
Namhyung Kim <namhyung@kernel.org> wrote:

> Hi Steve and Byungchul,
> 
> On Wed, 19 Nov 2014 20:06:04 -0500, Steven Rostedt wrote:
> > On Thu, 20 Nov 2014 09:15:35 +0900
> > byungchul.park@lge.com wrote:
> >> -static unsigned long preempt_mark_thresh_us = 100;
> >> +#undef MARK
> >> +#define MARK(v, s) {.val = v, .sym = s}
> >> +/* trace overhead mark */
> >> +static const struct trace_mark {
> >> +	unsigned long long	val; /* unit: nsec */
> >> +	char			sym;
> >> +} mark[] = {
> >> +	MARK(1000000000ULL	, '$'), /* 1 sec */
> >> +	MARK(1000000ULL		, '#'), /* 1000 usecs */
> >> +	MARK(100000ULL		, '!'), /* 100 usecs */
> >> +	MARK(10000ULL		, '+'), /* 10 usecs */
> >> +	MARK(0ULL		, ' '), /* 0 usecs */
> >> +};
> >> +#undef MARK
> >> +
> >> +char trace_find_mark(unsigned long long d)
> >> +{
> >> +	int i;
> >> +	int size = ARRAY_SIZE(mark);
> >> +
> >> +	for (i = 0; i < size; i++) {
> >> +		if (d >= mark[i].val)
> >> +			break;
> >> +	}
> >> +
> >> +	return (i == size)? ' ' : mark[i].sym;
> >
> > Change this to:
> >
> > 	/* The break from loop must have been hit */
> > 	if (WARN_ON_ONCE(i == size))
> > 		return ' ';
> 
> I think it's impossible since it's always true that 'd >= 0'.
> 

It is impossible if this code never changes. But we all know that
wont be the case :-)

-- Steve
 

Re: [PATCH v5 2/2] tracing: add additional marks to signal very large time

[Steven Rostedt]

On Thu, 20 Nov 2014 15:38:46 +0900
Byungchul Park <byungchul.park@lge.com> wrote:


> > I think it's impossible since it's always true that 'd >= 0'.
> > 
> 
> If someone won't define "MARK(0ULL, ' ')", then i think it can happen. :)
> 

Actually, remove the "MARK(0ULL, ' ')" and keep the return value as is.
But clean it up a little like this:

	return (i == size) ? ' ' : mark[i].sym;

Notice the space between "size)" and "?"

-- Steve