Performance impact of CONFIG_FUNCTION_TRACER

Performance impact of CONFIG_FUNCTION_TRACER

[Sascha Hauer]

Hi,

I ran some lmbench subtests on a ARMv7 machine (NXP i.MX6q) with and
without CONFIG_FUNCTION_TRACER enabled (with CONFIG_DYNAMIC_FTRACE
enabled and no tracing active), see below. The Kconfig help text of this
option reads as:

> If it's runtime disabled (the bootup default), then the overhead of
> the instructions is very small and not measurable even in
> micro-benchmarks.

In my tests the overhead is small, but it surely exists and is
measurable at least on ARMv7 machines. Is this expected? Should the help
text be rephrased a little less optimistic?

lat_fs
======

CONFIG_FUNCTION_TRACER=y
------------------------

  _ file size
 /        _ repetitions
 |       /         _ created files per second
 |       |        /        _ deleted files per second
 |       |        |       /
0k      205     38325   70264
1k      123     21949   41495
4k      119     21632   42365
10k     84      14408   29439

CONFIG_FUNCTION_TRACER=n
------------------------

0k      198     39317   76241
1k      125     22397   42420
4k      125     22038   44144
10k     84      14965   30032

./scripts/do_ctx
================

Measures context switch time (in us?)

CONFIG_FUNCTION_TRACER=y
------------------------
"size=0k ovr=4.60
2 16.57
4 15.75
8 16.99
16 16.93
24 18.79
32 20.11
64 22.20
96 21.59

CONFIG_FUNCTION_TRACER=n
------------------------
"size=0k ovr=4.88
2 15.26
4 17.29
8 18.25
16 18.40
24 22.19
32 20.85
64 23.32
96 23.11
 
lat_pipe
========

I think it measures the time between sending and receiving data
through a pipe.

CONFIG_FUNCTION_TRACER=y
------------------------
Pipe latency: 44.7039 microseconds

CONFIG_FUNCTION_TRACER=n
------------------------
Pipe latency: 41.9876 microseconds

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

Performance impact of CONFIG_FUNCTION_TRACER

[Sascha Hauer]

Hi,

I ran some lmbench subtests on a ARMv7 machine (NXP i.MX6q) with and
without CONFIG_FUNCTION_TRACER enabled (with CONFIG_DYNAMIC_FTRACE
enabled and no tracing active), see below. The Kconfig help text of this
option reads as:

> If it's runtime disabled (the bootup default), then the overhead of
> the instructions is very small and not measurable even in
> micro-benchmarks.

In my tests the overhead is small, but it surely exists and is
measurable at least on ARMv7 machines. Is this expected? Should the help
text be rephrased a little less optimistic?

lat_fs
======

CONFIG_FUNCTION_TRACER=y
------------------------

  _ file size
 /        _ repetitions
 |       /         _ created files per second
 |       |        /        _ deleted files per second
 |       |        |       /
0k      205     38325   70264
1k      123     21949   41495
4k      119     21632   42365
10k     84      14408   29439

CONFIG_FUNCTION_TRACER=n
------------------------

0k      198     39317   76241
1k      125     22397   42420
4k      125     22038   44144
10k     84      14965   30032

./scripts/do_ctx
================

Measures context switch time (in us?)

CONFIG_FUNCTION_TRACER=y
------------------------
"size=0k ovr=4.60
2 16.57
4 15.75
8 16.99
16 16.93
24 18.79
32 20.11
64 22.20
96 21.59

CONFIG_FUNCTION_TRACER=n
------------------------
"size=0k ovr=4.88
2 15.26
4 17.29
8 18.25
16 18.40
24 22.19
32 20.85
64 23.32
96 23.11
 
lat_pipe
========

I think it measures the time between sending and receiving data
through a pipe.

CONFIG_FUNCTION_TRACER=y
------------------------
Pipe latency: 44.7039 microseconds

