[ovs-dev] [PATCH V13] Function tracer to trace all function calls
nghosh at us.ibm.com
nghosh at us.ibm.com
Sat Jul 9 00:04:06 UTC 2016
From: Nirapada Ghosh <nghosh at 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 at us.ibm.com>
---
INSTALL.md | 17 ++++
configure.ac | 10 +++
include/openvswitch/vlog.h | 5 ++
lib/vlog.c | 30 +++++++
ovn/controller/automake.mk | 5 ++
ovn/northd/automake.mk | 5 ++
utilities/automake.mk | 7 ++
utilities/function_tracer.c | 171 ++++++++++++++++++++++++++++++++++++++++
utilities/generate_ft_report.py | 79 +++++++++++++++++++
vswitchd/automake.mk | 5 ++
10 files changed, 334 insertions(+)
create mode 100644 utilities/function_tracer.c
create mode 100644 utilities/generate_ft_report.py
diff --git a/INSTALL.md b/INSTALL.md
index f4d232b..d12c00d 100644
--- a/INSTALL.md
+++ b/INSTALL.md
@@ -247,6 +247,23 @@ add --enable-Werror, which adds the -Werror option to the compiler
command line, turning warnings into errors. That makes it
impossible to miss warnings generated by the build.
+Function instrumentation might be enabled for modules like ovn-northd,
+ovn-controller, and ovs-vswitchd module. This is available only with GCC
+compiler today. Once ovs is built with instrumentation enabled, the service
+should be restarted and then vlog mode has to be put in dbg. Log file
+[with functions entry and exit timestamps] is created only when the vlog
+level is set to 'dbg'. This log file could be fed to the provided
+generate_ft_report.py to see a more human readable log.
+
+To build with function instrumentation enabled, add
+--enable-ft to configure, e.g.:
+
+ `% ./configure --enable-ft`
+
+To turn on instrumentation on module, use ovs-appctl to set vlog level, e.g.:
+
+ `ovs-appctl -t ovn-northd vlog/set any:any:dbg`
+
To build with gcov code coverage support, add --enable-coverage,
e.g.:
diff --git a/configure.ac b/configure.ac
index 05d80d5..6eb2c1c 100644
--- a/configure.ac
+++ b/configure.ac
@@ -28,6 +28,16 @@ AC_PROG_MKDIR_P
AC_PROG_FGREP
AC_PROG_EGREP
+AC_ARG_ENABLE([ft],
+ [AC_HELP_STRING([--enable-ft], [Turn on function tracing])],
+ [case "${enableval}" in
+ (yes) ft=true ;;
+ (no) ft=false ;;
+ (*) AC_MSG_ERROR([bad value ${enableval} for --enable-ft]) ;;
+ esac],
+ [ft=false])
+AM_CONDITIONAL([ENABLE_FT], [test x$ft = xtrue])
+
AC_ARG_VAR([PERL], [path to Perl interpreter])
AC_PATH_PROG([PERL], perl, no)
if test "$PERL" = no; then
diff --git a/include/openvswitch/vlog.h b/include/openvswitch/vlog.h
index de64cbd..2fcc616 100644
--- a/include/openvswitch/vlog.h
+++ b/include/openvswitch/vlog.h
@@ -57,6 +57,11 @@ enum vlog_level {
VLL_N_LEVELS
};
+#ifdef __GNUC__
+void __attribute__ ((no_instrument_function)) vlog_directory(char *, int);
+#else
+void vlog_directory(char *, int);
+#endif
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 333337b..9f7e255 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -1262,6 +1262,36 @@ vlog_should_drop(const struct vlog_module *module, enum vlog_level level,
return false;
}
+#ifdef __GNUC__
+void __attribute__ ((no_instrument_function))
+#else
+void
+#endif
+vlog_directory(char *dir,int len)
+{
+ char *tmp_dir = NULL;
+ if (log_file_name == NULL) {
+ tmp_dir = strdup(ovs_logdir());
+ } else {
+ tmp_dir = strdup(log_file_name);
+ if (tmp_dir) {
+ /* Take out the filename, we need only the path */
+ char *fname = strrchr(tmp_dir,'/');
+ if (fname) {
+ *fname = '\0';
+ }
+ }
+ }
+ if ((tmp_dir == NULL) || (strlen(tmp_dir) > len)) {
+ *dir = '\0';
+ } else {
+ strcpy(dir, tmp_dir);
+ }
+ if (tmp_dir) {
+ free(tmp_dir);
+ }
+}
+
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..1bd0d7a 100644
--- a/ovn/controller/automake.mk
+++ b/ovn/controller/automake.mk
@@ -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 += utilities/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/northd/automake.mk b/ovn/northd/automake.mk
index 6e713fc..2e467b6 100644
--- a/ovn/northd/automake.mk
+++ b/ovn/northd/automake.mk
@@ -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 += utilities/function_tracer.c
+endif
+
ovn_northd_ovn_northd_LDADD = \
ovn/lib/libovn.la \
ovsdb/libovsdb.la \
diff --git a/utilities/automake.mk b/utilities/automake.mk
index 9d5b425..81b3121 100644
--- a/utilities/automake.mk
+++ b/utilities/automake.mk
@@ -1,3 +1,9 @@
+if ENABLE_FT
+CFLAGS += -g -finstrument-functions \
+ -ldl -export-dynamic -lrt \
+ -finstrument-functions-exclude-function-list=fprintf,strcpy,snprintf
+endif
+
bin_PROGRAMS += \
utilities/ovs-appctl \
utilities/ovs-testcontroller \
@@ -59,6 +65,7 @@ EXTRA_DIST += \
utilities/ovs-vlan-test.in \
utilities/ovs-vsctl-bashcomp.bash \
utilities/qemu-wrap.py \
+ utilities/generate_ft_report.py \
utilities/checkpatch.py
MAN_ROOTS += \
utilities/ovs-appctl.8.in \
diff --git a/utilities/function_tracer.c b/utilities/function_tracer.c
new file mode 100644
index 0000000..ab152d9
--- /dev/null
+++ b/utilities/function_tracer.c
@@ -0,0 +1,171 @@
+/* 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 <config.h>
+#include <stdio.h>
+#include <sys/types.h>
+#include <unistd.h>
+#include <time.h>
+#include <sys/time.h>
+#include <string.h>
+#include <dlfcn.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;
+static bool setting_log_file_completed = false;
+static void *setting_log_file_completion_indicator = "daemonize_start";
+
+/* External functions used here */
+void __attribute__ ((no_instrument_function)) ft_log_open(void);
+bool __attribute__ ((no_instrument_function)) check_if_function_matches(
+ const char *fname_to_match,
+ void *func);
+
+/* 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);
+ }
+}
+
+bool __attribute__ ((no_instrument_function))
+check_if_function_matches(const char *function_to_match, void *func)
+{
+ Dl_info dl1;
+ dladdr(func, &dl1);
+ if (dl1.dli_sname == NULL || strcmp(function_to_match,
+ dl1.dli_sname) != 0) {
+ return false;
+ }
+ return true;
+}
+
+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 (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) {
+ return;
+ }
+ if (log_fp) {
+ ft("entry", func, caller);
+ } else if (setting_log_file_completed == true) {
+ ft_log_open();
+ if (log_fp) {
+ ft("entry", func, caller);
+ }
+ }
+}
+
+void __attribute__ ((no_instrument_function))
+__cyg_profile_func_exit(void *func, void *caller)
+{
+ if (setting_log_file_completed == false &&
+ check_if_function_matches(setting_log_file_completion_indicator,
+ func)) {
+ setting_log_file_completed = true;
+ }
+ if (CURRENT_LOG_LEVEL < VLL_DBG) {
+ return;
+ }
+ if (log_fp) {
+ ft("exit", func, caller);
+ } else if (setting_log_file_completed == true) {
+ ft_log_open();
+ }
+}
diff --git a/utilities/generate_ft_report.py b/utilities/generate_ft_report.py
new file mode 100644
index 0000000..a9969a2
--- /dev/null
+++ b/utilities/generate_ft_report.py
@@ -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, 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 "Function Entry not found, skipping, exception %s" % (ex)
+ else:
+ functions[func_name] = {'timestamp':tstamp, 'caller':caller,
+ 'serial':serial}
+
+
+def main():
+ if len(sys.argv) != 3:
+ print "Usage: %s <exe-file> <log-file>" %sys.argv[0]
+ return
+ exe = sys.argv[1]
+ filename = sys.argv[2]
+ serial = 0
+ with open(filename) as f:
+ for line in f:
+ serial += 1
+ tokens = line.strip().split('>')
+ #arguments (timestamp, dirn, called, caller,serial,exe)
+ update_and_print(tokens[0], tokens[1], tokens[2],
+ tokens[3], serial, exe)
+
+if __name__ == "__main__":
+ main()
diff --git a/vswitchd/automake.mk b/vswitchd/automake.mk
index 8d7f3ea..5024c78 100644
--- a/vswitchd/automake.mk
+++ b/vswitchd/automake.mk
@@ -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 += utilities/function_tracer.c
+endif
+
vswitchd_ovs_vswitchd_LDADD = \
ofproto/libofproto.la \
lib/libsflow.la \
--
2.9.0
More information about the dev
mailing list