[ovs-dev] [PATCH V16] Function tracer to trace all function calls
Ben Pfaff
blp at ovn.org
Mon Dec 12 21:32:55 UTC 2016
Ryan, at one point you were shepherding this patch through review. Are
you still doing that? Is it ready for me to review?
Thanks,
Ben.
On Thu, Oct 20, 2016 at 06:18:04PM -0700, nghosh at us.ibm.com wrote:
> From: Nirapada Ghosh <nghosh at us.ibm.com>
>
> In some circumstances, we might need to figure out where in
> code, the CPU time is being spent most, so as to pinpoint
> the bottleneck and thereby resolve it with proper changes.
> Using '-finstrument-functions' flag, that can be achieved, and
> this patch exactly does that.
>
> There is a python file [generate_ft_report.py] with the patch,
> that may be used to convert this trace output to a human readable
> format with symbol names instead of address and their execution
> times. This tool uses addr2line that expects the executable to
> be built with -g flag.
>
> To enable this feature, ovs needs to be configured with
> "--enable-ft" command line argument [i.e. configure --enable-ft]
>
> This feature logs the tracing output to log files,
> that is set using "ovs-appctl vlog/trace <filename>" command.
> "ovs-appctl vlog/trace off" turns the logging off.
>
> The feature uses the hooks GNU-C provides when compiled with
> -finstrument-functions flag, we just have to implement
> them. What it means is, once you compile the code with --enable-ft
> option, function calls are going to be routed to the tracing routine.
> In other words, even if we do disable tracing, the extra calls would
> be happening even though with very less CPU overhead as the calls
> would return right away. The initialization call [ constructor ] happens
> even before main() is invoked, so no chance of completely disabling
> tracing when configured with --enable-ft. So, unless you intend on debugging
> a module in OVS, this option would better be turned off by default.
>
> It is intended to be used for debugging purposes only. Compiling with
> --enable-ft flag will add two calls for every function call [entry and exit]
> thereby two log lines into trace log output file if enabled, please turn it on
> when you need to and turn it off when done. If you are not debugging a
> problem that requires function-tracing, please do not even compile with
> --enable-ft flag.
>
> Signed-off-by: Nirapada Ghosh <nghosh at us.ibm.com>
> ---
> INSTALL.Fedora.md | 4 +-
> INSTALL.rst | 4 ++
> NEWS | 2 +
> configure.ac | 10 +++
> lib/vlog-unixctl.man | 19 ++++++
> lib/vlog.c | 143 ++++++++++++++++++++++++++++++++++++++++
> utilities/automake.mk | 8 +++
> utilities/generate_ft_report.py | 83 +++++++++++++++++++++++
> utilities/ovs-appctl.8.in | 18 +++++
> 9 files changed, 289 insertions(+), 2 deletions(-)
> create mode 100644 utilities/generate_ft_report.py
>
> diff --git a/INSTALL.Fedora.md b/INSTALL.Fedora.md
> index 028a992..6faa1c9 100644
> --- a/INSTALL.Fedora.md
> +++ b/INSTALL.Fedora.md
> @@ -37,11 +37,11 @@ below.
>
> ### Preparing to Build Open vSwitch RPMs with a GIT Tree
> From the top-level directory of the git tree, execute the following
> -commands:
> +commands, use "--enable-ft" to enable function tracing:
>
> ```
> ./boot.sh
> -./configure
> +./configure [ --enable-ft ]
> ```
>
> ### Preparing to Build Open vSwitch RPMs from a Tarball
> diff --git a/INSTALL.rst b/INSTALL.rst
> index 07d69f1..27bf994 100644
> --- a/INSTALL.rst
> +++ b/INSTALL.rst
> @@ -294,6 +294,10 @@ To build with gcov code coverage support, add ``--enable-coverage``::
>
> $ ./configure --enable-coverage
>
> +To build with function tracing enabled, add ``--enable-ft``::
> +
> + $ ./configure --enable-ft
> +
> The configure script accepts a number of other options and honors additional
> environment variables. For a full list, invoke configure with the ``--help``
> option::
> diff --git a/NEWS b/NEWS
> index d07ec45..300e92f 100644
> --- a/NEWS
> +++ b/NEWS
> @@ -1,5 +1,7 @@
> Post-v2.6.0
> ---------------------
> + - ovs-appctl:
> + * New "vlog/trace" command, this will add function tracing capability.
> - OVN:
> * QoS is now implemented via egress shaping rather than ingress policing.
> * DSCP marking is now supported, via the new northbound QoS table.
> diff --git a/configure.ac b/configure.ac
> index 2f854dd..2bcad39 100644
> --- a/configure.ac
> +++ b/configure.ac
> @@ -28,6 +28,16 @@ AC_PROG_MKDIR_P
> AC_PROG_FGREP
> AC_PROG_EGREP
>
> +AC_ARG_ENABLE([ft],
> + [AC_HELP_STRING([--enable-ft], [Turn on function tracing])],
> + [case "${enableval}" in
> + (yes) ft=true ;;
> + (no) ft=false ;;
> + (*) AC_MSG_ERROR([bad value ${enableval} for --enable-ft]) ;;
> + esac],
> + [ft=false])
> +AM_CONDITIONAL([ENABLE_FT], [test x$ft = xtrue])
> +
> AC_ARG_VAR([PERL], [path to Perl interpreter])
> AC_PATH_PROG([PERL], perl, no)
> if test "$PERL" = no; then
> diff --git a/lib/vlog-unixctl.man b/lib/vlog-unixctl.man
> index 7372a7e..f13e143 100644
> --- a/lib/vlog-unixctl.man
> +++ b/lib/vlog-unixctl.man
> @@ -82,3 +82,22 @@ the keyword \fBany\fR disables rate limits for every log module.
> The \fBvlog/enable\-rate\-limit\fR command, whose syntax is the same
> as \fBvlog/disable\-rate\-limit\fR, can be used to re-enable a rate
> limit that was previously disabled.
> +.
> +.IP "\fBvlog/trace\fR \fIfilename\fR"
> +Turns on function tracing output to \fIfilename\fR, which will be
> +overwritten if it already exists. When function tracing is enabled,
> +each time execution enters or exits a function, OVS logs the current
> +time in microseconds, either \fBenter\fR or \fBexit\fR, and the
> +address of the function and its caller. This output, suitably
> +analyzed (e.g. with the script provided in the OVS tree as
> +\fButilities/generate_ft_report.py\fR), can be useful for profiling
> +and debugging.
> +.IP
> +This feature is available only when Open vSwitch was built with GNU C
> +and configured with \fB\-\-enable\-ft\fR. Configuring with
> +\fB\-\-enable\-ft\fR adds significant runtime overhead, which
> +increases further when tracing is enabled.
> +.
> +.IP "\fBvlog/trace\fR \fBoff\fR"
> +Disables function tracing.
> +.IP
> diff --git a/lib/vlog.c b/lib/vlog.c
> index 333337b..6d5edea 100644
> --- a/lib/vlog.c
> +++ b/lib/vlog.c
> @@ -46,6 +46,36 @@
>
> VLOG_DEFINE_THIS_MODULE(vlog);
>
> +#if defined(ENABLE_FT) && defined(__GNUC__)
> +
> +/* Mutex for function tracing globals. */
> +static struct ovs_mutex function_tracing_mutex = OVS_MUTEX_INITIALIZER;
> +
> +/* File pointer for logging trace output. */
> +static FILE *function_tracing_fp OVS_GUARDED_BY(funcion_tracing_mutex) = NULL;
> +
> +/* Global flag holding current state of function-tracing-enabled or not. */
> +static bool function_tracing_enabled OVS_GUARDED_BY(funcion_tracing_mutex) = 0;
> +
> +/* Prototypes for the functions declared/used in this file. */
> +static void close_trace_file(const char *ft_log_file);
> +static const char *vlog_set_fn_tracing_log(const char *s_);
> +
> +static void vlog_unixctl_set_fn_tracing(struct unixctl_conn *conn,
> + int argc,
> + const char *argv[],
> + void *aux OVS_UNUSED);
> +void __attribute__ ((constructor,no_instrument_function)) fn_trace_begin(void);
> +void __attribute__ ((destructor,no_instrument_function)) fn_trace_end(void);
> +void __attribute__ ((no_instrument_function)) trace_func_call(
> + const char *direction,
> + void *func, void * caller);
> +void __attribute__ ((no_instrument_function)) __cyg_profile_func_enter(
> + void *func, void *caller);
> +void __attribute__ ((no_instrument_function)) __cyg_profile_func_exit(
> + void *func, void *caller);
> +#endif
> +
> /* ovs_assert() logs the assertion message, so using ovs_assert() in this
> * source file could cause recursion. */
> #undef ovs_assert
> @@ -792,6 +822,10 @@ vlog_init(void)
> unixctl_command_register(
> "vlog/set", "{spec | PATTERN:destination:pattern}",
> 1, INT_MAX, vlog_unixctl_set, NULL);
> +#if defined(ENABLE_FT) && defined(__GNUC__)
> + unixctl_command_register("vlog/trace", "filename",
> + 1, 1, vlog_unixctl_set_fn_tracing, NULL);
> +#endif
> unixctl_command_register("vlog/list", "", 0, 0, vlog_unixctl_list,
> NULL);
> unixctl_command_register("vlog/list-pattern", "", 0, 0,
> @@ -1289,3 +1323,112 @@ Logging options:\n\
> --syslog-target=HOST:PORT also send syslog msgs to HOST:PORT via UDP\n",
> ovs_logdir(), program_name);
> }
> +
> +#if defined(ENABLE_FT) && defined(__GNUC__)
> +
> +/* Unixctl callback routine to enable or disable function tracing,
> + * A valid filename is required to enable it,"off" to turn it off. */
> +static void
> +vlog_unixctl_set_fn_tracing(struct unixctl_conn *conn,
> + int argc OVS_UNUSED, const char *argv[],
> + void *aux OVS_UNUSED)
> +{
> + const char *error = vlog_set_fn_tracing_log(argv[1]);
> + if (error) {
> + unixctl_command_reply_error(conn, error);
> + } else {
> + unixctl_command_reply(conn, NULL);
> + }
> +}
> +
> +static void
> +close_trace_file(const char *ft_log_file) OVS_EXCLUDED(function_tracing_mutex)
> +{
> + ovs_mutex_lock(&function_tracing_mutex);
> + function_tracing_enabled = false;
> + fclose(function_tracing_fp);
> + function_tracing_fp = NULL;
> + ovs_mutex_unlock(&function_tracing_mutex);
> + VLOG_INFO("function-tracing-log file %s closed", ft_log_file);
> +}
> +
> +/* Set function tracing on. A value of "off" disables tracing, otherwise
> + * the argument is name of the file where tracing data will be written.
> + * Returns null if successful, otherwise an error
> + * message that the caller must free(). */
> +static const char *
> +vlog_set_fn_tracing_log(const char *s) OVS_EXCLUDED(function_tracing_mutex)
> +{
> + static char *ft_log_file = NULL;
> +
> + if (strncmp(s,"off",4) == 0) {
> + if (!function_tracing_enabled) {
> + return "FT already disabled, skipping";
> + }
> + close_trace_file(ft_log_file);
> + return NULL;
> + }
> +
> + if (function_tracing_enabled) {
> + if (!strcmp(ft_log_file, s)) {
> + return "Tracing is already on, command ignored";
> + }
> + close_trace_file(ft_log_file);
> + }
> + ovs_mutex_lock(&function_tracing_mutex);
> + function_tracing_fp = fopen(s, "w");
> + if (!function_tracing_fp) {
> + ovs_mutex_unlock(&function_tracing_mutex);
> + return "Failed to open file, command failed";
> + }
> + function_tracing_enabled = true;
> + if (ft_log_file) {
> + free(ft_log_file);
> + }
> + ft_log_file = xstrdup(s);
> + ovs_mutex_unlock(&function_tracing_mutex);
> +
> + VLOG_INFO("function-tracing-log file %s opened", s);
> + return NULL;
> +}
> +
> +void __attribute__ ((constructor, no_instrument_function))
> +fn_trace_begin(void)
> +{
> + /* Nothing at this point, but this function is needed */
> +}
> +
> +void __attribute__ ((destructor, no_instrument_function))
> +fn_trace_end(void)
> +{
> + if (function_tracing_fp) {
> + fclose(function_tracing_fp);
> + }
> +}
> +
> +void __attribute__ ((no_instrument_function))
> +trace_func_call(const char *direction, void *func, void *caller)
> +{
> + struct timeval ltime;
> + xgettimeofday(<ime);
> + fprintf(function_tracing_fp, "%ld.%ld %s %p %p\n",
> + ltime.tv_sec,ltime.tv_usec, direction, func, caller);
> + fflush(function_tracing_fp);
> +}
> +
> +void __attribute__ ((no_instrument_function))
> +__cyg_profile_func_enter(void *func, void *caller)
> +{
> + if (function_tracing_enabled) {
> + trace_func_call("entry", func, caller);
> + }
> +}
> +
> +void __attribute__ ((no_instrument_function))
> +__cyg_profile_func_exit(void *func, void *caller)
> +{
> + if (function_tracing_enabled) {
> + trace_func_call("exit", func, caller);
> + }
> +}
> +#endif
> diff --git a/utilities/automake.mk b/utilities/automake.mk
> index 380418a..11a3183 100644
> --- a/utilities/automake.mk
> +++ b/utilities/automake.mk
> @@ -1,3 +1,10 @@
> +if ENABLE_FT
> +# Following exclude functions are needed to break recursive call \
> + because tracing routine uses them.
> +AM_CFLAGS += -g -finstrument-functions -DENABLE_FT \
> + -finstrument-functions-exclude-function-list=fprintf,xgettimeofday
> +endif
> +
> bin_PROGRAMS += \
> utilities/ovs-appctl \
> utilities/ovs-testcontroller \
> @@ -58,6 +65,7 @@ EXTRA_DIST += \
> utilities/ovs-test.in \
> utilities/ovs-vlan-test.in \
> utilities/ovs-vsctl-bashcomp.bash \
> + utilities/generate_ft_report.py \
> utilities/checkpatch.py
> MAN_ROOTS += \
> utilities/ovs-appctl.8.in \
> diff --git a/utilities/generate_ft_report.py b/utilities/generate_ft_report.py
> new file mode 100644
> index 0000000..72857c4
> --- /dev/null
> +++ b/utilities/generate_ft_report.py
> @@ -0,0 +1,83 @@
> +# Copyright (c) 2016 IBM, Inc.
> +# Licensed under the Apache License, Version 2.0 (the "License"); you may
> +# not use this file except in compliance with the License. You may obtain
> +# a copy of the License at
> +#
> +# http://www.apache.org/licenses/LICENSE-2.0
> +#
> +# Unless required by applicable law or agreed to in writing, software
> +# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
> +# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
> +# License for the specific language governing permissions and limitations
> +# under the License.
> +#!/usr/bin/env python
> +import sys
> +import subprocess
> +from datetime import datetime
> +
> +# functions hold the details regarding when it was called, when it was complete
> +functions = {}
> +
> +def find_symbol_name(func_addr, exe):
> + """Give the hex address of a method, returns the symbol name
> + """
> + p = subprocess.Popen("addr2line -e " + exe + ' --functions ' +
> + func_addr, stdout=subprocess.PIPE, shell=True)
> + (out, err) = p.communicate()
> + if not err:
> + tokens = out.split()
> + return tokens[0]
> + return func_addr + "(unknown)"
> +
> +def time_diff(time1, time2):
> + """This method finds the delta between two times passed in ms.
> + Time format passed is "sec.ms"
> + """
> +
> + tokens1 = time1.strip().split('.')
> + tokens2 = time2.strip().split('.')
> + diff_secs = int(tokens2[0]) - int(tokens1[0])
> + diff_in_usecs = diff_secs * 1000000 + int(tokens2[1]) - int(tokens1[1]);
> + delta_time = "%d (ms)" % (diff_in_usecs)
> + return delta_time
> +
> +def update_and_print(tstamp, direction, called, caller,
> + serial, exe, verbose=False):
> + """This method updates the exit-point of a function in functions map,
> + finds out the execution time of that function and prints in human-
> + readable format.
> + """
> + func_name = find_symbol_name(called, exe)
> + if direction == "exit":
> + ## Find out corresponding entry point,
> + try:
> + entry = functions[func_name]
> + if verbose:
> + print "ENTRY:%s EXIT %s" % (entry['timestamp'], tstamp)
> + diff = time_diff(entry['timestamp'], tstamp)
> + print "%d %s %s %s" % (entry['serial'], func_name,
> + entry['caller'], diff)
> + except Exception, ex:
> + print "Function Entry not found, skipping, exception %s" % (ex)
> + else:
> + functions[func_name] = {'timestamp':tstamp, 'caller':caller,
> + 'serial':serial}
> +
> +
> +def main():
> + if len(sys.argv) != 3:
> + print "Usage: %s <exe-file> <log-file>" %sys.argv[0]
> + return
> + exe = sys.argv[1]
> + filename = sys.argv[2]
> + serial = 0
> + with open(filename) as f:
> + for line in f:
> + serial += 1
> + tokens = line.strip().split(' ')
> + #arguments (timestamp, dirn, called, caller,serial,exename)
> + update_and_print(tokens[0], tokens[1], tokens[2],
> + tokens[3], serial, exe)
> +
> +if __name__ == "__main__":
> + main()
> diff --git a/utilities/ovs-appctl.8.in b/utilities/ovs-appctl.8.in
> index 645b62b..539336a 100644
> --- a/utilities/ovs-appctl.8.in
> +++ b/utilities/ovs-appctl.8.in
> @@ -277,6 +277,24 @@ log file to be used.)
> This has no effect if the target application was not invoked with the
> \fB\-\-log\-file\fR option.
> .
> +.IP "\fBvlog/trace\fR \fIfilename\fR"
> +Turns on function tracing output to \fIfilename\fR, which will be
> +overwritten if it already exists. When function tracing is enabled,
> +each time execution enters or exits a function, OVS logs the current
> +time in microseconds, either \fBenter\fR or \fBexit\fR, and the
> +address of the function and its caller. This output, suitably
> +analyzed (e.g. with the script provided in the OVS tree as
> +\fButilities/generate_ft_report.py\fR), can be useful for profiling
> +and debugging.
> +.IP
> +This feature is available only when Open vSwitch was built with GNU C
> +and configured with \fB\-\-enable\-ft\fR. Configuring with
> +\fB\-\-enable\-ft\fR adds significant runtime overhead, which
> +increases further when tracing is enabled.
> +.
> +.IP "\fBvlog/trace\fR \fBoff\fR"
> +Disables function tracing.
> +.
> .SH OPTIONS
> .
> .so lib/common.man
> --
> 2.10.1
>
> _______________________________________________
> dev mailing list
> dev at openvswitch.org
> http://openvswitch.org/mailman/listinfo/dev
More information about the dev
mailing list