CONFIG_FUNCTION_TRACER=n
------------------------
Pipe latency: 41.9876 microseconds

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Performance impact of CONFIG_FUNCTION_TRACER

[Steven Rostedt]

On Tue, 5 Jul 2022 12:54:16 +0200
Sascha Hauer <sha@pengutronix.de> wrote:

> Hi,
> 
> I ran some lmbench subtests on a ARMv7 machine (NXP i.MX6q) with and
> without CONFIG_FUNCTION_TRACER enabled (with CONFIG_DYNAMIC_FTRACE
> enabled and no tracing active), see below. The Kconfig help text of this
> option reads as:
> 
> > If it's runtime disabled (the bootup default), then the overhead of
> > the instructions is very small and not measurable even in
> > micro-benchmarks.  

Well, this is true for x86 ;-)

> 
> In my tests the overhead is small, but it surely exists and is
> measurable at least on ARMv7 machines. Is this expected? Should the help
> text be rephrased a little less optimistic?

You mean "(but may vary by architecture)"

As I believe due to using a link register for function calls, ARM
requires adding two 4 byte nops to every function where as x86 only
adds a single 5 byte nop.

Although nops are very fast (they should not be processed in the CPU's
pipe line, but I don't know if that's true for every arch). It also
affects instruction cache misses, as adding 8 bytes around the code
will cause more cache misses than when they do not exist.

Also, there's some configurations that use the old mcount that does add
some more code to handle the mcount case.

So if this is just to have us change the kconfig, I'm happy to do that.

-- Steve

Re: Performance impact of CONFIG_FUNCTION_TRACER

[Steven Rostedt]

On Tue, 5 Jul 2022 12:54:16 +0200
Sascha Hauer <sha@pengutronix.de> wrote:

> Hi,
> 
> I ran some lmbench subtests on a ARMv7 machine (NXP i.MX6q) with and
> without CONFIG_FUNCTION_TRACER enabled (with CONFIG_DYNAMIC_FTRACE
> enabled and no tracing active), see below. The Kconfig help text of this
> option reads as:
> 
> > If it's runtime disabled (the bootup default), then the overhead of
> > the instructions is very small and not measurable even in
> > micro-benchmarks.  

Well, this is true for x86 ;-)

> 
> In my tests the overhead is small, but it surely exists and is
> measurable at least on ARMv7 machines. Is this expected? Should the help
> text be rephrased a little less optimistic?

You mean "(but may vary by architecture)"

As I believe due to using a link register for function calls, ARM
requires adding two 4 byte nops to every function where as x86 only
adds a single 5 byte nop.

Although nops are very fast (they should not be processed in the CPU's
pipe line, but I don't know if that's true for every arch). It also
affects instruction cache misses, as adding 8 bytes around the code
will cause more cache misses than when they do not exist.

Also, there's some configurations that use the old mcount that does add
some more code to handle the mcount case.

So if this is just to have us change the kconfig, I'm happy to do that.

-- Steve

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Performance impact of CONFIG_FUNCTION_TRACER

[Sascha Hauer]

On Tue, Jul 05, 2022 at 10:39:01AM -0400, Steven Rostedt wrote:
> On Tue, 5 Jul 2022 12:54:16 +0200
> Sascha Hauer <sha@pengutronix.de> wrote:
> 
> > Hi,
> > 
> > I ran some lmbench subtests on a ARMv7 machine (NXP i.MX6q) with and
> > without CONFIG_FUNCTION_TRACER enabled (with CONFIG_DYNAMIC_FTRACE
> > enabled and no tracing active), see below. The Kconfig help text of this
> > option reads as:
> > 
> > > If it's runtime disabled (the bootup default), then the overhead of
> > > the instructions is very small and not measurable even in
> > > micro-benchmarks.  
> 
> Well, this is true for x86 ;-)

That was my assumption ;)

> 
> > 
> > In my tests the overhead is small, but it surely exists and is
> > measurable at least on ARMv7 machines. Is this expected? Should the help
> > text be rephrased a little less optimistic?
> 
> You mean "(but may vary by architecture)"

