diff mbox

[ovs-dev,V5] Function tracer to trace all function calls

Message ID 1465952754-47704-1-git-send-email-nghosh@us.ibm.com
State Superseded
Headers show

Commit Message

Nirapada Ghosh June 15, 2016, 1:05 a.m. UTC 
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 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 <nghosh@us.ibm.com>

---
 configure.ac                      |  10 +++
 include/openvswitch/vlog.h        |   1 +
 lib/vlog.c                        |  23 ++++++-
 ovn/controller/automake.mk        |   9 +++
 ovn/controller/ovn-controller.c   |   9 +++
 ovn/northd/automake.mk            |   9 +++
 ovn/northd/ovn-northd.c           |   9 +++
 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           |   8 +++
 12 files changed, 292 insertions(+), 1 deletion(-)
 create mode 100644 third-party/function_tracer.c
 create mode 100644 third-party/generate_ft_report.py

Comments

Daniele Di Proietto June 15, 2016, 1:58 a.m. UTC | #1 
Hi Nirapada,

When optimizing for the DPDK datapath we have a very similar problem and,
usually, running a simple profiler like perf (
https://perf.wiki.kernel.org/index.php/Main_Page) is enough to highlight
the bottlenecks in terms of CPU usage.

Have you tried perf? Does this infrastructure provide advantages over
sample profiling? I'm not saying that one is better than the other, I'm
just curious!

Thanks,

Daniele

2016-06-14 18:05 GMT-07:00 <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 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 <nghosh@us.ibm.com>
>
> ---
>  configure.ac                      |  10 +++
>  include/openvswitch/vlog.h        |   1 +
>  lib/vlog.c                        |  23 ++++++-
>  ovn/controller/automake.mk        |   9 +++
>  ovn/controller/ovn-controller.c   |   9 +++
>  ovn/northd/automake.mk            |   9 +++
>  ovn/northd/ovn-northd.c           |   9 +++
>  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           |   8 +++
>  12 files changed, 292 insertions(+), 1 deletion(-)
>  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..65fa073 100644
> --- a/lib/vlog.c
> +++ b/lib/vlog.c
> @@ -1137,7 +1137,6 @@ vlog_valist(const struct vlog_module *module, enum
> vlog_level level,
>          errno = save_errno;
>      }
>  }
> -
>  void
>  vlog(const struct vlog_module *module, enum vlog_level level,
>       const char *message, ...)
> @@ -1262,6 +1261,28 @@ vlog_should_drop(const struct vlog_module *module,
> enum vlog_level level,
>      return false;
>  }
>
> +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_rate_limit(const struct vlog_module *module, enum vlog_level level,
>                  struct vlog_rate_limit *rl, 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..4f71b15 100644
> --- a/ovn/controller/ovn-controller.c
> +++ b/ovn/controller/ovn-controller.c
> @@ -61,11 +61,19 @@ static unixctl_cb_func ct_zone_list;
>
>  #define DEFAULT_BRIDGE_NAME "br-int"
>
> +static bool g_command_line_args_parsed = false;
>  static void parse_options(int argc, char *argv[]);
> +
>  OVS_NO_RETURN static void usage(void);
>
>  static char *ovs_remote;
>
> +bool
> +is_command_line_args_parsed(void)
> +{
> +    return g_command_line_args_parsed;
> +}
> +
>  struct local_datapath *
>  get_local_datapath(const struct hmap *local_datapaths, uint32_t
> tunnel_key)
>  {
> @@ -614,6 +622,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..6ffef96 100644
> --- a/ovn/northd/ovn-northd.c
> +++ b/ovn/northd/ovn-northd.c
> @@ -42,6 +42,8 @@
>
>  VLOG_DEFINE_THIS_MODULE(ovn_northd);
>
> +static bool g_command_line_args_parsed = false;
> +
>  static unixctl_cb_func ovn_northd_exit;
>
>  struct northd_context {
> @@ -119,6 +121,12 @@ enum ovn_stage {
>  #undef PIPELINE_STAGE
>  };
>
> +bool
> +is_command_line_args_parsed(void)
> +{
> +    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 +2498,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..422fccd
> --- /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();
> +
> +/* 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(&lt->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(&ltime, NULL) != 0) {
> +        return;
> +    }
> +    if (format_time(&ltime, 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)
> +    (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
> +    """
> +    date_obj1 = datetime.strptime(time1, '%Y-%m-%dT%H:%M:%S.%f')
> +    date_obj2 = datetime.strptime(time2, '%Y-%m-%dT%H:%M:%S.%f')
> +    delta = date_obj2 - date_obj1
> +    return delta
> +
> +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 "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,exe)
> +            update_and_print(tokens[0], tokens[1], tokens[2],
> +                             tokens[3], serial, exe)
> +
> +if __name__ == "__main__":
> +    main()
> diff --git a/utilities/automake.mk b/utilities/automake.mk
> index 1cc66b6..747cb36 100644
> --- a/utilities/automake.mk
> +++ b/utilities/automake.mk
> @@ -57,6 +57,7 @@ EXTRA_DIST += \
>         utilities/ovs-vlan-test.in \
>         utilities/ovs-vsctl-bashcomp.bash \
>         utilities/qemu-wrap.py \
> +       third-party/generate_ft_report.py \
>         utilities/checkpatch.py
>  MAN_ROOTS += \
>         utilities/ovs-appctl.8.in \
> diff --git a/vswitchd/automake.mk b/vswitchd/automake.mk
> index 8d7f3ea..bc4cd54 100644
> --- a/vswitchd/automake.mk
> +++ b/vswitchd/automake.mk
> @@ -1,3 +1,8 @@
> +if ENABLE_FT
> +CFLAGS += -g -finstrument-functions  \
> +         `pkg-config --cflags glib-2.0` \
> +         `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt
> +endif
>  sbin_PROGRAMS += vswitchd/ovs-vswitchd
>  man_MANS += vswitchd/ovs-vswitchd.8
>  DISTCLEANFILES += \
> @@ -11,6 +16,9 @@ vswitchd_ovs_vswitchd_SOURCES = \
>         vswitchd/system-stats.h \
>         vswitchd/xenserver.c \
>         vswitchd/xenserver.h
> +if ENABLE_FT
> +vswitchd_ovs_vswitchd_SOURCES += third-party/function_tracer.c
> +endif
>  vswitchd_ovs_vswitchd_LDADD = \
>         ofproto/libofproto.la \
>         lib/libsflow.la \
> diff --git a/vswitchd/ovs-vswitchd.c b/vswitchd/ovs-vswitchd.c
> index 72448bb..ba985fd 100644
> --- a/vswitchd/ovs-vswitchd.c
> +++ b/vswitchd/ovs-vswitchd.c
> @@ -51,6 +51,7 @@
>
>  VLOG_DEFINE_THIS_MODULE(vswitchd);
>
> +static bool g_command_line_args_parsed = false;
>  /* --mlockall: If set, locks all process memory into physical RAM,
> preventing
>   * the kernel from paging any of its memory to disk. */
>  static bool want_mlockall;
> @@ -60,6 +61,12 @@ static unixctl_cb_func ovs_vswitchd_exit;
>  static char *parse_options(int argc, char *argv[], char **unixctl_path);
>  OVS_NO_RETURN static void usage(void);
>
> +bool
> +is_command_line_args_parsed(void)
> +{
> +    return g_command_line_args_parsed;
> +}
> +
>  int
>  main(int argc, char *argv[])
>  {
> @@ -240,6 +247,7 @@ parse_options(int argc, char *argv[], char
> **unixctl_pathp)
>          VLOG_FATAL("at most one non-option argument accepted; "
>                     "use --help for usage");
>      }
> +    g_command_line_args_parsed = true;
>  }
>
>  static void
> --
> 1.9.1
>
> _______________________________________________
> dev mailing list
> dev@openvswitch.org
> http://openvswitch.org/mailman/listinfo/dev
>
Hui Kang June 15, 2016, 5:02 a.m. UTC | #2 
Hi, Daniele,
I am also interesting in profiling the ovs process and would like to
participate in the discussion.


I am using oprofile-1.1.0 to profiling the ovn-northd process. I believe
oprofile-1.1.0 share the same underlying profiling mechanism as Linux perf
(correct me if I am wrong). However, it is hard for me to understand the
output of the profiled data. For example, in a highly overloaded ovn-northd
process, the output of opreport --callgraph is

===============================================================
CPU: Intel Sandy Bridge microarchitecture, speed 3300 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit
mask of 0x00 (No unit mask) count 90000
samples  %        image name               symbol name
-------------------------------------------------------------------------------
  1         0.3497  ovn-northd
build_lswitch_flows.constprop.16
  1         0.3497  ovn-northd               sbrec_port_binding_set_options
  1         0.3497  ovn-northd               jsonrpc_session_run
  1         0.3497  ovn-northd               _init
  1         0.3497  ovn-northd
nbrec_logical_port_set_addresses
  1         0.3497  ovn-northd
nbrec_logical_router_port_get_mac
  1         0.3497  ovn-northd
sbrec_chassis_set_vtep_logical_switches
  1         0.3497  ovn-northd               describe_fd
  1         0.3497  ovn-northd               ovs_error
  1         0.3497  ovn-northd               vlog_valist
  1         0.3497  ovn-northd               make_unix_socket
  1         0.3497  ovn-northd               ofpbuf_use_const
  2         0.6993  ovn-northd               quicksort
  2         0.6993  ovn-northd               count_cpu_cores
  7         2.4476  ovn-northd               _fini
  263      91.9580  ovn-northd               ovs_scan__
137264   58.5425
libc-2.19.so             /lib/x86_64-linux-gnu/libc-2.19.so
  137264   100.000
libc-2.19.so             /lib/x86_64-linux-gnu/libc-2.19.so [self]
-------------------------------------------------------------------------------
  1        33.3333  ovn-northd               json_hash
  2        66.6667  ovn-northd               sbrec_chassis_set_external_ids
17467     7.4496  ovn-northd               main
  17467    99.9828  ovn-northd               main [self]
  2         0.0114  kallsyms                 apic_timer_interrupt
  1         0.0057  kallsyms                 reschedule_interrupt
-------------------------------------------------------------------------------
13190     5.6255  ovn-northd               hexit_value
  13190    99.9924  ovn-northd               hexit_value [self]
  1         0.0076  kallsyms                 apic_timer_interrupt
-------------------------------------------------------------------------------
10227     4.3618  ovn-northd               hash_bytes
  10227    99.9804  ovn-northd               hash_bytes [self]
  2         0.0196  kallsyms                 apic_timer_interrupt
-------------------------------------------------------------------------------
9458      4.0338  ovn-northd               scan_int

===============================================================

The callgraph seems not aligh with the ovn-northd implementation. Did I
miss anything
when compiling openvswitch source code (I used default ./configure; make to
generate
the ovn-northd execuable)? Thanks.

- Hui

> From: Daniele Di Proietto <diproiettod@ovn.org>
> To: Nirapada Ghosh/San Jose/IBM@IBMUS
> Cc: "dev@openvswitch.org" <dev@openvswitch.org>
> Date: 06/14/2016 09:58 PM
> Subject: Re: [ovs-dev] [PATCH V5] Function tracer to trace all function
calls
> Sent by: "dev" <dev-bounces@openvswitch.org>
>
> Hi Nirapada,
>
> When optimizing for the DPDK datapath we have a very similar problem and,
> usually, running a simple profiler like perf (
> https://perf.wiki.kernel.org/index.php/Main_Page) is enough to highlight
> the bottlenecks in terms of CPU usage.
>
> Have you tried perf? Does this infrastructure provide advantages over
> sample profiling? I'm not saying that one is better than the other, I'm
> just curious!
>
> Thanks,
>
> Daniele
>
> 2016-06-14 18:05 GMT-07:00 <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 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 <nghosh@us.ibm.com>
> >
> > ---
> >  configure.ac                      |  10 +++
> >  include/openvswitch/vlog.h        |   1 +
> >  lib/vlog.c                        |  23 ++++++-
> >  ovn/controller/automake.mk        |   9 +++
> >  ovn/controller/ovn-controller.c   |   9 +++
> >  ovn/northd/automake.mk            |   9 +++
> >  ovn/northd/ovn-northd.c           |   9 +++
> >  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           |   8 +++
> >  12 files changed, 292 insertions(+), 1 deletion(-)
> >  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..65fa073 100644
> > --- a/lib/vlog.c
> > +++ b/lib/vlog.c
> > @@ -1137,7 +1137,6 @@ vlog_valist(const struct vlog_module *module,
enum
> > vlog_level level,
> >          errno = save_errno;
> >      }
> >  }
> > -
> >  void
> >  vlog(const struct vlog_module *module, enum vlog_level level,
> >       const char *message, ...)
> > @@ -1262,6 +1261,28 @@ vlog_should_drop(const struct vlog_module
*module,
> > enum vlog_level level,
> >      return false;
> >  }
> >
> > +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_rate_limit(const struct vlog_module *module, enum vlog_level
level,
> >                  struct vlog_rate_limit *rl, 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..4f71b15 100644
> > --- a/ovn/controller/ovn-controller.c
> > +++ b/ovn/controller/ovn-controller.c
> > @@ -61,11 +61,19 @@ static unixctl_cb_func ct_zone_list;
> >
> >  #define DEFAULT_BRIDGE_NAME "br-int"
> >
> > +static bool g_command_line_args_parsed = false;
> >  static void parse_options(int argc, char *argv[]);
> > +
> >  OVS_NO_RETURN static void usage(void);
> >
> >  static char *ovs_remote;
> >
> > +bool
> > +is_command_line_args_parsed(void)
> > +{
> > +    return g_command_line_args_parsed;
> > +}
> > +
> >  struct local_datapath *
> >  get_local_datapath(const struct hmap *local_datapaths, uint32_t
> > tunnel_key)
> >  {
> > @@ -614,6 +622,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..6ffef96 100644
> > --- a/ovn/northd/ovn-northd.c
> > +++ b/ovn/northd/ovn-northd.c
> > @@ -42,6 +42,8 @@
> >
> >  VLOG_DEFINE_THIS_MODULE(ovn_northd);
> >
> > +static bool g_command_line_args_parsed = false;
> > +
> >  static unixctl_cb_func ovn_northd_exit;
> >
> >  struct northd_context {
> > @@ -119,6 +121,12 @@ enum ovn_stage {
> >  #undef PIPELINE_STAGE
> >  };
> >
> > +bool
> > +is_command_line_args_parsed(void)
> > +{
> > +    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 +2498,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..422fccd
> > --- /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();
> > +
> > +/* 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(&lt->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(&ltime, NULL) != 0) {
> > +        return;
> > +    }
> > +    if (format_time(&ltime, 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)
> > +    (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
> > +    """
> > +    date_obj1 = datetime.strptime(time1, '%Y-%m-%dT%H:%M:%S.%f')
> > +    date_obj2 = datetime.strptime(time2, '%Y-%m-%dT%H:%M:%S.%f')
> > +    delta = date_obj2 - date_obj1
> > +    return delta
> > +
> > +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 "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,exe)
> > +            update_and_print(tokens[0], tokens[1], tokens[2],
> > +                             tokens[3], serial, exe)
> > +
> > +if __name__ == "__main__":
> > +    main()
> > diff --git a/utilities/automake.mk b/utilities/automake.mk
> > index 1cc66b6..747cb36 100644
> > --- a/utilities/automake.mk
> > +++ b/utilities/automake.mk
> > @@ -57,6 +57,7 @@ EXTRA_DIST += \
> >         utilities/ovs-vlan-test.in \
> >         utilities/ovs-vsctl-bashcomp.bash \
> >         utilities/qemu-wrap.py \
> > +       third-party/generate_ft_report.py \
> >         utilities/checkpatch.py
> >  MAN_ROOTS += \
> >         utilities/ovs-appctl.8.in \
> > diff --git a/vswitchd/automake.mk b/vswitchd/automake.mk
> > index 8d7f3ea..bc4cd54 100644
> > --- a/vswitchd/automake.mk
> > +++ b/vswitchd/automake.mk
> > @@ -1,3 +1,8 @@
> > +if ENABLE_FT
> > +CFLAGS += -g -finstrument-functions  \
> > +         `pkg-config --cflags glib-2.0` \
> > +         `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt
> > +endif
> >  sbin_PROGRAMS += vswitchd/ovs-vswitchd
> >  man_MANS += vswitchd/ovs-vswitchd.8
> >  DISTCLEANFILES += \
> > @@ -11,6 +16,9 @@ vswitchd_ovs_vswitchd_SOURCES = \
> >         vswitchd/system-stats.h \
> >         vswitchd/xenserver.c \
> >         vswitchd/xenserver.h
> > +if ENABLE_FT
> > +vswitchd_ovs_vswitchd_SOURCES += third-party/function_tracer.c
> > +endif
> >  vswitchd_ovs_vswitchd_LDADD = \
> >         ofproto/libofproto.la \
> >         lib/libsflow.la \
> > diff --git a/vswitchd/ovs-vswitchd.c b/vswitchd/ovs-vswitchd.c
> > index 72448bb..ba985fd 100644
> > --- a/vswitchd/ovs-vswitchd.c
> > +++ b/vswitchd/ovs-vswitchd.c
> > @@ -51,6 +51,7 @@
> >
> >  VLOG_DEFINE_THIS_MODULE(vswitchd);
> >
> > +static bool g_command_line_args_parsed = false;
> >  /* --mlockall: If set, locks all process memory into physical RAM,
> > preventing
> >   * the kernel from paging any of its memory to disk. */
> >  static bool want_mlockall;
> > @@ -60,6 +61,12 @@ static unixctl_cb_func ovs_vswitchd_exit;
> >  static char *parse_options(int argc, char *argv[], char
**unixctl_path);
> >  OVS_NO_RETURN static void usage(void);
> >
> > +bool
> > +is_command_line_args_parsed(void)
> > +{
> > +    return g_command_line_args_parsed;
> > +}
> > +
> >  int
> >  main(int argc, char *argv[])
> >  {
> > @@ -240,6 +247,7 @@ parse_options(int argc, char *argv[], char
> > **unixctl_pathp)
> >          VLOG_FATAL("at most one non-option argument accepted; "
> >                     "use --help for usage");
> >      }
> > +    g_command_line_args_parsed = true;
> >  }
> >
> >  static void
> > --
> > 1.9.1
> >
> > _______________________________________________
> > dev mailing list
> > dev@openvswitch.org
> > http://openvswitch.org/mailman/listinfo/dev
> >
> _______________________________________________
> dev mailing list
> dev@openvswitch.org
> http://openvswitch.org/mailman/listinfo/dev
Ryan Moats June 15, 2016, 1:37 p.m. UTC | #3 
"dev" <dev-bounces@openvswitch.org> wrote on 06/14/2016 08:58:33 PM:

> From: Daniele Di Proietto <diproiettod@ovn.org>
> To: Nirapada Ghosh/San Jose/IBM@IBMUS
> Cc: "dev@openvswitch.org" <dev@openvswitch.org>
> Date: 06/14/2016 08:59 PM
> Subject: Re: [ovs-dev] [PATCH V5] Function tracer to trace all function
calls
> Sent by: "dev" <dev-bounces@openvswitch.org>
>
> Hi Nirapada,
>
> When optimizing for the DPDK datapath we have a very similar problem and,
> usually, running a simple profiler like perf (
> https://perf.wiki.kernel.org/index.php/Main_Page) is enough to highlight
> the bottlenecks in terms of CPU usage.
>
> Have you tried perf? Does this infrastructure provide advantages over
> sample profiling? I'm not saying that one is better than the other, I'm
> just curious!
>
> Thanks,
>
> Daniele

Daniele-

Nirapada's patch set is driven by the requirement to extract automated
profiling under scale while using the same bytes that are to be
deployed for operation.

This pretty much precludes the use of any external profiler.

Ryan
Daniele Di Proietto June 15, 2016, 6:06 p.m. UTC | #4 
Hi Hui,

I've never used oprofile, from what I read it's pretty similar to perf.

To compile OVS for profiling or debugging I use the ovs-dev.py script,
which adds "-fno-omit-frame-pointer" to CFLAGS.  It would be equivalent to
calling configure like this:

./configure CFLAGS="-O2 -g -fno-omit-frame-pointer"

Then I launch perf for 5 seconds on the nortd process like this:

perf record -p `pidof ovn-northd` sleep 5

This generates the perf.data file which can be inspected with `perf report
-i perf.data` to generate an output like the following:

  24.24%  ovn-northd  libc-2.19.so        [.] vfprintf
   9.83%  ovn-northd  libc-2.19.so        [.] _IO_default_xsputn
   5.62%  ovn-northd  ovn-northd          [.] hash_bytes
   4.92%  ovn-northd  ovn-northd          [.] ovsdb_idl_next_row
   4.84%  ovn-northd  libc-2.19.so        [.] __strcmp_sse2_unaligned
   4.40%  ovn-northd  ovn-northd          [.] build_lflows
   3.90%  ovn-northd  libc-2.19.so        [.] _int_malloc
   3.50%  ovn-northd  libc-2.19.so        [.] __strchrnul
   3.46%  ovn-northd  libc-2.19.so        [.] strlen
   2.93%  ovn-northd  ovn-northd          [.] ovs_scan__
   2.15%  ovn-northd  ovn-northd          [.] ovsdb_datum_compare_3way
   2.12%  ovn-northd  libc-2.19.so        [.] _IO_strn_overflow
   2.12%  ovn-northd  libc-2.19.so        [.] malloc_consolidate
   2.02%  ovn-northd  ovn-northd          [.] scan_int
   1.86%  ovn-northd  libc-2.19.so        [.] _IO_padn
   1.40%  ovn-northd  ovn-northd          [.] main
   1.24%  ovn-northd  ovn-northd          [.] hexits_value
   1.16%  ovn-northd  libc-2.19.so        [.] _int_free
   0.87%  ovn-northd  libc-2.19.so        [.] malloc
   0.86%  ovn-northd  ovn-northd          [.] ovn_lflow_add
   0.86%  ovn-northd  libc-2.19.so        [.] read_int
   0.85%  ovn-northd  libc-2.19.so        [.] _itoa_word
   0.79%  ovn-northd  ovn-northd          [.] resize
   0.75%  ovn-northd  libc-2.19.so        [.] _IO_vsnprintf
   0.73%  ovn-northd  ovn-northd          [.] ds_put_format_valist
   0.72%  ovn-northd  ovn-northd          [.] json_serialize_string
   0.71%  ovn-northd  libc-2.19.so        [.] _IO_str_init_static_internal
   0.68%  ovn-northd  libc-2.19.so        [.] _IO_old_init
   0.65%  ovn-northd  ovn-northd          [.] build_port_security_l2
   0.52%  ovn-northd  libc-2.19.so        [.] free
   0.50%  ovn-northd  ovn-northd          [.] xstrdup

By adding the -g option while recording, perf tries to reassemble the
current stack trace and group function accordingly

perf record -g -p `pidof ovn-northd` sleep 5

+   40.50%     0.00%  ovn-northd  libc-2.19.so        [.] __libc_start_main
+   40.07%     1.39%  ovn-northd  ovn-northd          [.] main
+   36.63%     0.86%  ovn-northd  libc-2.19.so        [.] _IO_vsnprintf
+   26.95%    26.94%  ovn-northd  libc-2.19.so        [.] vfprintf
+   26.61%     4.26%  ovn-northd  ovn-northd          [.] build_lflows
+   12.46%    12.44%  ovn-northd  libc-2.19.so        [.] _IO_default_xsputn
+   11.34%     0.00%  ovn-northd  [unknown]           [.] 0x702d30777322203d
+    6.88%     0.00%  ovn-northd  [unknown]           [.] 0x262620646e202626
+    5.12%     5.10%  ovn-northd  ovn-northd          [.] hash_bytes
+    4.24%     0.00%  ovn-northd  [unknown]           [.] 0x002b26db3bd7b800
+    4.15%     0.66%  ovn-northd  ovn-northd          [.] ovn_lflow_add
+    3.80%     3.74%  ovn-northd  libc-2.19.so        [.] _int_malloc
+    3.76%     3.74%  ovn-northd  libc-2.19.so        [.] strlen
+    3.55%     0.26%  ovn-northd  ovn-northd          [.]
ovn_port_update_sbrec
+    3.34%     0.11%  ovn-northd  ovn-northd          [.]
ovn_datapath_from_sbrec
+    3.27%     3.25%  ovn-northd  libc-2.19.so        [.] __strchrnul
+    3.23%     3.23%  ovn-northd  ovn-northd          [.] ovsdb_idl_next_row
+    3.21%     0.11%  ovn-northd  ovn-northd          [.] smap_get_uuid
+    3.13%     0.19%  ovn-northd  ovn-northd          [.]
extract_lport_addresses
+    3.10%     3.07%  ovn-northd  libc-2.19.so        [.]
__strcmp_sse2_unaligned
+    3.00%     0.00%  ovn-northd  [unknown]           [.] 0x30303a3030203d3d
+    2.93%     0.03%  ovn-northd  ovn-northd          [.] ovs_scan_len
+    2.77%     2.77%  ovn-northd  ovn-northd          [.] ovs_scan__
+    2.44%     2.42%  ovn-northd  libc-2.19.so        [.] _IO_strn_overflow
+    2.41%     0.31%  ovn-northd  ovn-northd          [.]
ovsdb_idl_txn_write__
+    2.38%     0.35%  ovn-northd  ovn-northd          [.]
build_port_security_l2
+    2.33%     2.33%  ovn-northd  ovn-northd          [.] scan_int
+    2.27%     0.00%  ovn-northd  ovn-northd          [.]
eth_addr_from_string
+    2.25%     0.08%  ovn-northd  ovn-northd          [.] ovs_scan
+    2.05%     0.04%  ovn-northd  ovn-northd          [.] ovsdb_datum_equals
+    1.95%     1.95%  ovn-northd  libc-2.19.so        [.] malloc_consolidate
+    1.95%     0.02%  ovn-northd  ovn-northd          [.]
build_port_security_ip
+    1.80%     1.80%  ovn-northd  libc-2.19.so        [.] _IO_padn
+    1.73%     0.10%  ovn-northd  ovn-northd          [.] ds_put_format
+    1.69%     1.69%  ovn-northd  libc-2.19.so        [.] _int_free
+    1.67%     0.12%  ovn-northd  ovn-northd          [.] uuid_from_string
+    1.56%     1.56%  ovn-northd  ovn-northd          [.]
ovsdb_datum_compare_3way
+    1.51%     0.00%  ovn-northd  [unknown]           [.] 0x2b26db3bd7b80000
+    1.42%     1.06%  ovn-northd  ovn-northd          [.]
ds_put_format_valist
+    1.39%     0.00%  ovn-northd  [unknown]           [.] 0x3030303030303030
+    1.39%     1.39%  ovn-northd  ovn-northd          [.] hexits_value
+    1.39%     0.21%  ovn-northd  ovn-northd          [.]
sbrec_port_binding_set_mac
+    1.35%     1.35%  ovn-northd  libc-2.19.so        [.] malloc
+    1.33%     0.00%  ovn-northd  [unknown]           [.] 0000000000000000
+    1.29%     0.06%  ovn-northd  ovn-northd          [.] ovn_port_create

You can expand each "+" to understand who calls the function.  It's not
100% reliable (it's a sampling profiler after all).

It's also possible to "annotate" each function to show where the samples
are taken with an assembly instruction level granularity.

I guess this process works to optimize high CPU usage if your functions are
executed over and over in a loop (for example, in OVS-DPDK, we call
miniflow_extract for each packet).

That said, I don't know how much of this is applicable to ovn-northd, where
the input varies highly.
In this example I run in parallel a for loop with ovn-nbctl invocation that
constantly change the database, but that's probably a totally unrealistic
use case. I have no idea if it's worth doing this kind of
micro-optimization for a distributed system like OVN. Some might be worth,
like commit 76adea871d0d("lib/util.c: Optimise bitwise_rscan.")

Again, I just wanted to share my experience about profiling the datapath.
This looks like a different problem and it probably requires other tools.

Thanks,

Daniele


2016-06-14 22:02 GMT-07:00 Hui Kang <kangh@us.ibm.com>:

> Hi, Daniele,
> I am also interesting in profiling the ovs process and would like to
> participate in the discussion.
>
>
> I am using oprofile-1.1.0 to profiling the ovn-northd process. I believe
> oprofile-1.1.0 share the same underlying profiling mechanism as Linux perf
> (correct me if I am wrong). However, it is hard for me to understand the
> output of the profiled data. For example, in a highly overloaded ovn-northd
> process, the output of opreport --callgraph is
>
> ===============================================================
> CPU: Intel Sandy Bridge microarchitecture, speed 3300 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit
> mask of 0x00 (No unit mask) count 90000
> samples % image name symbol name
>
> -------------------------------------------------------------------------------
> 1 0.3497 ovn-northd build_lswitch_flows.constprop.16
> 1 0.3497 ovn-northd sbrec_port_binding_set_options
> 1 0.3497 ovn-northd jsonrpc_session_run
> 1 0.3497 ovn-northd _init
> 1 0.3497 ovn-northd nbrec_logical_port_set_addresses
> 1 0.3497 ovn-northd nbrec_logical_router_port_get_mac
> 1 0.3497 ovn-northd sbrec_chassis_set_vtep_logical_switches
> 1 0.3497 ovn-northd describe_fd
> 1 0.3497 ovn-northd ovs_error
> 1 0.3497 ovn-northd vlog_valist
> 1 0.3497 ovn-northd make_unix_socket
> 1 0.3497 ovn-northd ofpbuf_use_const
> 2 0.6993 ovn-northd quicksort
> 2 0.6993 ovn-northd count_cpu_cores
> 7 2.4476 ovn-northd _fini
> 263 91.9580 ovn-northd ovs_scan__
> 137264 58.5425 libc-2.19.so /lib/x86_64-linux-gnu/libc-2.19.so
> 137264 100.000 libc-2.19.so /lib/x86_64-linux-gnu/libc-2.19.so [self]
>
> -------------------------------------------------------------------------------
> 1 33.3333 ovn-northd json_hash
> 2 66.6667 ovn-northd sbrec_chassis_set_external_ids
> 17467 7.4496 ovn-northd main
> 17467 99.9828 ovn-northd main [self]
> 2 0.0114 kallsyms apic_timer_interrupt
> 1 0.0057 kallsyms reschedule_interrupt
>
> -------------------------------------------------------------------------------
> 13190 5.6255 ovn-northd hexit_value
> 13190 99.9924 ovn-northd hexit_value [self]
> 1 0.0076 kallsyms apic_timer_interrupt
>
> -------------------------------------------------------------------------------
> 10227 4.3618 ovn-northd hash_bytes
> 10227 99.9804 ovn-northd hash_bytes [self]
> 2 0.0196 kallsyms apic_timer_interrupt
>
> -------------------------------------------------------------------------------
> 9458 4.0338 ovn-northd scan_int
>
> ===============================================================
>
> The callgraph seems not aligh with the ovn-northd implementation. Did I
> miss anything
> when compiling openvswitch source code (I used default ./configure; make
> to generate
> the ovn-northd execuable)? Thanks.
>
> - Hui
>
> > From: Daniele Di Proietto <diproiettod@ovn.org>
> > To: Nirapada Ghosh/San Jose/IBM@IBMUS
> > Cc: "dev@openvswitch.org" <dev@openvswitch.org>
> > Date: 06/14/2016 09:58 PM
> > Subject: Re: [ovs-dev] [PATCH V5] Function tracer to trace all function
> calls
> > Sent by: "dev" <dev-bounces@openvswitch.org>
>
> >
> > Hi Nirapada,
> >
> > When optimizing for the DPDK datapath we have a very similar problem and,
> > usually, running a simple profiler like perf (
> > https://perf.wiki.kernel.org/index.php/Main_Page) is enough to highlight
> > the bottlenecks in terms of CPU usage.
> >
> > Have you tried perf? Does this infrastructure provide advantages over
> > sample profiling? I'm not saying that one is better than the other, I'm
> > just curious!
> >
> > Thanks,
> >
> > Daniele
> >
> > 2016-06-14 18:05 GMT-07:00 <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 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 <nghosh@us.ibm.com>
> > >
> > > ---
> > >  configure.ac                      |  10 +++
> > >  include/openvswitch/vlog.h        |   1 +
> > >  lib/vlog.c                        |  23 ++++++-
> > >  ovn/controller/automake.mk        |   9 +++
> > >  ovn/controller/ovn-controller.c   |   9 +++
> > >  ovn/northd/automake.mk            |   9 +++
> > >  ovn/northd/ovn-northd.c           |   9 +++
> > >  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           |   8 +++
> > >  12 files changed, 292 insertions(+), 1 deletion(-)
> > >  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..65fa073 100644
> > > --- a/lib/vlog.c
> > > +++ b/lib/vlog.c
> > > @@ -1137,7 +1137,6 @@ vlog_valist(const struct vlog_module *module,
> enum
> > > vlog_level level,
> > >          errno = save_errno;
> > >      }
> > >  }
> > > -
> > >  void
> > >  vlog(const struct vlog_module *module, enum vlog_level level,
> > >       const char *message, ...)
> > > @@ -1262,6 +1261,28 @@ vlog_should_drop(const struct vlog_module
> *module,
> > > enum vlog_level level,
> > >      return false;
> > >  }
> > >
> > > +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_rate_limit(const struct vlog_module *module, enum vlog_level
> level,
> > >                  struct vlog_rate_limit *rl, 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..4f71b15 100644
> > > --- a/ovn/controller/ovn-controller.c
> > > +++ b/ovn/controller/ovn-controller.c
> > > @@ -61,11 +61,19 @@ static unixctl_cb_func ct_zone_list;
> > >
> > >  #define DEFAULT_BRIDGE_NAME "br-int"
> > >
> > > +static bool g_command_line_args_parsed = false;
> > >  static void parse_options(int argc, char *argv[]);
> > > +
> > >  OVS_NO_RETURN static void usage(void);
> > >
> > >  static char *ovs_remote;
> > >
> > > +bool
> > > +is_command_line_args_parsed(void)
> > > +{
> > > +    return g_command_line_args_parsed;
> > > +}
> > > +
> > >  struct local_datapath *
> > >  get_local_datapath(const struct hmap *local_datapaths, uint32_t
> > > tunnel_key)
> > >  {
> > > @@ -614,6 +622,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..6ffef96 100644
> > > --- a/ovn/northd/ovn-northd.c
> > > +++ b/ovn/northd/ovn-northd.c
> > > @@ -42,6 +42,8 @@
> > >
> > >  VLOG_DEFINE_THIS_MODULE(ovn_northd);
> > >
> > > +static bool g_command_line_args_parsed = false;
> > > +
> > >  static unixctl_cb_func ovn_northd_exit;
> > >
> > >  struct northd_context {
> > > @@ -119,6 +121,12 @@ enum ovn_stage {
> > >  #undef PIPELINE_STAGE
> > >  };
> > >
> > > +bool
> > > +is_command_line_args_parsed(void)
> > > +{
> > > +    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 +2498,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..422fccd
> > > --- /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();
> > > +
> > > +/* 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(&lt->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(&ltime, NULL) != 0) {
> > > +        return;
> > > +    }
> > > +    if (format_time(&ltime, 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)
> > > +    (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
> > > +    """
> > > +    date_obj1 = datetime.strptime(time1, '%Y-%m-%dT%H:%M:%S.%f')
> > > +    date_obj2 = datetime.strptime(time2, '%Y-%m-%dT%H:%M:%S.%f')
> > > +    delta = date_obj2 - date_obj1
> > > +    return delta
> > > +
> > > +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 "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,exe)
> > > +            update_and_print(tokens[0], tokens[1], tokens[2],
> > > +                             tokens[3], serial, exe)
> > > +
> > > +if __name__ == "__main__":
> > > +    main()
> > > diff --git a/utilities/automake.mk b/utilities/automake.mk
> > > index 1cc66b6..747cb36 100644
> > > --- a/utilities/automake.mk
> > > +++ b/utilities/automake.mk
> > > @@ -57,6 +57,7 @@ EXTRA_DIST += \
> > >         utilities/ovs-vlan-test.in \
> > >         utilities/ovs-vsctl-bashcomp.bash \
> > >         utilities/qemu-wrap.py \
> > > +       third-party/generate_ft_report.py \
> > >         utilities/checkpatch.py
> > >  MAN_ROOTS += \
> > >         utilities/ovs-appctl.8.in \
> > > diff --git a/vswitchd/automake.mk b/vswitchd/automake.mk
> > > index 8d7f3ea..bc4cd54 100644
> > > --- a/vswitchd/automake.mk
> > > +++ b/vswitchd/automake.mk
> > > @@ -1,3 +1,8 @@
> > > +if ENABLE_FT
> > > +CFLAGS += -g -finstrument-functions  \
> > > +         `pkg-config --cflags glib-2.0` \
> > > +         `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt
> > > +endif
> > >  sbin_PROGRAMS += vswitchd/ovs-vswitchd
> > >  man_MANS += vswitchd/ovs-vswitchd.8
> > >  DISTCLEANFILES += \
> > > @@ -11,6 +16,9 @@ vswitchd_ovs_vswitchd_SOURCES = \
> > >         vswitchd/system-stats.h \
> > >         vswitchd/xenserver.c \
> > >         vswitchd/xenserver.h
> > > +if ENABLE_FT
> > > +vswitchd_ovs_vswitchd_SOURCES += third-party/function_tracer.c
> > > +endif
> > >  vswitchd_ovs_vswitchd_LDADD = \
> > >         ofproto/libofproto.la \
> > >         lib/libsflow.la \
> > > diff --git a/vswitchd/ovs-vswitchd.c b/vswitchd/ovs-vswitchd.c
> > > index 72448bb..ba985fd 100644
> > > --- a/vswitchd/ovs-vswitchd.c
> > > +++ b/vswitchd/ovs-vswitchd.c
> > > @@ -51,6 +51,7 @@
> > >
> > >  VLOG_DEFINE_THIS_MODULE(vswitchd);
> > >
> > > +static bool g_command_line_args_parsed = false;
> > >  /* --mlockall: If set, locks all process memory into physical RAM,
> > > preventing
> > >   * the kernel from paging any of its memory to disk. */
> > >  static bool want_mlockall;
> > > @@ -60,6 +61,12 @@ static unixctl_cb_func ovs_vswitchd_exit;
> > >  static char *parse_options(int argc, char *argv[], char
> **unixctl_path);
> > >  OVS_NO_RETURN static void usage(void);
> > >
> > > +bool
> > > +is_command_line_args_parsed(void)
> > > +{
> > > +    return g_command_line_args_parsed;
> > > +}
> > > +
> > >  int
> > >  main(int argc, char *argv[])
> > >  {
> > > @@ -240,6 +247,7 @@ parse_options(int argc, char *argv[], char
> > > **unixctl_pathp)
> > >          VLOG_FATAL("at most one non-option argument accepted; "
> > >                     "use --help for usage");
> > >      }
> > > +    g_command_line_args_parsed = true;
> > >  }
> > >
> > >  static void
> > > --
> > > 1.9.1
> > >
> > > _______________________________________________
> > > dev mailing list
> > > dev@openvswitch.org
> > > http://openvswitch.org/mailman/listinfo/dev
> > >
> > _______________________________________________
> > dev mailing list
> > dev@openvswitch.org
> > http://openvswitch.org/mailman/listinfo/dev
>
>
Daniele Di Proietto June 15, 2016, 6:20 p.m. UTC | #5 
2016-06-15 6:37 GMT-07:00 Ryan Moats <rmoats@us.ibm.com>:

> "dev" <dev-bounces@openvswitch.org> wrote on 06/14/2016 08:58:33 PM:
>
> > From: Daniele Di Proietto <diproiettod@ovn.org>
> > To: Nirapada Ghosh/San Jose/IBM@IBMUS
> > Cc: "dev@openvswitch.org" <dev@openvswitch.org>
> > Date: 06/14/2016 08:59 PM
> > Subject: Re: [ovs-dev] [PATCH V5] Function tracer to trace all function
> calls
> > Sent by: "dev" <dev-bounces@openvswitch.org>
> >
> > Hi Nirapada,
> >
> > When optimizing for the DPDK datapath we have a very similar problem and,
> > usually, running a simple profiler like perf (
> > https://perf.wiki.kernel.org/index.php/Main_Page) is enough to highlight
> > the bottlenecks in terms of CPU usage.
> >
> > Have you tried perf? Does this infrastructure provide advantages over
> > sample profiling? I'm not saying that one is better than the other, I'm
> > just curious!
> >
> > Thanks,
> >
> > Daniele
>
> Daniele-
>
> Nirapada's patch set is driven by the requirement to extract automated
> profiling under scale while using the same bytes that are to be
> deployed for operation.
>
> This pretty much precludes the use of any external profiler.
>
> Ryan
>
Ok, I understand, no objections here.

Thanks,

Daniele
diff mbox

Patch

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..65fa073 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -1137,7 +1137,6 @@  vlog_valist(const struct vlog_module *module, enum vlog_level level,
         errno = save_errno;
     }
 }
-
 void
 vlog(const struct vlog_module *module, enum vlog_level level,
      const char *message, ...)
@@ -1262,6 +1261,28 @@  vlog_should_drop(const struct vlog_module *module, enum vlog_level level,
     return false;
 }
 
+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_rate_limit(const struct vlog_module *module, enum vlog_level level,
                 struct vlog_rate_limit *rl, 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..4f71b15 100644
--- a/ovn/controller/ovn-controller.c
+++ b/ovn/controller/ovn-controller.c
@@ -61,11 +61,19 @@  static unixctl_cb_func ct_zone_list;
 
 #define DEFAULT_BRIDGE_NAME "br-int"
 
+static bool g_command_line_args_parsed = false;
 static void parse_options(int argc, char *argv[]);
+
 OVS_NO_RETURN static void usage(void);
 
 static char *ovs_remote;
 
+bool
+is_command_line_args_parsed(void)
+{
+    return g_command_line_args_parsed;
+}
+
 struct local_datapath *
 get_local_datapath(const struct hmap *local_datapaths, uint32_t tunnel_key)
 {
@@ -614,6 +622,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..6ffef96 100644
--- a/ovn/northd/ovn-northd.c
+++ b/ovn/northd/ovn-northd.c
@@ -42,6 +42,8 @@ 
 
 VLOG_DEFINE_THIS_MODULE(ovn_northd);
 
+static bool g_command_line_args_parsed = false;
+
 static unixctl_cb_func ovn_northd_exit;
 
 struct northd_context {
@@ -119,6 +121,12 @@  enum ovn_stage {
 #undef PIPELINE_STAGE
 };
 
+bool
+is_command_line_args_parsed(void)
+{
+    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 +2498,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..422fccd
--- /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();
+
+/* 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(&lt->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(&ltime, NULL) != 0) {
+        return;
+    }
+    if (format_time(&ltime, 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)
+    (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
+    """
+    date_obj1 = datetime.strptime(time1, '%Y-%m-%dT%H:%M:%S.%f')
+    date_obj2 = datetime.strptime(time2, '%Y-%m-%dT%H:%M:%S.%f')
+    delta = date_obj2 - date_obj1
+    return delta
+
+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 "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,exe)
+            update_and_print(tokens[0], tokens[1], tokens[2],
+                             tokens[3], serial, exe)
+
+if __name__ == "__main__":
+    main()
diff --git a/utilities/automake.mk b/utilities/automake.mk
index 1cc66b6..747cb36 100644
--- a/utilities/automake.mk
+++ b/utilities/automake.mk
@@ -57,6 +57,7 @@  EXTRA_DIST += \
 	utilities/ovs-vlan-test.in \
 	utilities/ovs-vsctl-bashcomp.bash \
 	utilities/qemu-wrap.py \
+	third-party/generate_ft_report.py \
 	utilities/checkpatch.py
 MAN_ROOTS += \
 	utilities/ovs-appctl.8.in \
diff --git a/vswitchd/automake.mk b/vswitchd/automake.mk
index 8d7f3ea..bc4cd54 100644
--- a/vswitchd/automake.mk
+++ b/vswitchd/automake.mk
@@ -1,3 +1,8 @@ 
+if ENABLE_FT
+CFLAGS += -g -finstrument-functions  \
+         `pkg-config --cflags glib-2.0` \
+         `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt
+endif
 sbin_PROGRAMS += vswitchd/ovs-vswitchd
 man_MANS += vswitchd/ovs-vswitchd.8
 DISTCLEANFILES += \
@@ -11,6 +16,9 @@  vswitchd_ovs_vswitchd_SOURCES = \
 	vswitchd/system-stats.h \
 	vswitchd/xenserver.c \
 	vswitchd/xenserver.h
+if ENABLE_FT
+vswitchd_ovs_vswitchd_SOURCES += third-party/function_tracer.c
+endif
 vswitchd_ovs_vswitchd_LDADD = \
 	ofproto/libofproto.la \
 	lib/libsflow.la \
diff --git a/vswitchd/ovs-vswitchd.c b/vswitchd/ovs-vswitchd.c
index 72448bb..ba985fd 100644
--- a/vswitchd/ovs-vswitchd.c
+++ b/vswitchd/ovs-vswitchd.c
@@ -51,6 +51,7 @@ 
 
 VLOG_DEFINE_THIS_MODULE(vswitchd);
 
+static bool g_command_line_args_parsed = false;
 /* --mlockall: If set, locks all process memory into physical RAM, preventing
  * the kernel from paging any of its memory to disk. */
 static bool want_mlockall;
@@ -60,6 +61,12 @@  static unixctl_cb_func ovs_vswitchd_exit;
 static char *parse_options(int argc, char *argv[], char **unixctl_path);
 OVS_NO_RETURN static void usage(void);
 
+bool
+is_command_line_args_parsed(void)
+{
+    return g_command_line_args_parsed;
+}
+
 int
 main(int argc, char *argv[])
 {
@@ -240,6 +247,7 @@  parse_options(int argc, char *argv[], char **unixctl_pathp)
         VLOG_FATAL("at most one non-option argument accepted; "
                    "use --help for usage");
     }
+    g_command_line_args_parsed = true;
 }
 
 static void