Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1600994 > unrolled thread

[PATCH 1/7] trace: Move trace_seq_overflowed out of line

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  [PATCH 1/7] trace: Move trace_seq_overflowed out of line Andi Kleen <andi@firstfloor.org> - 2017-03-15 03:20 +0100
    Re: [PATCH 1/7] trace: Move trace_seq_overflowed out of line Steven Rostedt <rostedt@goodmis.org> - 2017-03-16 02:00 +0100
      Re: [PATCH 1/7] trace: Move trace_seq_overflowed out of line Andi Kleen <andi@firstfloor.org> - 2017-03-16 03:30 +0100
        Re: [PATCH 1/7] trace: Move trace_seq_overflowed out of line Steven Rostedt <rostedt@goodmis.org> - 2017-03-16 04:30 +0100
          Re: [PATCH 1/7] trace: Move trace_seq_overflowed out of line Steven Rostedt <rostedt@goodmis.org> - 2017-03-16 04:50 +0100

#1600994 — [PATCH 1/7] trace: Move trace_seq_overflowed out of line

From: Andi Kleen <ak@linux.intel.com>

Inlining trace_seq_overflowed takes ~17k in text size in my kernel.
The function doesn't seem to be time critical, so we can just out of line it.

Function                                           Total          Avg   Num
trace_seq_has_overflowed                           17134 (0.00%)  33    514

This saves around 6k here

   text    data     bss     dec     hex filename
9102881 5367568 11116544        25586993        1866d31 vmlinux-orig
9096494 5367568 11116544        25580606        186543e vmlinux-trace-seq

Cc: rostedt@goodmis.org
Signed-off-by: Andi Kleen <ak@linux.intel.com>
---
 include/linux/trace_seq.h | 12 +-----------
 kernel/trace/trace_seq.c  | 15 +++++++++++++++
 2 files changed, 16 insertions(+), 11 deletions(-)

diff --git a/include/linux/trace_seq.h b/include/linux/trace_seq.h
index cfaf5a1d4bad..442e4f087b95 100644
--- a/include/linux/trace_seq.h
+++ b/include/linux/trace_seq.h
@@ -56,17 +56,7 @@ trace_seq_buffer_ptr(struct trace_seq *s)
 	return s->buffer + seq_buf_used(&s->seq);
 }
 
-/**
- * trace_seq_has_overflowed - return true if the trace_seq took too much
- * @s: trace sequence descriptor
- *
- * Returns true if too much data was added to the trace_seq and it is
- * now full and will not take anymore.
- */
-static inline bool trace_seq_has_overflowed(struct trace_seq *s)
-{
-	return s->full || seq_buf_has_overflowed(&s->seq);
-}
+bool trace_seq_has_overflowed(struct trace_seq *s);
 
 /*
  * Currently only defined when tracing is enabled.
diff --git a/kernel/trace/trace_seq.c b/kernel/trace/trace_seq.c
index e694c9f9efa4..4367cd43e38c 100644
--- a/kernel/trace/trace_seq.c
+++ b/kernel/trace/trace_seq.c
@@ -375,3 +375,18 @@ int trace_seq_to_user(struct trace_seq *s, char __user *ubuf, int cnt)
 	return seq_buf_to_user(&s->seq, ubuf, cnt);
 }
 EXPORT_SYMBOL_GPL(trace_seq_to_user);
+
+
+
+/**
+ * trace_seq_has_overflowed - return true if the trace_seq took too much
+ * @s: trace sequence descriptor
+ *
+ * Returns true if too much data was added to the trace_seq and it is
+ * now full and will not take anymore.
+ */
+bool trace_seq_has_overflowed(struct trace_seq *s)
+{
+	return s->full || seq_buf_has_overflowed(&s->seq);
+}
+EXPORT_SYMBOL_GPL(trace_seq_has_overflowed);
-- 
2.9.3

[toc] | [next] | [standalone]

#1601824

On Tue, 14 Mar 2017 19:14:25 -0700
Andi Kleen <andi@firstfloor.org> wrote:

> From: Andi Kleen <ak@linux.intel.com>
> 
> Inlining trace_seq_overflowed takes ~17k in text size in my kernel.
> The function doesn't seem to be time critical, so we can just out of line it.

Instead of out of lining trace_seq_has_overflowed(), have you tried to
out of line the function that's called by tracepoints (one per
tracepoint). That is, trace_handle_return()?