Something like that, yes.

> 
> As I believe due to using a link register for function calls, ARM
> requires adding two 4 byte nops to every function where as x86 only
> adds a single 5 byte nop.
> 
> Although nops are very fast (they should not be processed in the CPU's
> pipe line, but I don't know if that's true for every arch). It also
> affects instruction cache misses, as adding 8 bytes around the code
> will cause more cache misses than when they do not exist.

Just digged around a bit and saw that on ARM it's not even a real nop.
The compiler emits:

	push    {lr}
	bl      8010e7c0 <__gnu_mcount_nc>

Which is then turned into a nop by replacing the second instruction with

	add   sp, sp, #4

to bring the stack pointer back to its original value. This indeed must
be processed by the CPU pipeline. I wonder if that could be optimized by
replacing both instructions with a nop. I have no idea though if that's
feasible at all or if the overhead would even get smaller by that.

> 
> Also, there's some configurations that use the old mcount that does add
> some more code to handle the mcount case.
> 
> So if this is just to have us change the kconfig, I'm happy to do that.

Yes, would be good to make the kconfig text clear. The overhead itself
is fine when people know that's the price to pay for getting the
function tracer.

Sascha

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

Re: Performance impact of CONFIG_FUNCTION_TRACER

[Sascha Hauer]

On Tue, Jul 05, 2022 at 10:39:01AM -0400, Steven Rostedt wrote:
> On Tue, 5 Jul 2022 12:54:16 +0200
> Sascha Hauer <sha@pengutronix.de> wrote:
> 
> > Hi,
> > 
> > I ran some lmbench subtests on a ARMv7 machine (NXP i.MX6q) with and
> > without CONFIG_FUNCTION_TRACER enabled (with CONFIG_DYNAMIC_FTRACE
> > enabled and no tracing active), see below. The Kconfig help text of this
> > option reads as:
> > 
> > > If it's runtime disabled (the bootup default), then the overhead of
> > > the instructions is very small and not measurable even in
> > > micro-benchmarks.  
> 
> Well, this is true for x86 ;-)

That was my assumption ;)

> 
> > 
> > In my tests the overhead is small, but it surely exists and is
> > measurable at least on ARMv7 machines. Is this expected? Should the help
> > text be rephrased a little less optimistic?
> 
> You mean "(but may vary by architecture)"

Something like that, yes.

> 
> As I believe due to using a link register for function calls, ARM
> requires adding two 4 byte nops to every function where as x86 only
> adds a single 5 byte nop.
> 
> Although nops are very fast (they should not be processed in the CPU's
> pipe line, but I don't know if that's true for every arch). It also
> affects instruction cache misses, as adding 8 bytes around the code
> will cause more cache misses than when they do not exist.

Just digged around a bit and saw that on ARM it's not even a real nop.
The compiler emits:

	push    {lr}
	bl      8010e7c0 <__gnu_mcount_nc>

Which is then turned into a nop by replacing the second instruction with

	add   sp, sp, #4

to bring the stack pointer back to its original value. This indeed must
be processed by the CPU pipeline. I wonder if that could be optimized by
replacing both instructions with a nop. I have no idea though if that's
feasible at all or if the overhead would even get smaller by that.

> 
> Also, there's some configurations that use the old mcount that does add
> some more code to handle the mcount case.
> 
> So if this is just to have us change the kconfig, I'm happy to do that.

Yes, would be good to make the kconfig text clear. The overhead itself
is fine when people know that's the price to pay for getting the
function tracer.

Sascha

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Performance impact of CONFIG_FUNCTION_TRACER

[Steven Rostedt]

On Tue, 5 Jul 2022 23:59:48 +0200
Sascha Hauer <sha@pengutronix.de> wrote:

