Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Tue, 5 Jul 2022 12:54:16 +0200
To:     linux-kernel@vger.kernel.org
Cc:     linux-arm-kernel@lists.infradead.org,
        Steven Rostedt <rostedt@goodmis.org>,
        Ingo Molnar <mingo@redhat.com>, kernel@pengutronix.de
Subject: Performance impact of CONFIG_FUNCTION_TRACER
Message-ID: <20220705105416.GE5208@pengutronix.de>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
User-Agent: Mutt/1.10.1 (2018-07-13)
From:   Sascha Hauer <sha@pengutronix.de>
Precedence: bulk

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 |