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

In some circumstances, we might need to figure out where in
code, the CPU time is being spent most, so as to pinpoint
the bottleneck and thereby resolve it with proper changes.
Using '-finstrument-functions' flag, that can be achieved, and
this patch exactly does that.

There is a python file [generate_ft_report.py] with the patch,
that may be used to convert this trace output to a human readable
format with symbol names instead of address and their execution
times.

To enable this feature, ovs needs needs to be configured with
"--enable-ft" command line argument [i.e. configure --enable-ft]

This instrumentation logs the tracing output in separate log files
namely func_trace_<pid>.log. It does not use VLOG mechanism for
logging as that will make the patch very complicated to avoid
recursion in the trace routine.

This feature starts dumping output, only in debug mode, which means
ovs-appctl -t <module> vlog/set any:any:dbg should be used to enable
this logging.

Currently, only ovn-northd, ovn-controller, vswitchd are instrumented.

It is intended to be used for debugging purposes.

Signed-off-by: Nirapada Ghosh <nghosh@us.ibm.com>

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

Hi Nirapada,

This patch doesn’t apply, please rebase on top of the master branch. The ovn-northd diff indicates deletion of gateway related code at the minimum.

Thanks
Amitabha

> On Jun 9, 2016, at 11:12 AM, nghosh@us.ibm.com wrote:
> 
> In some circumstances, we might need to figure out where in
> code, the CPU time is being spent most, so as to pinpoint
> the bottleneck and thereby resolve it with proper changes.
> Using '-finstrument-functions' flag, that can be achieved, and
> this patch exactly does that.
> 
> There is a python file [generate_ft_report.py] with the patch,
> that may be used to convert this trace output to a human readable
> format with symbol names instead of address and their execution
> times.
> 
> To enable this feature, ovs needs needs to be configured with
> "--enable-ft" command line argument [i.e. configure --enable-ft]
> 
> This instrumentation logs the tracing output in separate log files
> namely func_trace_<pid>.log. It does not use VLOG mechanism for
> logging as that will make the patch very complicated to avoid
> recursion in the trace routine.
> 
> This feature starts dumping output, only in debug mode, which means
> ovs-appctl -t <module> vlog/set any:any:dbg should be used to enable
> this logging.
> 
> Currently, only ovn-northd, ovn-controller, vswitchd are instrumented.
> 
> It is intended to be used for debugging purposes.
> 
> Signed-off-by: Nirapada Ghosh <nghosh@us.ibm.com>
> 
> ---
> configure.ac                      |  10 +++
> include/openvswitch/vlog.h        |   1 +
> lib/vlog.c                        |  22 ++++++
> ovn/controller/automake.mk        |   9 +++
> ovn/controller/ovn-controller.c   |   4 +
> ovn/northd/automake.mk            |   9 +++
> ovn/northd/ovn-northd.c           | 149 +++++---------------------------------
> 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           |  10 +--
> 12 files changed, 292 insertions(+), 137 deletions(-)
> 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..32ae844 100644
> --- a/lib/vlog.c
> +++ b/lib/vlog.c
> @@ -1138,6 +1138,28 @@ vlog_valist(const struct vlog_module *module, enum vlog_level level,
>     }
> }
> 
> +void __attribute__ ((no_instrument_function))
> +vlog_directory(char *dir,int len)
> +{
> +    int dir_len;
> +    if (log_file_name == NULL) {
> +        dir_len = strlen(ovs_logdir());
> +        if (dir_len > len) {
> +            *dir = '\0';
> +        }
> +        snprintf(dir,dir_len,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,log_file_name);
> +           }
> +        }
> +    }
> +}
> void
> vlog(const struct vlog_module *module, enum vlog_level level,
>      const char *message, ...)
> diff --git a/ovn/controller/automake.mk b/ovn/controller/automake.mk
> index cf57bbd..61efcf4 100644
> --- a/ovn/controller/automake.mk
> +++ b/ovn/controller/automake.mk
> @@ -1,3 +1,9 @@
> +if ENABLE_FT
> +CFLAGS += -g -finstrument-functions  \
> +         `pkg-config --cflags glib-2.0` \
> +         `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt
> +endif
> +
> bin_PROGRAMS += ovn/controller/ovn-controller
> ovn_controller_ovn_controller_SOURCES = \
> 	ovn/controller/binding.c \
> @@ -20,6 +26,9 @@ ovn_controller_ovn_controller_SOURCES = \
> 	ovn/controller/ovn-controller.h \
> 	ovn/controller/physical.c \
> 	ovn/controller/physical.h
> +if ENABLE_FT
> +ovn_controller_ovn_controller_SOURCES += third-party/function_tracer.c
> +endif
> ovn_controller_ovn_controller_LDADD = ovn/lib/libovn.la lib/libopenvswitch.la
> man_MANS += ovn/controller/ovn-controller.8
> EXTRA_DIST += ovn/controller/ovn-controller.8.xml
> diff --git a/ovn/controller/ovn-controller.c b/ovn/controller/ovn-controller.c
> index 356a94b..85d1863 100644
> --- a/ovn/controller/ovn-controller.c
> +++ b/ovn/controller/ovn-controller.c
> @@ -62,6 +62,9 @@ static unixctl_cb_func ct_zone_list;
> #define DEFAULT_BRIDGE_NAME "br-int"
> 
> static void parse_options(int argc, char *argv[]);
> +
> +/* we need this for function tracing module */
> +bool   g_command_line_args_parsed = false;
> OVS_NO_RETURN static void usage(void);
> 
> static char *ovs_remote;
> @@ -614,6 +617,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 cac0148..66c2020 100644
> --- a/ovn/northd/ovn-northd.c
> +++ b/ovn/northd/ovn-northd.c
> @@ -56,6 +56,9 @@ static const char *ovnsb_db;
> 
> static const char *default_nb_db(void);
> static const char *default_sb_db(void);
> +
> +/* we need this for function tracing module */
> +bool   g_command_line_args_parsed = false;
> 
> /* Pipeline stages. */
> 
> @@ -690,24 +693,11 @@ ovn_port_update_sbrec(const struct ovn_port *op)
> {
>     sbrec_port_binding_set_datapath(op->sb, op->od->sb);
>     if (op->nbr) {
> -        /* If the router is for l3 gateway, it resides on a chassis
> -         * and its port type is "gateway". */
> -        const char *chassis = smap_get(&op->od->nbr->options, "chassis");
> -        if (chassis) {
> -            sbrec_port_binding_set_type(op->sb, "gateway");
> -        } else {
> -            sbrec_port_binding_set_type(op->sb, "patch");
> -        }
> +        sbrec_port_binding_set_type(op->sb, "patch");
> 
>         const char *peer = op->peer ? op->peer->key : "<error>";
> -        struct smap new;
> -        smap_init(&new);
> -        smap_add(&new, "peer", peer);
> -        if (chassis) {
> -            smap_add(&new, "gateway-chassis", chassis);
> -        }
> -        sbrec_port_binding_set_options(op->sb, &new);
> -        smap_destroy(&new);
> +        const struct smap ids = SMAP_CONST1(&ids, "peer", peer);
> +        sbrec_port_binding_set_options(op->sb, &ids);
> 
>         sbrec_port_binding_set_parent_port(op->sb, NULL);
>         sbrec_port_binding_set_tag(op->sb, NULL, 0);
> @@ -717,32 +707,15 @@ ovn_port_update_sbrec(const struct ovn_port *op)
>             sbrec_port_binding_set_type(op->sb, op->nbs->type);
>             sbrec_port_binding_set_options(op->sb, &op->nbs->options);
>         } else {
> -            const char *chassis = NULL;
> -            if (op->peer && op->peer->od && op->peer->od->nbr) {
> -                chassis = smap_get(&op->peer->od->nbr->options, "chassis");
> -            }
> -
> -            /* A switch port connected to a gateway router is also of
> -             * type "gateway". */
> -            if (chassis) {
> -                sbrec_port_binding_set_type(op->sb, "gateway");
> -            } else {
> -                sbrec_port_binding_set_type(op->sb, "patch");
> -            }
> +            sbrec_port_binding_set_type(op->sb, "patch");
> 
>             const char *router_port = smap_get(&op->nbs->options,
>                                                "router-port");
>             if (!router_port) {
>                 router_port = "<error>";
>             }
> -            struct smap new;
> -            smap_init(&new);
> -            smap_add(&new, "peer", router_port);
> -            if (chassis) {
> -                smap_add(&new, "gateway-chassis", chassis);
> -            }
> -            sbrec_port_binding_set_options(op->sb, &new);
> -            smap_destroy(&new);
> +            const struct smap ids = SMAP_CONST1(&ids, "peer", router_port);
> +            sbrec_port_binding_set_options(op->sb, &ids);
>         }
>         sbrec_port_binding_set_parent_port(op->sb, op->nbs->parent_name);
>         sbrec_port_binding_set_tag(op->sb, op->nbs->tag, op->nbs->n_tag);
> @@ -1063,17 +1036,12 @@ build_port_security_ipv6_flow(
>     ipv6_string_mapped(ip6_str, &lla);
>     ds_put_format(match, "%s, ", ip6_str);
> 
> -    /* Allow ip6.dst=ff00::/8 for multicast packets */
> -    if (pipeline == P_OUT) {
> -        ds_put_cstr(match, "ff00::/8, ");
> -    }
> +    /* Allow ip6.src=:: and ip6.dst=ff00::/8 for ND packets */
> +    ds_put_cstr(match, pipeline == P_IN ? "::" : "ff00::/8");
>     for(int i = 0; i < n_ipv6_addrs; i++) {
>         ipv6_string_mapped(ip6_str, &ipv6_addrs[i].addr);
> -        ds_put_format(match, "%s, ", ip6_str);
> +        ds_put_format(match, ", %s", ip6_str);
>     }
> -    /* Replace ", " by "}". */
> -    ds_chomp(match, ' ');
> -    ds_chomp(match, ',');
>     ds_put_cstr(match, "}");
> }
> 
> @@ -1209,19 +1177,8 @@ build_port_security_ip(enum ovn_pipeline pipeline, struct ovn_port *op,
>         if (ps.n_ipv4_addrs) {
>             struct ds match = DS_EMPTY_INITIALIZER;
>             if (pipeline == P_IN) {
> -                /* Permit use of the unspecified address for DHCP discovery */
> -                struct ds dhcp_match = DS_EMPTY_INITIALIZER;
> -                ds_put_format(&dhcp_match, "inport == %s"
> -                              " && eth.src == "ETH_ADDR_FMT
> -                              " && ip4.src == 0.0.0.0"
> -                              " && ip4.dst == 255.255.255.255"
> -                              " && udp.src == 68 && udp.dst == 67", op->json_key,
> -                              ETH_ADDR_ARGS(ps.ea));
> -                ovn_lflow_add(lflows, op->od, stage, 90,
> -                              ds_cstr(&dhcp_match), "next;");
> -                ds_destroy(&dhcp_match);
>                 ds_put_format(&match, "inport == %s && eth.src == "ETH_ADDR_FMT
> -                              " && ip4.src == {", op->json_key,
> +                              " && ip4.src == {0.0.0.0, ", op->json_key,
>                               ETH_ADDR_ARGS(ps.ea));
>             } else {
>                 ds_put_format(&match, "outport == %s && eth.dst == "ETH_ADDR_FMT
> @@ -1265,20 +1222,6 @@ build_port_security_ip(enum ovn_pipeline pipeline, struct ovn_port *op,
> 
>         if (ps.n_ipv6_addrs) {
>             struct ds match = DS_EMPTY_INITIALIZER;
> -            if (pipeline == P_IN) {
> -                /* Permit use of unspecified address for duplicate address
> -                 * detection */
> -                struct ds dad_match = DS_EMPTY_INITIALIZER;
> -                ds_put_format(&dad_match, "inport == %s"
> -                              " && eth.src == "ETH_ADDR_FMT
> -                              " && ip6.src == ::"
> -                              " && ip6.dst == ff02::/16"
> -                              " && icmp6.type == {131, 135, 143}", op->json_key,
> -                              ETH_ADDR_ARGS(ps.ea));
> -                ovn_lflow_add(lflows, op->od, stage, 90,
> -                              ds_cstr(&dad_match), "next;");
> -                ds_destroy(&dad_match);
> -            }
>             ds_put_format(&match, "%s == %s && %s == "ETH_ADDR_FMT"",
>                           port_direction, op->json_key,
>                           pipeline == P_IN ? "eth.src" : "eth.dst",
> @@ -1952,14 +1895,11 @@ build_lrouter_flows(struct hmap *datapaths, struct hmap *ports,
>         free(match);
> 
>         /* ICMP echo reply.  These flows reply to ICMP echo requests
> -         * received for the router's IP address. Since packets only
> -         * get here as part of the logical router datapath, the inport
> -         * (i.e. the incoming locally attached net) does not matter.
> -         * The ip.ttl also does not matter (RFC1812 section 4.2.2.9) */
> +         * received for the router's IP address. */
>         match = xasprintf(
> -            "(ip4.dst == "IP_FMT" || ip4.dst == "IP_FMT") && "
> +            "inport == %s && (ip4.dst == "IP_FMT" || ip4.dst == "IP_FMT") && "
>             "icmp4.type == 8 && icmp4.code == 0",
> -            IP_ARGS(op->ip), IP_ARGS(op->bcast));
> +            op->json_key, IP_ARGS(op->ip), IP_ARGS(op->bcast));
>         char *actions = xasprintf(
>             "ip4.dst = ip4.src; "
>             "ip4.src = "IP_FMT"; "
> @@ -2071,13 +2011,7 @@ build_lrouter_flows(struct hmap *datapaths, struct hmap *ports,
>                 free(actions);
>                 free(match);
>             }
> -        } else if (op->od->n_router_ports && strcmp(op->nbs->type, "router")) {
> -            /* This is a logical switch port that backs a VM or a container.
> -             * Extract its addresses. For each of the address, go through all
> -             * the router ports attached to the switch (to which this port
> -             * connects) and if the address in question is reachable from the
> -             * router port, add an ARP entry in that router's pipeline. */
> -
> +        } else if (op->od->n_router_ports) {
>             for (size_t i = 0; i < op->nbs->n_addresses; i++) {
>                 struct lport_addresses laddrs;
>                 if (!extract_lport_addresses(op->nbs->addresses[i], &laddrs,
> @@ -2125,56 +2059,8 @@ build_lrouter_flows(struct hmap *datapaths, struct hmap *ports,
> 
>                 free(laddrs.ipv4_addrs);
>             }
> -        } else if (!strcmp(op->nbs->type, "router")) {
> -            /* This is a logical switch port that connects to a router. */
> -
> -            /* The peer of this switch port is the router port for which
> -             * we need to add logical flows such that it can resolve
> -             * ARP entries for all the other router ports connected to
> -             * the switch in question. */
> -
> -            const char *peer_name = smap_get(&op->nbs->options,
> -                                             "router-port");
> -            if (!peer_name) {
> -                continue;
> -            }
> -
> -            struct ovn_port *peer = ovn_port_find(ports, peer_name);
> -            if (!peer || !peer->nbr || !peer->ip) {
> -                continue;
> -            }
> -
> -            for (size_t j = 0; j < op->od->n_router_ports; j++) {
> -                const char *router_port_name = smap_get(
> -                                    &op->od->router_ports[j]->nbs->options,
> -                                    "router-port");
> -                struct ovn_port *router_port = ovn_port_find(ports,
> -                                                             router_port_name);
> -                if (!router_port || !router_port->nbr || !router_port->ip) {
> -                    continue;
> -                }
> -
> -                /* Skip the router port under consideration. */
> -                if (router_port == peer) {
> -                   continue;
> -                }
> -
> -                if (!router_port->ip) {
> -                    continue;
> -                }
> -                char *match = xasprintf("outport == %s && reg0 == "IP_FMT,
> -                                        peer->json_key,
> -                                        IP_ARGS(router_port->ip));
> -                char *actions = xasprintf("eth.dst = "ETH_ADDR_FMT"; next;",
> -                                          ETH_ADDR_ARGS(router_port->mac));
> -                ovn_lflow_add(lflows, peer->od, S_ROUTER_IN_ARP_RESOLVE,
> -                              100, match, actions);
> -                free(actions);
> -                free(match);
> -            }
>         }
>     }
> -
>     HMAP_FOR_EACH (od, key_node, datapaths) {
>         if (!od->nbr) {
>             continue;
> @@ -2489,6 +2375,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..c63d936
> --- /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 variables used here */
> +extern bool g_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 && g_command_line_args_parsed == true) {
> +        ft_log_open();
> +    }
> +    if ((g_command_line_args_parsed == false) || (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..b273b79 100644
> --- a/vswitchd/ovs-vswitchd.c
> +++ b/vswitchd/ovs-vswitchd.c
> @@ -51,6 +51,9 @@
> 
> VLOG_DEFINE_THIS_MODULE(vswitchd);
> 
> +/* we need this for function tracing module */
> +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;
> @@ -145,7 +148,6 @@ parse_options(int argc, char *argv[], char **unixctl_pathp)
>         OPT_DISABLE_SYSTEM,
>         DAEMON_OPTION_ENUMS,
>         OPT_DPDK,
> -        OPT_DUMMY_NUMA,
>     };
>     static const struct option long_options[] = {
>         {"help",        no_argument, NULL, 'h'},
> @@ -160,7 +162,6 @@ parse_options(int argc, char *argv[], char **unixctl_pathp)
>         {"enable-dummy", optional_argument, NULL, OPT_ENABLE_DUMMY},
>         {"disable-system", no_argument, NULL, OPT_DISABLE_SYSTEM},
>         {"dpdk", optional_argument, NULL, OPT_DPDK},
> -        {"dummy-numa", required_argument, NULL, OPT_DUMMY_NUMA},
>         {NULL, 0, NULL, 0},
>     };
>     char *short_options = ovs_cmdl_long_options_to_short_options(long_options);
> @@ -216,10 +217,6 @@ parse_options(int argc, char *argv[], char **unixctl_pathp)
>             ovs_fatal(0, "Using --dpdk to configure DPDK is not supported.");
>             break;
> 
> -        case OPT_DUMMY_NUMA:
> -            ovs_numa_set_dummy(optarg);
> -            break;
> -
>         default:
>             abort();
>         }
> @@ -240,6 +237,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.8.3.1
> 
> _______________________________________________
> dev mailing list
> dev@openvswitch.org
> http://openvswitch.org/mailman/listinfo/dev