[ovs-dev] [PATCH V16] Function tracer to trace all function calls
nghosh at us.ibm.com
nghosh at us.ibm.com
Fri Oct 21 01:18:04 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 to be configured with
"--enable-ft" command line argument [i.e. configure --enable-ft]
This feature logs the tracing output to log files,
that is set using "ovs-appctl vlog/trace <filename>" command.
"ovs-appctl vlog/trace off" turns the logging off.
The feature uses the hooks GNU-C provides when compiled with
-finstrument-functions flag, we just have to implement
them. What it means is, once you compile the code with --enable-ft
option, function calls are going to be routed to the tracing routine.
In other words, even if we do disable tracing, the extra calls would
be happening even though with very less CPU overhead as the calls
would return right away. The initialization call [ constructor ] happens
even before main() is invoked, so no chance of completely disabling
tracing when configured with --enable-ft. So, unless you intend on debugging
a module in OVS, this option would better be turned off by default.
It is intended to be used for debugging purposes only. Compiling with
--enable-ft flag will add two calls for every function call [entry and exit]
thereby two log lines into trace log output file if enabled, please turn it on
when you need to and turn it off when done. If you are not debugging a
problem that requires function-tracing, please do not even compile with
--enable-ft flag.
Signed-off-by: Nirapada Ghosh <nghosh at us.ibm.com>
---
INSTALL.Fedora.md | 4 +-
INSTALL.rst | 4 ++
NEWS | 2 +
configure.ac | 10 +++
lib/vlog-unixctl.man | 19 ++++++
lib/vlog.c | 143 ++++++++++++++++++++++++++++++++++++++++
utilities/automake.mk | 8 +++
utilities/generate_ft_report.py | 83 +++++++++++++++++++++++
utilities/ovs-appctl.8.in | 18 +++++
9 files changed, 289 insertions(+), 2 deletions(-)
create mode 100644 utilities/generate_ft_report.py
diff --git a/INSTALL.Fedora.md b/INSTALL.Fedora.md
index 028a992..6faa1c9 100644
--- a/INSTALL.Fedora.md
+++ b/INSTALL.Fedora.md
@@ -37,11 +37,11 @@ below.
### Preparing to Build Open vSwitch RPMs with a GIT Tree
From the top-level directory of the git tree, execute the following
-commands:
+commands, use "--enable-ft" to enable function tracing:
```
./boot.sh
-./configure
+./configure [ --enable-ft ]
```
### Preparing to Build Open vSwitch RPMs from a Tarball
diff --git a/INSTALL.rst b/INSTALL.rst
index 07d69f1..27bf994 100644
--- a/INSTALL.rst
+++ b/INSTALL.rst
@@ -294,6 +294,10 @@ To build with gcov code coverage support, add ``--enable-coverage``::
$ ./configure --enable-coverage
+To build with function tracing enabled, add ``--enable-ft``::
+
+ $ ./configure --enable-ft
+
The configure script accepts a number of other options and honors additional
environment variables. For a full list, invoke configure with the ``--help``
option::
diff --git a/NEWS b/NEWS
index d07ec45..300e92f 100644
--- a/NEWS
+++ b/NEWS
@@ -1,5 +1,7 @@
Post-v2.6.0
---------------------
+ - ovs-appctl:
+ * New "vlog/trace" command, this will add function tracing capability.
- OVN:
* QoS is now implemented via egress shaping rather than ingress policing.
* DSCP marking is now supported, via the new northbound QoS table.
diff --git a/configure.ac b/configure.ac
index 2f854dd..2bcad39 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/lib/vlog-unixctl.man b/lib/vlog-unixctl.man
index 7372a7e..f13e143 100644
--- a/lib/vlog-unixctl.man
+++ b/lib/vlog-unixctl.man
@@ -82,3 +82,22 @@ the keyword \fBany\fR disables rate limits for every log module.
The \fBvlog/enable\-rate\-limit\fR command, whose syntax is the same
as \fBvlog/disable\-rate\-limit\fR, can be used to re-enable a rate
limit that was previously disabled.
+.
+.IP "\fBvlog/trace\fR \fIfilename\fR"
+Turns on function tracing output to \fIfilename\fR, which will be
+overwritten if it already exists. When function tracing is enabled,
+each time execution enters or exits a function, OVS logs the current
+time in microseconds, either \fBenter\fR or \fBexit\fR, and the
+address of the function and its caller. This output, suitably
+analyzed (e.g. with the script provided in the OVS tree as
+\fButilities/generate_ft_report.py\fR), can be useful for profiling
+and debugging.
+.IP
+This feature is available only when Open vSwitch was built with GNU C
+and configured with \fB\-\-enable\-ft\fR. Configuring with
+\fB\-\-enable\-ft\fR adds significant runtime overhead, which
+increases further when tracing is enabled.
+.
+.IP "\fBvlog/trace\fR \fBoff\fR"
+Disables function tracing.
+.IP
diff --git a/lib/vlog.c b/lib/vlog.c
index 333337b..6d5edea 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -46,6 +46,36 @@
VLOG_DEFINE_THIS_MODULE(vlog);
+#if defined(ENABLE_FT) && defined(__GNUC__)
+
+/* Mutex for function tracing globals. */
+static struct ovs_mutex function_tracing_mutex = OVS_MUTEX_INITIALIZER;
+
+/* File pointer for logging trace output. */
+static FILE *function_tracing_fp OVS_GUARDED_BY(funcion_tracing_mutex) = NULL;
+
+/* Global flag holding current state of function-tracing-enabled or not. */
+static bool function_tracing_enabled OVS_GUARDED_BY(funcion_tracing_mutex) = 0;
+
+/* Prototypes for the functions declared/used in this file. */
+static void close_trace_file(const char *ft_log_file);
+static const char *vlog_set_fn_tracing_log(const char *s_);
+
+static void vlog_unixctl_set_fn_tracing(struct unixctl_conn *conn,
+ int argc,
+ const char *argv[],
+ void *aux OVS_UNUSED);
+void __attribute__ ((constructor,no_instrument_function)) fn_trace_begin(void);
+void __attribute__ ((destructor,no_instrument_function)) fn_trace_end(void);
+void __attribute__ ((no_instrument_function)) trace_func_call(
+ 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);
+#endif
+
/* ovs_assert() logs the assertion message, so using ovs_assert() in this
* source file could cause recursion. */
#undef ovs_assert
@@ -792,6 +822,10 @@ vlog_init(void)
unixctl_command_register(
"vlog/set", "{spec | PATTERN:destination:pattern}",
1, INT_MAX, vlog_unixctl_set, NULL);
+#if defined(ENABLE_FT) && defined(__GNUC__)
+ unixctl_command_register("vlog/trace", "filename",
+ 1, 1, vlog_unixctl_set_fn_tracing, NULL);
+#endif
unixctl_command_register("vlog/list", "", 0, 0, vlog_unixctl_list,
NULL);
unixctl_command_register("vlog/list-pattern", "", 0, 0,
@@ -1289,3 +1323,112 @@ Logging options:\n\
--syslog-target=HOST:PORT also send syslog msgs to HOST:PORT via UDP\n",
ovs_logdir(), program_name);
}
+
+#if defined(ENABLE_FT) && defined(__GNUC__)
+
+/* Unixctl callback routine to enable or disable function tracing,
+ * A valid filename is required to enable it,"off" to turn it off. */
+static void
+vlog_unixctl_set_fn_tracing(struct unixctl_conn *conn,
+ int argc OVS_UNUSED, const char *argv[],
+ void *aux OVS_UNUSED)
+{
+ const char *error = vlog_set_fn_tracing_log(argv[1]);
+ if (error) {
+ unixctl_command_reply_error(conn, error);
+ } else {
+ unixctl_command_reply(conn, NULL);
+ }
+}
+
+static void
+close_trace_file(const char *ft_log_file) OVS_EXCLUDED(function_tracing_mutex)
+{
+ ovs_mutex_lock(&function_tracing_mutex);
+ function_tracing_enabled = false;
+ fclose(function_tracing_fp);
+ function_tracing_fp = NULL;
+ ovs_mutex_unlock(&function_tracing_mutex);
+ VLOG_INFO("function-tracing-log file %s closed", ft_log_file);
+}
+
+/* Set function tracing on. A value of "off" disables tracing, otherwise
+ * the argument is name of the file where tracing data will be written.
+ * Returns null if successful, otherwise an error
+ * message that the caller must free(). */
+static const char *
+vlog_set_fn_tracing_log(const char *s) OVS_EXCLUDED(function_tracing_mutex)
+{
+ static char *ft_log_file = NULL;
+
+ if (strncmp(s,"off",4) == 0) {
+ if (!function_tracing_enabled) {
+ return "FT already disabled, skipping";
+ }
+ close_trace_file(ft_log_file);
+ return NULL;
+ }
+
+ if (function_tracing_enabled) {
+ if (!strcmp(ft_log_file, s)) {
+ return "Tracing is already on, command ignored";
+ }
+ close_trace_file(ft_log_file);
+ }
+ ovs_mutex_lock(&function_tracing_mutex);
+ function_tracing_fp = fopen(s, "w");
+ if (!function_tracing_fp) {
+ ovs_mutex_unlock(&function_tracing_mutex);
+ return "Failed to open file, command failed";
+ }
+ function_tracing_enabled = true;
+ if (ft_log_file) {
+ free(ft_log_file);
+ }
+ ft_log_file = xstrdup(s);
+ ovs_mutex_unlock(&function_tracing_mutex);
+
+ VLOG_INFO("function-tracing-log file %s opened", s);
+ return NULL;
+}
+
+void __attribute__ ((constructor, no_instrument_function))
+fn_trace_begin(void)
+{
+ /* Nothing at this point, but this function is needed */
+}
+
+void __attribute__ ((destructor, no_instrument_function))
+fn_trace_end(void)
+{
+ if (function_tracing_fp) {
+ fclose(function_tracing_fp);
+ }
+}
+
+void __attribute__ ((no_instrument_function))
+trace_func_call(const char *direction, void *func, void *caller)
+{
+ struct timeval ltime;
+ xgettimeofday(<ime);
+ fprintf(function_tracing_fp, "%ld.%ld %s %p %p\n",
+ ltime.tv_sec,ltime.tv_usec, direction, func, caller);
+ fflush(function_tracing_fp);
+}
+
+void __attribute__ ((no_instrument_function))
+__cyg_profile_func_enter(void *func, void *caller)
+{
+ if (function_tracing_enabled) {
+ trace_func_call("entry", func, caller);
+ }
+}
+
+void __attribute__ ((no_instrument_function))
+__cyg_profile_func_exit(void *func, void *caller)
+{
+ if (function_tracing_enabled) {
+ trace_func_call("exit", func, caller);
+ }
+}
+#endif
diff --git a/utilities/automake.mk b/utilities/automake.mk
index 380418a..11a3183 100644
--- a/utilities/automake.mk
+++ b/utilities/automake.mk
@@ -1,3 +1,10 @@
+if ENABLE_FT
+# Following exclude functions are needed to break recursive call \
+ because tracing routine uses them.
+AM_CFLAGS += -g -finstrument-functions -DENABLE_FT \
+ -finstrument-functions-exclude-function-list=fprintf,xgettimeofday
+endif
+
bin_PROGRAMS += \
utilities/ovs-appctl \
utilities/ovs-testcontroller \
@@ -58,6 +65,7 @@ EXTRA_DIST += \
utilities/ovs-test.in \
utilities/ovs-vlan-test.in \
utilities/ovs-vsctl-bashcomp.bash \
+ utilities/generate_ft_report.py \
utilities/checkpatch.py
MAN_ROOTS += \
utilities/ovs-appctl.8.in \
diff --git a/utilities/generate_ft_report.py b/utilities/generate_ft_report.py
new file mode 100644
index 0000000..72857c4
--- /dev/null
+++ b/utilities/generate_ft_report.py
@@ -0,0 +1,83 @@
+# 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 in ms.
+ Time format passed is "sec.ms"
+ """
+
+ tokens1 = time1.strip().split('.')
+ tokens2 = time2.strip().split('.')
+ diff_secs = int(tokens2[0]) - int(tokens1[0])
+ diff_in_usecs = diff_secs * 1000000 + int(tokens2[1]) - int(tokens1[1]);
+ delta_time = "%d (ms)" % (diff_in_usecs)
+ return delta_time
+
+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,exename)
+ update_and_print(tokens[0], tokens[1], tokens[2],
+ tokens[3], serial, exe)
+
+if __name__ == "__main__":
+ main()
diff --git a/utilities/ovs-appctl.8.in b/utilities/ovs-appctl.8.in
index 645b62b..539336a 100644
--- a/utilities/ovs-appctl.8.in
+++ b/utilities/ovs-appctl.8.in
@@ -277,6 +277,24 @@ log file to be used.)
This has no effect if the target application was not invoked with the
\fB\-\-log\-file\fR option.
.
+.IP "\fBvlog/trace\fR \fIfilename\fR"
+Turns on function tracing output to \fIfilename\fR, which will be
+overwritten if it already exists. When function tracing is enabled,
+each time execution enters or exits a function, OVS logs the current
+time in microseconds, either \fBenter\fR or \fBexit\fR, and the
+address of the function and its caller. This output, suitably
+analyzed (e.g. with the script provided in the OVS tree as
+\fButilities/generate_ft_report.py\fR), can be useful for profiling
+and debugging.
+.IP
+This feature is available only when Open vSwitch was built with GNU C
+and configured with \fB\-\-enable\-ft\fR. Configuring with
+\fB\-\-enable\-ft\fR adds significant runtime overhead, which
+increases further when tracing is enabled.
+.
+.IP "\fBvlog/trace\fR \fBoff\fR"
+Disables function tracing.
+.
.SH OPTIONS
.
.so lib/common.man
--
2.10.1
More information about the dev
mailing list