> > 
> > As I believe due to using a link register for function calls, ARM
> > requires adding two 4 byte nops to every function where as x86 only
> > adds a single 5 byte nop.
> > 
> > Although nops are very fast (they should not be processed in the CPU's
> > pipe line, but I don't know if that's true for every arch). It also
> > affects instruction cache misses, as adding 8 bytes around the code
> > will cause more cache misses than when they do not exist.  
> 
> Just digged around a bit and saw that on ARM it's not even a real nop.
> The compiler emits:
> 
> 	push    {lr}
> 	bl      8010e7c0 <__gnu_mcount_nc>
> 
> Which is then turned into a nop by replacing the second instruction with
> 
> 	add   sp, sp, #4
> 
> to bring the stack pointer back to its original value. This indeed must
> be processed by the CPU pipeline. I wonder if that could be optimized by
> replacing both instructions with a nop. I have no idea though if that's
> feasible at all or if the overhead would even get smaller by that.

The problem is that there's no easy way to do that, because a task
could have been preempted after doing the 'push {lr}' and before the
'bl'. Thus, you create a race by changing either one to a nop first.

I wonder if it would have been better to change the first one to a jump
passed the second :-/

Actually, if you don't mind setups that take a long time, if you change
the first to a jump passed the second, then do synchronize_rcu_rude()
(which may take a while, possibly several seconds or more) then you know
that all users now only see the jump, and none will see the bl. Then
you could convert the bl to nop, and then even change the jump to nop
after that.

To convert back, you would need to reverse it. Convert the first nop
back to a jmp, run synchronize_rcu_rude(). Then convert the second nop
to the bl, and then convert the first to the push {lr}.

> 
> > 
> > Also, there's some configurations that use the old mcount that does add
> > some more code to handle the mcount case.
> > 
> > So if this is just to have us change the kconfig, I'm happy to do that.  
> 
> Yes, would be good to make the kconfig text clear. The overhead itself
> is fine when people know that's the price to pay for getting the
> function tracer.

Agreed. I'll write up a patch.

-- Steve

Re: Performance impact of CONFIG_FUNCTION_TRACER

[Steven Rostedt]

On Tue, 5 Jul 2022 23:59:48 +0200
Sascha Hauer <sha@pengutronix.de> wrote:

> > 
> > As I believe due to using a link register for function calls, ARM
> > requires adding two 4 byte nops to every function where as x86 only
> > adds a single 5 byte nop.
> > 
> > Although nops are very fast (they should not be processed in the CPU's
> > pipe line, but I don't know if that's true for every arch). It also
> > affects instruction cache misses, as adding 8 bytes around the code
> > will cause more cache misses than when they do not exist.  
> 
> Just digged around a bit and saw that on ARM it's not even a real nop.
> The compiler emits:
> 
> 	push    {lr}
> 	bl      8010e7c0 <__gnu_mcount_nc>
> 
> Which is then turned into a nop by replacing the second instruction with
> 
> 	add   sp, sp, #4
> 
> to bring the stack pointer back to its original value. This indeed must
> be processed by the CPU pipeline. I wonder if that could be optimized by
> replacing both instructions with a nop. I have no idea though if that's
> feasible at all or if the overhead would even get smaller by that.

The problem is that there's no easy way to do that, because a task
could have been preempted after doing the 'push {lr}' and before the
'bl'. Thus, you create a race by changing either one to a nop first.

I wonder if it would have been better to change the first one to a jump
passed the second :-/

Actually, if you don't mind setups that take a long time, if you change
the first to a jump passed the second, then do synchronize_rcu_rude()
(which may take a while, possibly several seconds or more) then you know
that all users now only see the jump, and none will see the bl. Then
you could convert the bl to nop, and then even change the jump to nop
after that.

To convert back, you would need to reverse it. Convert the first nop
back to a jmp, run synchronize_rcu_rude(). Then convert the second nop
to the bl, and then convert the first to the push {lr}.

