@@ -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
@@ -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);
@@ -1262,6 +1262,29 @@ 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, ...)
@@ -20,6 +20,11 @@ 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
@@ -61,11 +61,20 @@ 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[]);
+bool __attribute__ ((no_instrument_function)) is_cmd_line_args_parsed(void);
+
OVS_NO_RETURN static void usage(void);
static char *ovs_remote;
+bool __attribute__ ((no_instrument_function))
+is_cmd_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)
{
@@ -608,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
@@ -1,6 +1,11 @@
# ovn-northd
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 \
@@ -42,6 +42,9 @@
VLOG_DEFINE_THIS_MODULE(ovn_northd);
+static bool g_command_line_args_parsed = false;
+bool __attribute__ ((no_instrument_function)) is_cmd_line_args_parsed(void);
+
static unixctl_cb_func ovn_northd_exit;
struct northd_context {
@@ -122,6 +125,12 @@ enum ovn_stage {
#undef PIPELINE_STAGE
};
+bool __attribute__ ((no_instrument_function))
+is_cmd_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
@@ -2692,6 +2701,7 @@ parse_options(int argc OVS_UNUSED, char *argv[] OVS_UNUSED)
}
free(short_options);
+ g_command_line_args_parsed = true;
}
static void
@@ -1,2 +1,8 @@
+if ENABLE_FT
+CFLAGS += -g -finstrument-functions \
+ -ldl -export-dynamic -lrt \
+ -finstrument-functions-exclude-function-list=snprintf,fprintf
+endif
+
docs += third-party/README.md
EXTRA_DIST += third-party/ofp-tcpdump.patch
new file mode 100644
@@ -0,0 +1,143 @@
+/* Copyright (c) 2016 IBM, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at:
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+/*
+ * 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 */
+void __attribute__ ((no_instrument_function)) ft_log_open(void);
+bool __attribute__ ((no_instrument_function)) is_cmd_line_args_parsed(void);
+
+/* Prototypes for the functions declared/used in this file. */
+void __attribute__ ((constructor,no_instrument_function)) ft_begin(void);
+void __attribute__ ((destructor,no_instrument_function)) ft_end(void);
+void __attribute__ ((no_instrument_function)) ft(const char * direction,
+ void *func, void * caller);
+void __attribute__ ((no_instrument_function)) __cyg_profile_func_enter(
+ void *func, void *caller);
+void __attribute__ ((no_instrument_function)) __cyg_profile_func_exit(
+ void *func, void *caller);
+int __attribute__ ((no_instrument_function)) format_time(struct timeval *lt,
+ char *buf,
+ size_t size);
+
+void __attribute__ ((constructor,no_instrument_function))
+ft_begin(void)
+{
+ /* Nothing at this point, but needed */
+}
+
+void __attribute__ ((no_instrument_function))
+ft_log_open(void)
+{
+ char log_name[LOG_FILE_NAME_LEN];
+ char dir_name[LOG_DIR_NAME_LEN];
+
+ vlog_directory(dir_name, LOG_DIR_NAME_LEN);
+ snprintf(log_name, LOG_FILE_NAME_LEN, "%s/%s_%d.log",
+ dir_name, LOG_FILENAME_PREFIX, getpid());
+ if ((log_fp = fopen(log_name, "w")) == NULL) {
+ fprintf(stderr, "Failed to open output trace file: %s\n", log_name);
+ }
+}
+
+
+void __attribute__ ((destructor,no_instrument_function))
+ft_end(void)
+{
+ if (log_fp != NULL) {
+ fclose(log_fp);
+ }
+}
+
+/* Gets the current timestamp into the input buffer in ascii format */
+int __attribute__ ((no_instrument_function))
+format_time(struct timeval *lt, char *buf, size_t size)
+{
+ struct tm gm_time;
+ int bytes_written = -1;
+
+ gmtime_r(<->tv_sec,&gm_time);
+ bytes_written = strftime(buf, size, "%Y-%m-%dT%H:%M:%S", &gm_time);
+ if ((bytes_written > 0) && ((size_t) bytes_written < size)) {
+ int tmp = snprintf(buf + bytes_written,
+ size - (size_t) bytes_written, ".%06d",
+ (int) lt->tv_usec);
+ bytes_written = (tmp > 0) ? bytes_written + tmp : -1;
+ }
+ return bytes_written;
+}
+
+
+void __attribute__ ((no_instrument_function))
+ft(const char *direction, void *func, void *caller)
+{
+ char timestr[64];
+ struct timeval ltime;
+
+ if (log_fp == NULL && is_cmd_line_args_parsed()) {
+ ft_log_open();
+ }
+ if ((!is_cmd_line_args_parsed()) || (log_fp == NULL)) {
+ return;
+ }
+ if (gettimeofday(<ime, NULL) != 0) {
+ return;
+ }
+ if (format_time(<ime, timestr, sizeof(timestr)) <= 0) {
+ return;
+ }
+ 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)
+{
+ if (CURRENT_LOG_LEVEL >= VLL_DBG) {
+ ft("entry", func, caller);
+ }
+}
+
+void __attribute__ ((no_instrument_function))
+__cyg_profile_func_exit(void *func, void *caller)
+{
+ if (CURRENT_LOG_LEVEL >= VLL_DBG) {
+ ft("exit", func, caller);
+ }
+}
new file mode 100644
@@ -0,0 +1,79 @@
+# Copyright (c) 2016 IBM, Inc.
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+# http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+#!/usr/bin/env python
+import sys
+import subprocess
+from datetime import datetime
+
+# functions hold the details regarding when it was called, when it was complete
+functions = {}
+
+def find_symbol_name(func_addr, exe):
+ """Give the hex address of a method, 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()
@@ -59,6 +59,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 \
@@ -11,6 +11,11 @@ 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 \
@@ -51,6 +51,8 @@
VLOG_DEFINE_THIS_MODULE(vswitchd);
+static bool g_command_line_args_parsed = false;
+bool __attribute__ ((no_instrument_function)) is_cmd_line_args_parsed(void);
/* --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 +62,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 __attribute__ ((no_instrument_function))
+is_cmd_line_args_parsed(void)
+{
+ return g_command_line_args_parsed;
+}
+
int
main(int argc, char *argv[])
{
@@ -240,6 +248,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