The trace_seq_handle_overflow() is used in not reproduced places that I
would like to keep it as an inline. If the issue is size of the kernel,
please just out of line the one place that calls it that is duplicated
for every tracepoint. Which happens to be trace_handle_return().

Thanks!

-- Steve


> 
> Function                                           Total          Avg   Num
> trace_seq_has_overflowed                           17134 (0.00%)  33    514
> 
> This saves around 6k here
> 
>    text    data     bss     dec     hex filename
> 9102881 5367568 11116544        25586993        1866d31 vmlinux-orig
> 9096494 5367568 11116544        25580606        186543e vmlinux-trace-seq
> 
> Cc: rostedt@goodmis.org
> Signed-off-by: Andi Kleen <ak@linux.intel.com>
> ---
>  include/linux/trace_seq.h | 12 +-----------
>  kernel/trace/trace_seq.c  | 15 +++++++++++++++
>  2 files changed, 16 insertions(+), 11 deletions(-)
> 
> diff --git a/include/linux/trace_seq.h b/include/linux/trace_seq.h
> index cfaf5a1d4bad..442e4f087b95 100644
> --- a/include/linux/trace_seq.h
> +++ b/include/linux/trace_seq.h
> @@ -56,17 +56,7 @@ trace_seq_buffer_ptr(struct trace_seq *s)
>  	return s->buffer + seq_buf_used(&s->seq);
>  }
>  
> -/**
> - * trace_seq_has_overflowed - return true if the trace_seq took too much
> - * @s: trace sequence descriptor
> - *
> - * Returns true if too much data was added to the trace_seq and it is
> - * now full and will not take anymore.
> - */
> -static inline bool trace_seq_has_overflowed(struct trace_seq *s)
> -{
> -	return s->full || seq_buf_has_overflowed(&s->seq);
> -}
> +bool trace_seq_has_overflowed(struct trace_seq *s);
>  
>  /*
>   * Currently only defined when tracing is enabled.
> diff --git a/kernel/trace/trace_seq.c b/kernel/trace/trace_seq.c
> index e694c9f9efa4..4367cd43e38c 100644
> --- a/kernel/trace/trace_seq.c
> +++ b/kernel/trace/trace_seq.c
> @@ -375,3 +375,18 @@ int trace_seq_to_user(struct trace_seq *s, char __user *ubuf, int cnt)
>  	return seq_buf_to_user(&s->seq, ubuf, cnt);
>  }
>  EXPORT_SYMBOL_GPL(trace_seq_to_user);
> +
> +
> +
> +/**
> + * trace_seq_has_overflowed - return true if the trace_seq took too much
> + * @s: trace sequence descriptor
> + *
> + * Returns true if too much data was added to the trace_seq and it is
> + * now full and will not take anymore.
> + */
> +bool trace_seq_has_overflowed(struct trace_seq *s)
> +{
> +	return s->full || seq_buf_has_overflowed(&s->seq);
> +}
> +EXPORT_SYMBOL_GPL(trace_seq_has_overflowed);

[toc] | [prev] | [next] | [standalone]

#1601877

On Wed, Mar 15, 2017 at 08:54:20PM -0400, Steven Rostedt wrote:
> On Tue, 14 Mar 2017 19:14:25 -0700
> Andi Kleen <andi@firstfloor.org> wrote:
> 
> > From: Andi Kleen <ak@linux.intel.com>
> > 
> > Inlining trace_seq_overflowed takes ~17k in text size in my kernel.
> > The function doesn't seem to be time critical, so we can just out of line it.
> 
> Instead of out of lining trace_seq_has_overflowed(), have you tried to
> out of line the function that's called by tracepoints (one per
> tracepoint). That is, trace_handle_return()?

This is a data driven approach so I always went for the largest savings.

> 
> The trace_seq_handle_overflow() is used in not reproduced places that I
> would like to keep it as an inline. If the issue is size of the kernel,

I cannot parse this sentence. What advantage has it being inline?

> please just out of line the one place that calls it that is duplicated
> for every tracepoint. Which happens to be trace_handle_return().

It is used in lots of places outside trace_handle_return, so that would
give far less savings.

-Andi

include/linux/trace_events.h:143:       return trace_seq_has_overflowed(s) ?
include/linux/trace_seq.h:60: * trace_seq_has_overflowed - return true if the trace_seq took too much
include/linux/trace_seq.h:66:static inline bool trace_seq_has_overflowed(struct trace_seq *s)
kernel/trace/ring_buffer.c:47:  return !trace_seq_has_overflowed(s);
kernel/trace/ring_buffer.c:390: return !trace_seq_has_overflowed(s);
kernel/trace/trace.c:3268:      if (trace_seq_has_overflowed(s))
kernel/trace/trace.c:3292:      if (trace_seq_has_overflowed(s))
kernel/trace/trace.c:3318:              if (trace_seq_has_overflowed(s))
kernel/trace/trace.c:3347:              if (trace_seq_has_overflowed(s))
kernel/trace/trace.c:3399:              if (trace_seq_has_overflowed(&iter->seq))
kernel/trace/trace.c:5490:              if (trace_seq_has_overflowed(&iter->seq)) {
kernel/trace/trace_functions_graph.c:910:       if (trace_seq_has_overflowed(s))
kernel/trace/trace_functions_graph.c:1221:      if (trace_seq_has_overflowed(s))
kernel/trace/trace_output.c:354:        return !trace_seq_has_overflowed(s);
kernel/trace/trace_output.c:374:        return !trace_seq_has_overflowed(s);
kernel/trace/trace_output.c:435:        return !trace_seq_has_overflowed(s);
kernel/trace/trace_output.c:522:        return !trace_seq_has_overflowed(s);
kernel/trace/trace_output.c:550:        return !trace_seq_has_overflowed(s);
kernel/trace/trace_output.c:586:        return !trace_seq_has_overflowed(s);
kernel/trace/trace_output.c:1021:               if (trace_seq_has_overflowed(s))
kernel/trace/trace_output.c:1071:               if (ip == ULONG_MAX || trace_seq_has_overflowed(s))
kernel/trace/trace_probe.c:44:  return !trace_seq_has_overflowed(s);                            \
kernel/trace/trace_probe.c:73:  return !trace_seq_has_overflowed(s);
kernel/trace/trace_syscalls.c:147:              if (trace_seq_has_overflowed(s))

[toc] | [prev] | [next] | [standalone]

#1601913

On Wed, 15 Mar 2017 19:27:57 -0700
Andi Kleen <andi@firstfloor.org> wrote:

> On Wed, Mar 15, 2017 at 08:54:20PM -0400, Steven Rostedt wrote:
> > On Tue, 14 Mar 2017 19:14:25 -0700
> > Andi Kleen <andi@firstfloor.org> wrote:
> >   
> > > From: Andi Kleen <ak@linux.intel.com>
> > > 
> > > Inlining trace_seq_overflowed takes ~17k in text size in my kernel.
> > > The function doesn't seem to be time critical, so we can just out of line it.  
> > 
> > Instead of out of lining trace_seq_has_overflowed(), have you tried to
> > out of line the function that's called by tracepoints (one per
> > tracepoint). That is, trace_handle_return()?  
> 
> This is a data driven approach so I always went for the largest savings.
> 
> > 
> > The trace_seq_handle_overflow() is used in not reproduced places that I
> > would like to keep it as an inline. If the issue is size of the kernel,  
> 
> I cannot parse this sentence. What advantage has it being inline?

Because you don't understand the problem. And why I'm against your
patch!

> 
> > please just out of line the one place that calls it that is duplicated
> > for every tracepoint. Which happens to be trace_handle_return().  
> 
> It is used in lots of places outside trace_handle_return, so that would
> give far less savings.

Have you actually looked at what trace_seq_has_overflowed() is?

static inline bool trace_seq_has_overflowed(struct trace_seq *s)
{
	return s->full || seq_buf_has_overflowed(&s->seq);
}

static inline bool
seq_buf_has_overflowed(struct seq_buf *s)
{
	return s->len > s->size;
}

Basically trace_seq_has_overflowed() is the same as:

	return s->full || s->seq->len > s->seq->size


You really think the above in 24 locations would cause 17k difference??



> 
> -Andi
> 
> include/linux/trace_events.h:143:       return trace_seq_has_overflowed(s) ?

Every thing below is negligible. The above which is called in
trace_handle_return() is your problem.

Let me explain it to you.

The above is part of the TRACE_EVENT() logic. It is duplicated for
*every* tracepoint in the system.

Looking at a current kernel:

 # ls /debug/tracing/events/*/*/enable | wc -l
1267

There's 1267 events. That means the function trace_handle_return() is
called 1267 times! THAT IS THE PROBLEM!!!!

