"dev" <[email protected]> wrote on 06/13/2016 11:24:21 PM:
> From: Nirapada Ghosh/San Jose/IBM@IBMUS > To: [email protected] > Date: 06/13/2016 11:28 PM > Subject: [ovs-dev] [PATCH V4] Function tracer to trace all function calls > Sent by: "dev" <[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. > > To enable this feature, ovs needs needs to be configured with > "--enable-ft" command line argument [i.e. configure --enable-ft] > > This instrumentation logs the tracing output in separate log files > namely func_trace_<pid>.log. It does not use VLOG mechanism for > logging as that will make the patch very complicated to avoid > recursion in the trace routine. > > This feature starts dumping output, only in debug mode, which means > ovs-appctl -t <module> vlog/set any:any:dbg should be used to enable > this logging. > > Currently, only ovn-northd, ovn-controller, vswitchd are instrumented. > > It is intended to be used for debugging purposes. > > Signed-off-by: Nirapada Ghosh <[email protected]> > > --- > configure.ac | 10 +++ > include/openvswitch/vlog.h | 1 + > lib/vlog.c | 22 +++++++ > ovn/controller/automake.mk | 9 +++ > ovn/controller/ovn-controller.c | 10 +++ > ovn/northd/automake.mk | 9 +++ > ovn/northd/ovn-northd.c | 10 +++ > third-party/function_tracer.c | 126 +++++++++++++++++++++++++++ > +++++++++++ > third-party/generate_ft_report.py | 80 ++++++++++++++++++++++++ > utilities/automake.mk | 1 + > vswitchd/automake.mk | 8 +++ > vswitchd/ovs-vswitchd.c | 9 +++ > 12 files changed, 295 insertions(+) > create mode 100644 third-party/function_tracer.c > create mode 100644 third-party/generate_ft_report.py > > diff --git a/configure.ac b/configure.ac > index 05d80d5..4abb2ea 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, > +[ --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/include/openvswitch/vlog.h b/include/openvswitch/vlog.h > index de64cbd..2df8796 100644 > --- a/include/openvswitch/vlog.h > +++ b/include/openvswitch/vlog.h > @@ -57,6 +57,7 @@ enum vlog_level { > VLL_N_LEVELS > }; > > +void __attribute__ ((no_instrument_function)) vlog_directory(char *, int); > const char *vlog_get_level_name(enum vlog_level); > enum vlog_level vlog_get_level_val(const char *name); > > diff --git a/lib/vlog.c b/lib/vlog.c > index 30b5bc2..468d444 100644 > --- a/lib/vlog.c > +++ b/lib/vlog.c > @@ -1138,6 +1138,28 @@ vlog_valist(const struct vlog_module *module, > enum vlog_level level, > } > } > > +void __attribute__ ((no_instrument_function)) > +vlog_directory(char *dir,int len) > +{ > + int dir_len; > + if (log_file_name == NULL) { > + dir_len = strlen(ovs_logdir()); > + if (dir_len > len) { > + *dir = '\0'; > + } > + snprintf(dir, dir_len, "%s", ovs_logdir()); > + } else { > + char *fname = strrchr(log_file_name,'/'); > + if (fname) { > + dir_len = strlen(log_file_name) - strlen(fname)+1; > + if (dir_len > len) { > + *dir = '\0'; > + } else { > + snprintf(dir, dir_len, "%s", log_file_name); > + } > + } > + } > +} > void > vlog(const struct vlog_module *module, enum vlog_level level, > const char *message, ...) > diff --git a/ovn/controller/automake.mk b/ovn/controller/automake.mk > index cf57bbd..61efcf4 100644 > --- a/ovn/controller/automake.mk > +++ b/ovn/controller/automake.mk > @@ -1,3 +1,9 @@ > +if ENABLE_FT > +CFLAGS += -g -finstrument-functions \ > + `pkg-config --cflags glib-2.0` \ > + `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt > +endif > + > bin_PROGRAMS += ovn/controller/ovn-controller > ovn_controller_ovn_controller_SOURCES = \ > ovn/controller/binding.c \ > @@ -20,6 +26,9 @@ ovn_controller_ovn_controller_SOURCES = \ > ovn/controller/ovn-controller.h \ > ovn/controller/physical.c \ > ovn/controller/physical.h > +if ENABLE_FT > +ovn_controller_ovn_controller_SOURCES += third-party/function_tracer.c > +endif > ovn_controller_ovn_controller_LDADD = ovn/lib/libovn.la lib/libopenvswitch.la > man_MANS += ovn/controller/ovn-controller.8 > EXTRA_DIST += ovn/controller/ovn-controller.8.xml > diff --git a/ovn/controller/ovn-controller.c b/ovn/controller/ovn-controller.c > index 356a94b..10479e8 100644 > --- a/ovn/controller/ovn-controller.c > +++ b/ovn/controller/ovn-controller.c > @@ -62,10 +62,19 @@ static unixctl_cb_func ct_zone_list; > #define DEFAULT_BRIDGE_NAME "br-int" > > static void parse_options(int argc, char *argv[]); > +static bool g_command_line_args_parsed = false; > OVS_NO_RETURN static void usage(void); > > static char *ovs_remote; > > +bool is_command_line_args_parsed(void); > + I don't believe the above is necessary, all that is needed is to put void in the argument call below > +bool > +is_command_line_args_parsed() > +{ > + return g_command_line_args_parsed; > +} > + > struct local_datapath * > get_local_datapath(const struct hmap *local_datapaths, uint32_t tunnel_key) > { > @@ -614,6 +623,7 @@ parse_options(int argc, char *argv[]) > VLOG_FATAL("exactly zero or one non-option argument required; " > "use --help for usage"); > } > + g_command_line_args_parsed = true; > } > > static void > diff --git a/ovn/northd/automake.mk b/ovn/northd/automake.mk > index 6e713fc..ae8dc3f 100644 > --- a/ovn/northd/automake.mk > +++ b/ovn/northd/automake.mk > @@ -1,6 +1,15 @@ > # ovn-northd > +if ENABLE_FT > +CFLAGS += -g -finstrument-functions \ > + `pkg-config --cflags glib-2.0` \ > + `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt > +endif > + > bin_PROGRAMS += ovn/northd/ovn-northd > ovn_northd_ovn_northd_SOURCES = ovn/northd/ovn-northd.c > +if ENABLE_FT > +ovn_northd_ovn_northd_SOURCES += third-party/function_tracer.c > +endif > ovn_northd_ovn_northd_LDADD = \ > ovn/lib/libovn.la \ > ovsdb/libovsdb.la \ > diff --git a/ovn/northd/ovn-northd.c b/ovn/northd/ovn-northd.c > index d53fca9..35fe6b0 100644 > --- a/ovn/northd/ovn-northd.c > +++ b/ovn/northd/ovn-northd.c > @@ -42,6 +42,9 @@ > > VLOG_DEFINE_THIS_MODULE(ovn_northd); > > +bool is_command_line_args_parsed(void); Again, I don't believe this is necessary, just put void in the arg list of the declaration below > +static bool g_command_line_args_parsed = false; > + > static unixctl_cb_func ovn_northd_exit; > > struct northd_context { > @@ -119,6 +122,12 @@ enum ovn_stage { > #undef PIPELINE_STAGE > }; > > +bool > +is_command_line_args_parsed() > +{ > + return g_command_line_args_parsed; > +} > + > /* Due to various hard-coded priorities need to implement ACLs, the > * northbound database supports a smaller range of ACL priorities than > * are available to logical flows. This value is added to an ACL > @@ -2490,6 +2499,7 @@ parse_options(int argc OVS_UNUSED, char > *argv[] OVS_UNUSED) > } > > free(short_options); > + g_command_line_args_parsed = true; > } > > static void > diff --git a/third-party/function_tracer.c b/third-party/function_tracer.c > new file mode 100644 > index 0000000..b6bbd20 > --- /dev/null > +++ b/third-party/function_tracer.c > @@ -0,0 +1,126 @@ > +/* > + * This file implements routines needed to log all function calls' > + * entry and exit timestamps along with it's hex address. With > + * python tool generate_ft_report.py, this log can be converted with > + * symbol names for offline analysis. > + */ > + > +#include <stdio.h> > +#include <sys/types.h> > +#include <unistd.h> > +#include <time.h> > +#include <sys/time.h> > +#include <string.h> > +#include "openvswitch/vlog.h" > + > +VLOG_DEFINE_THIS_MODULE(trace); > + > +#define LOG_FILE_NAME_LEN 256 > +#define LOG_DIR_NAME_LEN 128 > +#define LOG_FILENAME_PREFIX "func_trace" > +#define CURRENT_LOG_LEVEL this_module.min_level > + > +/* File pointer for logging the trace output. */ > +static FILE *log_fp; > + > +/* External functions used here */ > +extern bool is_command_line_args_parsed(void); > + > +/* Prototypes for the functions declared/used in this file. */ > +void __attribute__ ((constructor,no_instrument_function)) ft_begin (void); > +void __attribute__ ((destructor,no_instrument_function)) ft_end(void); > +void __attribute__ ((no_instrument_function)) ft(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); > +int __attribute__ ((no_instrument_function)) format_time(struct timeval *lt, > + char *buf, > + size_t size); > + > +void __attribute__ ((constructor,no_instrument_function)) > +ft_begin(void) > +{ > + /* Nothing at this point, but needed */ > +} > + > +void __attribute__ ((no_instrument_function)) > +ft_log_open(void) > +{ > + char log_name[LOG_FILE_NAME_LEN]; > + char dir_name[LOG_DIR_NAME_LEN]; > + > + vlog_directory(dir_name, LOG_DIR_NAME_LEN); > + snprintf(log_name, LOG_FILE_NAME_LEN, "%s/%s_%d.log", > + dir_name, LOG_FILENAME_PREFIX, getpid()); > + if ((log_fp = fopen(log_name, "w")) == NULL) { > + fprintf(stderr, "Failed to open output trace file: %s\n", log_name); > + } > +} > + > + > +void __attribute__ ((destructor,no_instrument_function)) > +ft_end(void) > +{ > + if (log_fp != NULL) { > + fclose(log_fp); > + } > +} > + > +/* Gets the current timestamp into the input buffer in ascii format */ > +int __attribute__ ((no_instrument_function)) > +format_time(struct timeval *lt, char *buf, size_t size) > +{ > + struct tm gm_time; > + int bytes_written = -1; > + > + gmtime_r(<->tv_sec,&gm_time); > + bytes_written = strftime(buf, size, "%Y-%m-%dT%H:%M:%S", &gm_time); > + if ((bytes_written > 0) && ((size_t) bytes_written < size)) { > + int tmp = snprintf(buf + bytes_written, > + size - (size_t) bytes_written, ".%06d", > + (int) lt->tv_usec); > + bytes_written = (tmp > 0) ? bytes_written + tmp : -1; > + } > + return bytes_written; > +} > + > + > +void __attribute__ ((no_instrument_function)) > +ft(const char *direction, void *func, void *caller) > +{ > + char timestr[64]; > + struct timeval ltime; > + > + if (log_fp == NULL && is_command_line_args_parsed()) { > + ft_log_open(); > + } > + if ((!is_command_line_args_parsed()) || (log_fp == NULL)) { > + return; > + } > + if (gettimeofday(<ime, NULL) != 0) { > + return; > + } > + if (format_time(<ime, timestr, sizeof(timestr)) <= 0) { > + return; > + } > + /* Trace only if log level is >= DEBUG */ > + if (CURRENT_LOG_LEVEL >= VLL_DBG) { > + fprintf(log_fp, "%s>%s>%p>%p\n", timestr, > + direction, func, caller); > + } > + fflush(log_fp); > +} > + > +void __attribute__ ((no_instrument_function)) > +__cyg_profile_func_enter(void *func, void *caller) > +{ > + ft("entry", func, caller); > +} > + > +void __attribute__ ((no_instrument_function)) > +__cyg_profile_func_exit(void *func, void *caller) > +{ > + ft("exit", func, caller); > +} > diff --git a/third-party/generate_ft_report.py b/third-party/ > generate_ft_report.py > new file mode 100644 > index 0000000..7e49489 > --- /dev/null > +++ b/third-party/generate_ft_report.py > @@ -0,0 +1,80 @@ > +#!/usr/bin/env python > +# Copyright (c) 2016 Red Hat, 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. > +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, this returns the symbol name > + """ > + p = subprocess.Popen("addr2line -e " + exe + ' --functions ' + > + func_addr, stdout=subprocess.PIPE, shell=True) Doesn't addr2line require debugging information to work? In other words are you assuming that the code base is compiled with -g and/or not stripped? If that is the case, then the commit message should be updated to reflect that fact. Ryan Moats _______________________________________________ dev mailing list [email protected] http://openvswitch.org/mailman/listinfo/dev
