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, [email protected] wrote: > From: Nirapada Ghosh <[email protected]> > > 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 <[email protected]> > --- > 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 > [email protected] > http://openvswitch.org/mailman/listinfo/dev _______________________________________________ dev mailing list [email protected] https://mail.openvswitch.org/mailman/listinfo/ovs-dev
