Message ID | 20161021011804.10002-1-nghosh@us.ibm.com |
---|---|
State | Not Applicable |
Headers | show |
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@us.ibm.com wrote: > From: Nirapada Ghosh <nghosh@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@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@openvswitch.org > http://openvswitch.org/mailman/listinfo/dev
Ben Pfaff <blp@ovn.org> wrote on 12/12/2016 03:32:55 PM: > From: Ben Pfaff <blp@ovn.org> > To: Ryan Moats/Omaha/IBM@IBMUS > Cc: dev@openvswitch.org, Nirapada Ghosh/San Jose/IBM@IBMUS > Date: 12/12/2016 03:33 PM > Subject: Re: [ovs-dev] [PATCH V16] Function tracer to trace all function calls > > 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@us.ibm.com wrote: > > From: Nirapada Ghosh <nghosh@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 ondebugging > > 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 [entryand 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@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 honorsadditional > > 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. Youmay 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@openvswitch.org > > http://openvswitch.org/mailman/listinfo/dev > Sorry about dropping the ball here Ben, While I was shepherding this patch set through review, I've not looked at this version, nor do I expect to have time to review it in the near future. Ryan
On Mon, Dec 12, 2016 at 03:42:19PM -0600, Ryan Moats wrote: > Ben Pfaff <blp@ovn.org> wrote on 12/12/2016 03:32:55 PM: > > Ryan, at one point you were shepherding this patch through review. Are > > you still doing that? Is it ready for me to review? > > While I was shepherding this patch set through review, I've not > looked at this version, nor do I expect to have time to review it in > the near future. OK. Nirapada, is this still something that you'd like to get into OVS? Is it ready for review?
On Mon, Dec 12, 2016 at 04:20:52PM -0800, Ben Pfaff wrote: > On Mon, Dec 12, 2016 at 03:42:19PM -0600, Ryan Moats wrote: > > Ben Pfaff <blp@ovn.org> wrote on 12/12/2016 03:32:55 PM: > > > Ryan, at one point you were shepherding this patch through review. Are > > > you still doing that? Is it ready for me to review? > > > > While I was shepherding this patch set through review, I've not > > looked at this version, nor do I expect to have time to review it in > > the near future. > > OK. > > Nirapada, is this still something that you'd like to get into OVS? Is > it ready for review? If so, it will need to be rebased and reposted because of changes that have been committed to OVS in the meantime.
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