Date: Wed, 15 Mar 2017 23:41:09 -0400
From: Steven Rostedt <rostedt@goodmis.org>
To: Andi Kleen <andi@firstfloor.org>
Cc: akpm@linux-foundation.org, linux-kernel@vger.kernel.org,
        Andi Kleen <ak@linux.intel.com>
Subject: Re: [PATCH 1/7] trace: Move trace_seq_overflowed out of line
Message-ID: <20170315234109.6ddc7073@grimm.local.home>
In-Reply-To: <20170315232030.19d9ffe2@gandalf.local.home>
References: <20170315021431.13107-1-andi@firstfloor.org>
        <20170315021431.13107-2-andi@firstfloor.org>
        <20170315205420.53b5e105@grimm.local.home>
        <20170316022756.GF14380@two.firstfloor.org>
        <20170315232030.19d9ffe2@gandalf.local.home>
MIME-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Content-Length: 1808
Lines: 65

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