> 
> > 
> > Also, there's some configurations that use the old mcount that does add
> > some more code to handle the mcount case.
> > 
> > So if this is just to have us change the kconfig, I'm happy to do that.  
> 
> Yes, would be good to make the kconfig text clear. The overhead itself
> is fine when people know that's the price to pay for getting the
> function tracer.

Agreed. I'll write up a patch.

-- Steve

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: Performance impact of CONFIG_FUNCTION_TRACER

[Sascha Hauer]

On Tue, Jul 05, 2022 at 06:27:46PM -0400, Steven Rostedt wrote:
> On Tue, 5 Jul 2022 23:59:48 +0200
> Sascha Hauer <sha@pengutronix.de> wrote:
> 
> > > 
> > > As I believe due to using a link register for function calls, ARM
> > > requires adding two 4 byte nops to every function where as x86 only
> > > adds a single 5 byte nop.
> > > 
> > > Although nops are very fast (they should not be processed in the CPU's
> > > pipe line, but I don't know if that's true for every arch). It also
> > > affects instruction cache misses, as adding 8 bytes around the code
> > > will cause more cache misses than when they do not exist.  
> > 
> > Just digged around a bit and saw that on ARM it's not even a real nop.
> > The compiler emits:
> > 
> > 	push    {lr}
> > 	bl      8010e7c0 <__gnu_mcount_nc>
> > 
> > Which is then turned into a nop by replacing the second instruction with
> > 
> > 	add   sp, sp, #4
> > 
> > to bring the stack pointer back to its original value. This indeed must
> > be processed by the CPU pipeline. I wonder if that could be optimized by
> > replacing both instructions with a nop. I have no idea though if that's
> > feasible at all or if the overhead would even get smaller by that.
> 
> The problem is that there's no easy way to do that, because a task
> could have been preempted after doing the 'push {lr}' and before the
> 'bl'. Thus, you create a race by changing either one to a nop first.
> 
> I wonder if it would have been better to change the first one to a jump
> passed the second :-/

I gave this a try, but the performance was not better compared to the
stack push/pop operations we have now. I also tried to replace both
instructions with nops (mov r0, r0), still no better performance. I
guess we have to live with it then.

Sascha

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

Re: Performance impact of CONFIG_FUNCTION_TRACER

[Sascha Hauer]

On Tue, Jul 05, 2022 at 06:27:46PM -0400, Steven Rostedt wrote:
> On Tue, 5 Jul 2022 23:59:48 +0200
> Sascha Hauer <sha@pengutronix.de> wrote:
> 
> > > 
> > > As I believe due to using a link register for function calls, ARM
> > > requires adding two 4 byte nops to every function where as x86 only
> > > adds a single 5 byte nop.
> > > 
> > > Although nops are very fast (they should not be processed in the CPU's
> > > pipe line, but I don't know if that's true for every arch). It also
> > > affects instruction cache misses, as adding 8 bytes around the code
> > > will cause more cache misses than when they do not exist.  
> > 
> > Just digged around a bit and saw that on ARM it's not even a real nop.
> > The compiler emits:
> > 
> > 	push    {lr}
> > 	bl      8010e7c0 <__gnu_mcount_nc>
> > 
> > Which is then turned into a nop by replacing the second instruction with
> > 
> > 	add   sp, sp, #4
> > 
> > to bring the stack pointer back to its original value. This indeed must
> > be processed by the CPU pipeline. I wonder if that could be optimized by
> > replacing both instructions with a nop. I have no idea though if that's
> > feasible at all or if the overhead would even get smaller by that.
> 
> The problem is that there's no easy way to do that, because a task
> could have been preempted after doing the 'push {lr}' and before the
> 'bl'. Thus, you create a race by changing either one to a nop first.
> 
> I wonder if it would have been better to change the first one to a jump
> passed the second :-/

I gave this a try, but the performance was not better compared to the
stack push/pop operations we have now. I also tried to replace both
instructions with nops (mov r0, r0), still no better performance. I
guess we have to live with it then.

Sascha

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel