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

[Steven Rostedt]

On Wed, 15 Mar 2017 19:27:57 -0700
Andi Kleen <andi@xxxxxxxxxxxxxx> 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@xxxxxxxxxxxxxx> wrote:
> >   
> > > From: Andi Kleen <ak@xxxxxxxxxxxxxxx>
> > > 
> > > 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))
>