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

nghosh at us.ibm.com nghosh at us.ibm.com
Sat Aug 6 03:51:38 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.

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

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/lib/vlog-unixctl.man b/lib/vlog-unixctl.man
index 7372a7e..35f9f06 100644
--- a/lib/vlog-unixctl.man
+++ b/lib/vlog-unixctl.man
@@ -4,6 +4,15 @@
 .  IP "\\$1"
 ..
 .SS "VLOG COMMANDS"
+This command is 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.
+.
+.PP
 These commands manage \fB\*(PN\fR's logging settings.
 .IP "\fBvlog/set\fR [\fIspec\fR]"
 Sets logging levels.  Without any \fIspec\fR, sets the log level for
diff --git a/lib/vlog.c b/lib/vlog.c
index 333337b..95514fe 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -46,6 +46,26 @@
 
 VLOG_DEFINE_THIS_MODULE(vlog);
 
+#if defined(ENABLE_FT) && defined(__GNUC__)
+/* File pointer for logging trace output. */
+static FILE *ft_fp;
+/* Global flag holding current state of ft-enabled or not. */
+static bool ft_enabled = false;
+
+/* Prototypes for the functions declared/used in this file. */
+static void vlog_unixctl_set_ft(struct unixctl_conn *conn, int argc,
+                                const char *argv[], void *aux OVS_UNUSED);
+char * vlog_set_ft_log(const char *s_);
+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);
+#endif
+
 /* ovs_assert() logs the assertion message, so using ovs_assert() in this
  * source file could cause recursion. */
 #undef ovs_assert
@@ -467,6 +487,7 @@ vlog_change_owner_unix(uid_t user, gid_t group)
 }
 #endif
 
+
 /* Set debugging levels.  Returns null if successful, otherwise an error
  * message that the caller must free(). */
 char *
@@ -625,6 +646,7 @@ vlog_facility_exists(const char* facility, int *value)
     return false;
 }
 
+
 static void
 vlog_unixctl_set(struct unixctl_conn *conn, int argc, const char *argv[],
                  void *aux OVS_UNUSED)
@@ -792,6 +814,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_ft, NULL);
+#endif
         unixctl_command_register("vlog/list", "", 0, 0, vlog_unixctl_list,
                                  NULL);
         unixctl_command_register("vlog/list-pattern", "", 0, 0,
@@ -1289,3 +1316,99 @@ 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_ft(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_ft_log(argv[i]);
+        if (msg) {
+            unixctl_command_reply_error(conn, msg);
+            free(msg);
+            return;
+        }
+    }
+    unixctl_command_reply(conn, NULL);
+}
+
+/* Set function tracing on. "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_ft_log(const char *s_)
+{
+    char *msg = NULL;
+
+    if (strncmp(s_,"off",4) == 0) {
+       if (!ft_enabled) {
+           msg = xstrdup("FT already disabled,skipping");
+           goto exit;
+       }
+       ft_enabled = 0;
+       fclose(ft_fp);
+       VLOG_INFO("closing ft-log file");
+       ft_fp = NULL;
+       goto exit;
+    }
+    if (ft_enabled) {
+        msg = xstrdup("FT already enabled,skipping");
+        goto exit;
+    }
+    if ((ft_fp = fopen(s_, "w")) == NULL) {
+        msg = xstrdup("Failed to open file,exiting");
+        goto exit;
+    }
+    VLOG_INFO("opened ft-log file %s", s_);
+    ft_enabled=1;
+exit:
+    return msg;
+}
+void __attribute__ ((constructor,no_instrument_function))
+ft_begin(void)
+{
+    /* Nothing at this point, but this function is needed */
+}
+void __attribute__ ((destructor,no_instrument_function))
+ft_end(void)
+{
+    if (ft_fp != NULL) {
+        fclose(ft_fp);
+    }
+}
+void __attribute__ ((no_instrument_function))
+ft(const char *direction, void *func, void *caller)
+{
+    struct timeval ltime;
+    if (gettimeofday(&ltime, NULL) != 0) {
+        return;
+    }
+    fprintf(ft_fp, "%ld:%ld>%s>%p>%p\n", ltime.tv_sec,ltime.tv_usec,
+        direction, func, caller);
+    fflush(ft_fp);
+}
+
+void __attribute__ ((no_instrument_function))
+__cyg_profile_func_enter(void *func, void *caller)
+{
+    if (ft_enabled) {
+        ft("entry", func, caller);
+    }
+}
+
+void __attribute__ ((no_instrument_function))
+__cyg_profile_func_exit(void *func, void *caller)
+{
+    if (ft_enabled) {
+        ft("exit", func, caller);
+    }
+}
+#endif
diff --git a/utilities/automake.mk b/utilities/automake.mk
index 9d5b425..c12d279 100644
--- a/utilities/automake.mk
+++ b/utilities/automake.mk
@@ -1,3 +1,11 @@
+if ENABLE_FT
+CFLAGS += -g -finstrument-functions \
+          -ldl -export-dynamic -lrt -DENABLE_FT \
+          -f"instrument-functions-exclude-function-list=fprintf,time_init,\
+          xclock_gettime,time_timespec__,timespec_to_msec,timespec_to_msec,\
+          time_msec__,time_msec,gettimeofday"
+endif
+
 bin_PROGRAMS += \
 	utilities/ovs-appctl \
 	utilities/ovs-testcontroller \
@@ -59,6 +67,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/generate_ft_report.py b/utilities/generate_ft_report.py
new file mode 100644
index 0000000..58610a1
--- /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..fdbf1fd 100644
--- a/utilities/ovs-appctl.8.in
+++ b/utilities/ovs-appctl.8.in
@@ -106,6 +106,14 @@ Information useful only to someone with intricate knowledge of the
 system, or that would commonly cause too-voluminous log output.  Log
 messages at this level are not logged by default.
 .
+.SS "VLOG COMMANDS"
+This command is 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.
+.
 .PP
 Every Open vSwitch daemon supports the following commands for examining
 and adjusting log levels.
diff --git a/utilities/ovs-appctl.c b/utilities/ovs-appctl.c
index 8f87cc4..5bff3cf 100644
--- a/utilities/ovs-appctl.c
+++ b/utilities/ovs-appctl.c
@@ -98,6 +98,11 @@ Common commands:\n\
       A valid module name (all modules, by default)\n\
       'syslog', 'console', 'file' (all destinations, by default))\n\
       'off', 'emer', 'err', 'warn', 'info', or 'dbg' ('dbg', bydefault)\n\
+  vlog/trace <filename>\n\
+      Sets function tracing on or off. Only available when configured\n\
+      with --enable-ft. If 'off' is passed, it turns off tracing\n\
+      for the module in question. Otherwise, filename is the name of\n\
+      the trace log file and tracing will be turned on with this.\n\
   vlog/reopen        Make the program reopen its log file\n\
 Other options:\n\
   --timeout=SECS     wait at most SECS seconds for a response\n\
-- 
2.9.2




More information about the dev mailing list