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

[Steven Rostedt <rostedt@goodmis.org>]

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