linux-kernel - Re: [PATCH 1/7] trace: Move trace_seq

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Message-ID: <20170315234109.6ddc7073@grimm.local.home>
Date:   Wed, 15 Mar 2017 23:41:09 -0400
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Andi Kleen <andi@...stfloor.org>
Cc:     akpm@...ux-foundation.org, linux-kernel@...r.kernel.org,
        Andi Kleen <ak@...ux.intel.com>
Subject: Re: [PATCH 1/7] trace: Move trace_seq_overflowed out of line

On Wed, 15 Mar 2017 23:20:30 -0400
Steven Rostedt <rostedt@...dmis.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