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

nghosh at us.ibm.com nghosh at us.ibm.com
Tue Aug 23 01:55:32 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
anyways. In other words, even if we do disable tracing, the extra calls would
be happening though with very less CPU overhead, because 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. Turning it ON will
add two calls for every function call [entry and exit] and thereby two
log lines into trace log output file, please turn it on when you need to
and turn it off when done.

Currently working on adding a knob to set the min and max stack depth beyond which
functions won't be traced, any suggestions/comments are welcome.

Signed-off-by: Nirapada Ghosh <nghosh at us.ibm.com>
---
 configure.ac                    |  10 +++
 lib/vlog-unixctl.man            |   9 +++
 lib/vlog.c                      | 139 ++++++++++++++++++++++++++++++++++++++++
 utilities/automake.mk           |   8 +++
 utilities/generate_ft_report.py |  83 ++++++++++++++++++++++++
 utilities/ovs-appctl.8.in       |   8 +++
 6 files changed, 257 insertions(+)
 create mode 100644 utilities/generate_ft_report.py

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..71d0f8f 100644
--- a/lib/vlog-unixctl.man
+++ b/lib/vlog-unixctl.man
@@ -82,3 +82,12 @@ 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
+This command is also used to enable/disable function-tracing, availble
+only when configured with --enable-ft and only with GNUC.
+.IP "\fBvlog/trace\fR [\fIfilename\fR]"
+Sets function tracing on or off. If "off" is passed, it
+turns off tracing for the module in question, Otherwise,
+\fIfilename\fR is the name of the trace log file and tracing will
+be turned on with this command automatically.
+.IP
diff --git a/lib/vlog.c b/lib/vlog.c
index 333337b..313ffaa 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -46,6 +46,29 @@
 
 VLOG_DEFINE_THIS_MODULE(vlog);
 
+#if defined(ENABLE_FT) && defined(__GNUC__)
+/* File pointer for logging trace output. */
+static FILE *function_tracing_fp;
+/* Global flag holding current state of function-tracing-enabled or not. */
+static bool function_tracing_enabled = false;
+
+/* Prototypes for the functions declared/used in this file. */
+static void vlog_unixctl_set_fn_tracing(struct unixctl_conn *conn,
+                                        int argc,
+                                        const char *argv[],
+                                        void *aux OVS_UNUSED);
+static char * vlog_set_fn_tracing_log(const char *s_);
+void __attribute__ ((constructor,no_instrument_function)) fn_trace_begin(void);
+void __attribute__ ((destructor,no_instrument_function)) fn_trace_end(void);
+static 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 +815,11 @@ 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", "{spec | filename}",
+            1, INT_MAX, 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 +1317,114 @@ 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,
+                            const char *argv[],
+                            void *aux OVS_UNUSED)
+{
+    int i;
+
+    for (i = 1; i < argc; i++) {
+        char *msg = vlog_set_fn_tracing_log(argv[i]);
+        if (msg) {
+            unixctl_command_reply_error(conn, msg);
+            free(msg);
+            return;
+        }
+    }
+    unixctl_command_reply(conn, NULL);
+}
+
+/* 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(). */
+char *
+vlog_set_fn_tracing_log(const char *s_)
+{
+    static char *ft_log_file = NULL;
+    char *msg = NULL;
+
+    if (strncmp(s_,"off",4) == 0) {
+       if (!function_tracing_enabled) {
+           msg = xstrdup("FT already disabled, skipping");
+           goto exit;
+       }
+       function_tracing_enabled = 0;
+       fclose(function_tracing_fp);
+       VLOG_INFO("closing function-tracing-log file:%s", ft_log_file);
+       function_tracing_fp = NULL;
+       goto exit;
+    }
+    if (function_tracing_enabled) {
+        /* If the filename changes, close the exiting one and open the new one,
+         * otherwise, ignore the command. */
+        if (strcmp(ft_log_file, s_)) {
+            fclose(function_tracing_fp);
+            VLOG_INFO("closing function-tracing-log file:%s", ft_log_file);
+            function_tracing_fp = NULL;
+        } else {
+            msg = xstrdup("Tracing is already on, command ignored");
+            goto exit;
+        }
+    }
+    if ((function_tracing_fp = fopen(s_, "w")) == NULL) {
+        msg = xstrdup("Failed to open file, command failed");
+        goto exit;
+    }
+    if (ft_log_file) {
+        free(ft_log_file);
+    }
+    ft_log_file = xstrdup(s_);
+    VLOG_INFO("opened function-tracing-log file %s", s_);
+    function_tracing_enabled = true;
+exit:
+    return msg;
+}
+
+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 != NULL) {
+        fclose(function_tracing_fp);
+    }
+}
+
+void __attribute__ ((no_instrument_function))
+trace_func_call(const char *direction, void *func, void *caller)
+{
+    struct timeval ltime;
+    xgettimeofday(&ltime);
+    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..bdb39c7 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.
+CFLAGS += -g -finstrument-functions -DENABLE_FT \
+          -f"instrument-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 0eda7f2..8e7bd67 100644
--- a/utilities/ovs-appctl.8.in
+++ b/utilities/ovs-appctl.8.in
@@ -277,6 +277,14 @@ log file to be used.)
 This has no effect if the target application was not invoked with the
 \fB\-\-log\-file\fR option.
 .
+.IP
+This command is also used to enable/disable function-tracing, availble
+only when configured with --enable-ft and with GNUC.
+.IP "\fBvlog/trace\fR [\fIfilename\fR]"
+Sets function tracing on or off. If "off" is passed, it turns
+off tracing for the module in question, Otherwise, \fIfilename\fR is
+the name of the trace log file and tracing will be turned on with this.
+.
 .SH OPTIONS
 .
 .so lib/common.man
-- 
2.9.3




More information about the dev mailing list