"dev" <dev-boun...@openvswitch.org> wrote on 08/05/2016 10:51:38 PM:
> From: Nirapada Ghosh/San Jose/IBM@IBMUS
> To: dev@openvswitch.org
> Date: 08/05/2016 10:52 PM
> Subject: [ovs-dev] [PATCH V14] Function tracer to trace all function
calls
> Sent by: "dev" <dev-boun...@openvswitch.org>
>
> 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.
>
> Signed-off-by: Nirapada Ghosh <ngh...@us.ibm.com>
> ---
Comments in line - I'm still fighting with getting performance numbers
for this that I trust, so I'm likely going to have additional comments
when I figure out what's going on...
[snip]
> 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
Placing this additional text here is misleading - vlog does a lot
more than just enable/disable function tracing. I'd move this to
the bottom of the vlog command section and start with
"This command is also used ..."
> 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
>
> +
Why is this extra new-line here?
> /* 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;
> }
>
> +
Ditto...
> 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.
> + */
Style: begin the comment with capital and pull the closing */ up after
"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
Style: begin the second sentence with "A value of..."
> + * 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");
Style: space after comma in message string
> + 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;
> + }
In ovs, if I supply a command with value 1 and then
supply the same command with value 2, the new value takes
effect. Here, that means I expect the current file to be
closed and the new file to be opened. In addition, the
error message if the fopen fails isn't true or helpful -
not saying why doesn't help and saying "exiting" isn't true
the binary isn't exiting...
> + VLOG_INFO("opened ft-log file %s", s_);
> + ft_enabled=1;
Style: use true for setting a bool instead of 1
> +exit:
> + return msg;
> +}
Style: add a blank line between the two methods
> +void __attribute__ ((constructor,no_instrument_function))
> +ft_begin(void)
> +{
> + /* Nothing at this point, but this function is needed */
This comment still isn't clear - explain why the function
is needed [carry-over from v13]
> +}
Style: add a blank line space between the two methods
> +void __attribute__ ((destructor,no_instrument_function))
> +ft_end(void)
> +{
> + if (ft_fp != NULL) {
> + fclose(ft_fp);
> + }
> +}
Style: add a blank line space between the two methods
also is ft called outside of this module? If not, it
should be declared static. Lastly, unless there is
a reason for naming this ft, ovs style says it should
be named ft_<something> where the <something> is what
it does...
> +void __attribute__ ((no_instrument_function))
> +ft(const char *direction, void *func, void *caller)
> +{
> + struct timeval ltime;
> + if (gettimeofday(<ime, NULL) != 0) {
gettimeofday is unix-centric, use xgettimeofday from
lib/timeval.c instead
> + return;
> + }
> + fprintf(ft_fp, "%ld:%ld>%s>%p>%p\n", ltime.tv_sec,ltime.tv_usec,
> + direction, func, caller);
I don't understand why the use of ':' and '>' in the
output string here, I would think using '.' and ' '
would make it more human readable...
> + 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 \
I don't believe we need the above line anymore other than -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"
Are all of these really needed in the exclude function list?
If so, can we add a comment as to why?
> +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.
> +.
Ditto my comment from earlier about about moving this text down in the
vlog section
> .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\
> --
_______________________________________________
dev mailing list
dev@openvswitch.org
http://openvswitch.org/mailman/listinfo/dev
