On Mon, Aug 22, 2016 at 06:59:03PM -0700, ngh...@us.ibm.com wrote:
> From: Nirapada Ghosh <ngh...@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 <ngh...@us.ibm.com>
Hi, thanks for the patch. I have some suggestions that I'll put in the
form of an updated. I'm appending an incremental diff followed by a
full revised diff.
My changes:
- Improve the manpages.
- Simplify the code and fix some style violations.
- Fix the interference with CFLAGS, which is supposed to be the
user's prerogative, not interfered with by Automake.
I haven't tested my changes, beyond compiling,
I have a few additional comments, too.
This should be mentioned in NEWS and in INSTALL.md.
I'm surprised that fflush doesn't need to be on the no-instrument list.
vlog_set_fn_tracing_log() doesn't seem thread-safe, if another thread
sees a change to function_tracing_enabled at a time different from
function_tracing_fp. It seems like a mutex or atomics would be
appropriate.
Thanks,
Ben.
--8<--------------------------cut here-------------------------->8--
diff --git a/lib/vlog-unixctl.man b/lib/vlog-unixctl.man
index 71d0f8f..f13e143 100644
--- a/lib/vlog-unixctl.man
+++ b/lib/vlog-unixctl.man
@@ -82,12 +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 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.
+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 313ffaa..28bb0b9 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -49,19 +49,20 @@ 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;
+static bool function_tracing_enabled;
/* 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_);
+static const 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 __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);
@@ -816,9 +817,8 @@ vlog_init(void)
"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);
+ 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);
@@ -1324,80 +1324,71 @@ Logging options:\n\
* 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[],
+ int argc OVS_UNUSED, 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;
- }
+ const char *error = vlog_set_fn_tracing_log(argv[1]);
+ if (error) {
+ unixctl_command_reply_error(conn, error);
+ } else {
+ unixctl_command_reply(conn, NULL);
}
- unixctl_command_reply(conn, NULL);
+}
+
+static void
+close_trace_file(const char *ft_log_file)
+{
+ function_tracing_enabled = false;
+ fclose(function_tracing_fp);
+ VLOG_INFO("%s: closing function-tracing-log file", ft_log_file);
+ function_tracing_fp = 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 const 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 (strncmp(s,"off",4) == 0) {
if (!function_tracing_enabled) {
- msg = xstrdup("FT already disabled, skipping");
- goto exit;
+ return "FT already disabled, skipping";
}
- 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;
+ close_trace_file(ft_log_file);
+ return NULL;
}
+
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 (!strcmp(ft_log_file, s)) {
+ return "Tracing is already on, command ignored";
}
+ close_trace_file(ft_log_file);
}
- if ((function_tracing_fp = fopen(s_, "w")) == NULL) {
- msg = xstrdup("Failed to open file, command failed");
- goto exit;
+ function_tracing_fp = fopen(s, "w");
+ if (!function_tracing_fp) {
+ return "Failed to open file, command failed";
}
- if (ft_log_file) {
- free(ft_log_file);
- }
- ft_log_file = xstrdup(s_);
- VLOG_INFO("opened function-tracing-log file %s", s_);
+
+ free(ft_log_file);
+ ft_log_file = xstrdup(s);
+ VLOG_INFO("%s: opened function-tracing-log file", s);
function_tracing_enabled = true;
-exit:
- return msg;
+ return NULL;
}
-void __attribute__ ((constructor,no_instrument_function))
+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))
+void __attribute__ ((destructor, no_instrument_function))
fn_trace_end(void)
{
- if (function_tracing_fp != NULL) {
+ if (function_tracing_fp) {
fclose(function_tracing_fp);
}
}
@@ -1408,7 +1399,7 @@ 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);
+ ltime.tv_sec,ltime.tv_usec, direction, func, caller);
fflush(function_tracing_fp);
}
diff --git a/utilities/automake.mk b/utilities/automake.mk
index bdb39c7..9a65418 100644
--- a/utilities/automake.mk
+++ b/utilities/automake.mk
@@ -1,8 +1,8 @@
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"
+AM_CFLAGS += -g -finstrument-functions -DENABLE_FT \
+ -finstrument-functions-exclude-function-list=fprintf,xgettimeofday
endif
bin_PROGRAMS += \
diff --git a/utilities/ovs-appctl.8.in b/utilities/ovs-appctl.8.in
index 8ec0a19..539336a 100644
--- a/utilities/ovs-appctl.8.in
+++ b/utilities/ovs-appctl.8.in
@@ -277,13 +277,23 @@ 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 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.
+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
.
--8<--------------------------cut here-------------------------->8--
From: Nirapada Ghosh <ngh...@us.ibm.com>
Date: Mon, 22 Aug 2016 18:59:03 -0700
Subject: [PATCH] Function tracer to trace all function calls
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 <ngh...@us.ibm.com>
Signed-off-by: Ben Pfaff <b...@ovn.org>
---
configure.ac | 10 ++++
lib/vlog-unixctl.man | 19 ++++++
lib/vlog.c | 130 ++++++++++++++++++++++++++++++++++++++++
utilities/automake.mk | 8 +++
utilities/generate_ft_report.py | 83 +++++++++++++++++++++++++
utilities/ovs-appctl.8.in | 18 ++++++
6 files changed, 268 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..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..28bb0b9 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -46,6 +46,30 @@
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;
+
+/* 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 const 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);
+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 +816,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 +1317,105 @@ 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)
+{
+ function_tracing_enabled = false;
+ fclose(function_tracing_fp);
+ VLOG_INFO("%s: closing function-tracing-log file", ft_log_file);
+ function_tracing_fp = 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(). */
+static const char *
+vlog_set_fn_tracing_log(const char *s)
+{
+ 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);
+ }
+ function_tracing_fp = fopen(s, "w");
+ if (!function_tracing_fp) {
+ return "Failed to open file, command failed";
+ }
+
+ free(ft_log_file);
+ ft_log_file = xstrdup(s);
+ VLOG_INFO("%s: opened function-tracing-log file", s);
+ function_tracing_enabled = true;
+ 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..9a65418 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.1.3
_______________________________________________
dev mailing list
dev@openvswitch.org
http://openvswitch.org/mailman/listinfo/dev