Look at include/trace/trace_events.h for

  trace_raw_output_##call()

That's the macro that creates over a thousand functions calling
trace_handle_return().

So please, fix where the issue is and not the other function, as 23
callers is not going to be noticed.

-- Steve


> include/linux/trace_seq.h:60: * trace_seq_has_overflowed - return true if the trace_seq took too much
> include/linux/trace_seq.h:66:static inline bool trace_seq_has_overflowed(struct trace_seq *s)
> kernel/trace/ring_buffer.c:47:  return !trace_seq_has_overflowed(s);
> kernel/trace/ring_buffer.c:390: return !trace_seq_has_overflowed(s);
> kernel/trace/trace.c:3268:      if (trace_seq_has_overflowed(s))
> kernel/trace/trace.c:3292:      if (trace_seq_has_overflowed(s))
> kernel/trace/trace.c:3318:              if (trace_seq_has_overflowed(s))
> kernel/trace/trace.c:3347:              if (trace_seq_has_overflowed(s))
> kernel/trace/trace.c:3399:              if (trace_seq_has_overflowed(&iter->seq))
> kernel/trace/trace.c:5490:              if (trace_seq_has_overflowed(&iter->seq)) {
> kernel/trace/trace_functions_graph.c:910:       if (trace_seq_has_overflowed(s))
> kernel/trace/trace_functions_graph.c:1221:      if (trace_seq_has_overflowed(s))
> kernel/trace/trace_output.c:354:        return !trace_seq_has_overflowed(s);
> kernel/trace/trace_output.c:374:        return !trace_seq_has_overflowed(s);
> kernel/trace/trace_output.c:435:        return !trace_seq_has_overflowed(s);
> kernel/trace/trace_output.c:522:        return !trace_seq_has_overflowed(s);
> kernel/trace/trace_output.c:550:        return !trace_seq_has_overflowed(s);
> kernel/trace/trace_output.c:586:        return !trace_seq_has_overflowed(s);
> kernel/trace/trace_output.c:1021:               if (trace_seq_has_overflowed(s))
> kernel/trace/trace_output.c:1071:               if (ip == ULONG_MAX || trace_seq_has_overflowed(s))
> kernel/trace/trace_probe.c:44:  return !trace_seq_has_overflowed(s);                            \
> kernel/trace/trace_probe.c:73:  return !trace_seq_has_overflowed(s);
> kernel/trace/trace_syscalls.c:147:              if (trace_seq_has_overflowed(s))
> 

[toc] | [prev] | [next] | [standalone]

#1601920

On Wed, 15 Mar 2017 23:20:30 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> > It is used in lots of places outside trace_handle_return, so that would
> > give far less savings.  

Actually, I think you'll probably have *more* savings inlining
trace_handle_return() than trace_seq_has_overflowed(). Why?

Think about it now before looking at the answer below.

> > include/linux/trace_events.h:143:       return trace_seq_has_overflowed(s) ?  
> 
> Every thing below is negligible. The above which is called in
> trace_handle_return() is your problem.
> 
> Let me explain it to you.
> 
> The above is part of the TRACE_EVENT() logic. It is duplicated for
> *every* tracepoint in the system.
> 
> Looking at a current kernel:
> 
>  # ls /debug/tracing/events/*/*/enable | wc -l
> 1267
> 
> There's 1267 events. That means the function trace_handle_return() is
> called 1267 times! THAT IS THE PROBLEM!!!!
> 
> Look at include/trace/trace_events.h for
> 
>   trace_raw_output_##call()
> 
> That's the macro that creates over a thousand functions calling
> trace_handle_return().
> 

trace_handle_return() is called 1267 times. If you out of line that
function, not only do you save the compares, you also save the
condition too! That could be a jump as well.

static inline enum print_line_t trace_handle_return(struct trace_seq *s)
{
	return trace_seq_has_overflowed(s) ?
		TRACE_TYPE_PARTIAL_LINE : TRACE_TYPE_HANDLED;
}

The above is called 1267 times. If you move out of line
trace_seq_has_overflowed() you only saved the

	s->full || s->seq->len > s->seq->size

part from being duplicated.

But if you out of line trace_handle_return, you move out

	s->full || s->seq->len > s->seq->size ?
		TRACE_TYPE_PARTIAL_LINE :
		TRACE_TYPE-HANDLED

1267 times as well.

Try it. It may surprise you.

-- Steve

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web