Hi, Daniele, I am also interesting in profiling the ovs process and would like to participate in the discussion.
I am using oprofile-1.1.0 to profiling the ovn-northd process. I believe oprofile-1.1.0 share the same underlying profiling mechanism as Linux perf (correct me if I am wrong). However, it is hard for me to understand the output of the profiled data. For example, in a highly overloaded ovn-northd process, the output of opreport --callgraph is =============================================================== CPU: Intel Sandy Bridge microarchitecture, speed 3300 MHz (estimated) Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 90000 samples % image name symbol name ------------------------------------------------------------------------------- 1 0.3497 ovn-northd build_lswitch_flows.constprop.16 1 0.3497 ovn-northd sbrec_port_binding_set_options 1 0.3497 ovn-northd jsonrpc_session_run 1 0.3497 ovn-northd _init 1 0.3497 ovn-northd nbrec_logical_port_set_addresses 1 0.3497 ovn-northd nbrec_logical_router_port_get_mac 1 0.3497 ovn-northd sbrec_chassis_set_vtep_logical_switches 1 0.3497 ovn-northd describe_fd 1 0.3497 ovn-northd ovs_error 1 0.3497 ovn-northd vlog_valist 1 0.3497 ovn-northd make_unix_socket 1 0.3497 ovn-northd ofpbuf_use_const 2 0.6993 ovn-northd quicksort 2 0.6993 ovn-northd count_cpu_cores 7 2.4476 ovn-northd _fini 263 91.9580 ovn-northd ovs_scan__ 137264 58.5425 libc-2.19.so /lib/x86_64-linux-gnu/libc-2.19.so 137264 100.000 libc-2.19.so /lib/x86_64-linux-gnu/libc-2.19.so [self] ------------------------------------------------------------------------------- 1 33.3333 ovn-northd json_hash 2 66.6667 ovn-northd sbrec_chassis_set_external_ids 17467 7.4496 ovn-northd main 17467 99.9828 ovn-northd main [self] 2 0.0114 kallsyms apic_timer_interrupt 1 0.0057 kallsyms reschedule_interrupt ------------------------------------------------------------------------------- 13190 5.6255 ovn-northd hexit_value 13190 99.9924 ovn-northd hexit_value [self] 1 0.0076 kallsyms apic_timer_interrupt ------------------------------------------------------------------------------- 10227 4.3618 ovn-northd hash_bytes 10227 99.9804 ovn-northd hash_bytes [self] 2 0.0196 kallsyms apic_timer_interrupt ------------------------------------------------------------------------------- 9458 4.0338 ovn-northd scan_int =============================================================== The callgraph seems not aligh with the ovn-northd implementation. Did I miss anything when compiling openvswitch source code (I used default ./configure; make to generate the ovn-northd execuable)? Thanks. - Hui > From: Daniele Di Proietto <diproiet...@ovn.org> > To: Nirapada Ghosh/San Jose/IBM@IBMUS > Cc: "dev@openvswitch.org" <dev@openvswitch.org> > Date: 06/14/2016 09:58 PM > Subject: Re: [ovs-dev] [PATCH V5] Function tracer to trace all function calls > Sent by: "dev" <dev-boun...@openvswitch.org> > > Hi Nirapada, > > When optimizing for the DPDK datapath we have a very similar problem and, > usually, running a simple profiler like perf ( > https://perf.wiki.kernel.org/index.php/Main_Page) is enough to highlight > the bottlenecks in terms of CPU usage. > > Have you tried perf? Does this infrastructure provide advantages over > sample profiling? I'm not saying that one is better than the other, I'm > just curious! > > Thanks, > > Daniele > > 2016-06-14 18:05 GMT-07:00 <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 needs to be configured with > > "--enable-ft" command line argument [i.e. configure --enable-ft] > > > > This instrumentation logs the tracing output in separate log files > > namely func_trace_<pid>.log. It does not use VLOG mechanism for > > logging as that will make the patch very complicated to avoid > > recursion in the trace routine. > > > > This feature starts dumping output, only in debug mode, which means > > ovs-appctl -t <module> vlog/set any:any:dbg should be used to enable > > this logging. > > > > Currently, only ovn-northd, ovn-controller, vswitchd are instrumented. > > > > It is intended to be used for debugging purposes. > > Signed-off-by: Nirapada Ghosh <ngh...@us.ibm.com> > > > > --- > > configure.ac | 10 +++ > > include/openvswitch/vlog.h | 1 + > > lib/vlog.c | 23 ++++++- > > ovn/controller/automake.mk | 9 +++ > > ovn/controller/ovn-controller.c | 9 +++ > > ovn/northd/automake.mk | 9 +++ > > ovn/northd/ovn-northd.c | 9 +++ > > third-party/function_tracer.c | 126 > > ++++++++++++++++++++++++++++++++++++++ > > third-party/generate_ft_report.py | 80 ++++++++++++++++++++++++ > > utilities/automake.mk | 1 + > > vswitchd/automake.mk | 8 +++ > > vswitchd/ovs-vswitchd.c | 8 +++ > > 12 files changed, 292 insertions(+), 1 deletion(-) > > create mode 100644 third-party/function_tracer.c > > create mode 100644 third-party/generate_ft_report.py > > > > diff --git a/configure.ac b/configure.ac > > index 05d80d5..4abb2ea 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, > > +[ --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/include/openvswitch/vlog.h b/include/openvswitch/vlog.h > > index de64cbd..2df8796 100644 > > --- a/include/openvswitch/vlog.h > > +++ b/include/openvswitch/vlog.h > > @@ -57,6 +57,7 @@ enum vlog_level { > > VLL_N_LEVELS > > }; > > > > +void __attribute__ ((no_instrument_function)) vlog_directory(char *, int); > > const char *vlog_get_level_name(enum vlog_level); > > enum vlog_level vlog_get_level_val(const char *name); > > > > diff --git a/lib/vlog.c b/lib/vlog.c > > index 30b5bc2..65fa073 100644 > > --- a/lib/vlog.c > > +++ b/lib/vlog.c > > @@ -1137,7 +1137,6 @@ vlog_valist(const struct vlog_module *module, enum > > vlog_level level, > > errno = save_errno; > > } > > } > > - > > void > > vlog(const struct vlog_module *module, enum vlog_level level, > > const char *message, ...) > > @@ -1262,6 +1261,28 @@ vlog_should_drop(const struct vlog_module *module, > > enum vlog_level level, > > return false; > > } > > > > +void __attribute__ ((no_instrument_function)) > > +vlog_directory(char *dir,int len) > > +{ > > + int dir_len; > > + if (log_file_name == NULL) { > > + dir_len = strlen(ovs_logdir()); > > + if (dir_len > len) { > > + *dir = '\0'; > > + } > > + snprintf(dir, dir_len, "%s", ovs_logdir()); > > + } else { > > + char *fname = strrchr(log_file_name,'/'); > > + if (fname) { > > + dir_len = strlen(log_file_name) - strlen(fname)+1; > > + if (dir_len > len) { > > + *dir = '\0'; > > + } else { > > + snprintf(dir, dir_len, "%s", log_file_name); > > + } > > + } > > + } > > +} > > void > > vlog_rate_limit(const struct vlog_module *module, enum vlog_level level, > > struct vlog_rate_limit *rl, const char *message, ...) > > diff --git a/ovn/controller/automake.mk b/ovn/controller/automake.mk > > index cf57bbd..61efcf4 100644 > > --- a/ovn/controller/automake.mk > > +++ b/ovn/controller/automake.mk > > @@ -1,3 +1,9 @@ > > +if ENABLE_FT > > +CFLAGS += -g -finstrument-functions \ > > + `pkg-config --cflags glib-2.0` \ > > + `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt > > +endif > > + > > bin_PROGRAMS += ovn/controller/ovn-controller > > ovn_controller_ovn_controller_SOURCES = \ > > ovn/controller/binding.c \ > > @@ -20,6 +26,9 @@ ovn_controller_ovn_controller_SOURCES = \ > > ovn/controller/ovn-controller.h \ > > ovn/controller/physical.c \ > > ovn/controller/physical.h > > +if ENABLE_FT > > +ovn_controller_ovn_controller_SOURCES += third-party/function_tracer.c > > +endif > > ovn_controller_ovn_controller_LDADD = ovn/lib/libovn.la lib/ > > libopenvswitch.la > > man_MANS += ovn/controller/ovn-controller.8 > > EXTRA_DIST += ovn/controller/ovn-controller.8.xml > > diff --git a/ovn/controller/ovn-controller.c > > b/ovn/controller/ovn-controller.c > > index 356a94b..4f71b15 100644 > > --- a/ovn/controller/ovn-controller.c > > +++ b/ovn/controller/ovn-controller.c > > @@ -61,11 +61,19 @@ static unixctl_cb_func ct_zone_list; > > > > #define DEFAULT_BRIDGE_NAME "br-int" > > > > +static bool g_command_line_args_parsed = false; > > static void parse_options(int argc, char *argv[]); > > + > > OVS_NO_RETURN static void usage(void); > > > > static char *ovs_remote; > > > > +bool > > +is_command_line_args_parsed(void) > > +{ > > + return g_command_line_args_parsed; > > +} > > + > > struct local_datapath * > > get_local_datapath(const struct hmap *local_datapaths, uint32_t > > tunnel_key) > > { > > @@ -614,6 +622,7 @@ parse_options(int argc, char *argv[]) > > VLOG_FATAL("exactly zero or one non-option argument required; " > > "use --help for usage"); > > } > > + g_command_line_args_parsed = true; > > } > > > > static void > > diff --git a/ovn/northd/automake.mk b/ovn/northd/automake.mk > > index 6e713fc..ae8dc3f 100644 > > --- a/ovn/northd/automake.mk > > +++ b/ovn/northd/automake.mk > > @@ -1,6 +1,15 @@ > > # ovn-northd > > +if ENABLE_FT > > +CFLAGS += -g -finstrument-functions \ > > + `pkg-config --cflags glib-2.0` \ > > + `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt > > +endif > > + > > bin_PROGRAMS += ovn/northd/ovn-northd > > ovn_northd_ovn_northd_SOURCES = ovn/northd/ovn-northd.c > > +if ENABLE_FT > > +ovn_northd_ovn_northd_SOURCES += third-party/function_tracer.c > > +endif > > ovn_northd_ovn_northd_LDADD = \ > > ovn/lib/libovn.la \ > > ovsdb/libovsdb.la \ > > diff --git a/ovn/northd/ovn-northd.c b/ovn/northd/ovn-northd.c > > index d53fca9..6ffef96 100644 > > --- a/ovn/northd/ovn-northd.c > > +++ b/ovn/northd/ovn-northd.c > > @@ -42,6 +42,8 @@ > > > > VLOG_DEFINE_THIS_MODULE(ovn_northd); > > > > +static bool g_command_line_args_parsed = false; > > + > > static unixctl_cb_func ovn_northd_exit; > > > > struct northd_context { > > @@ -119,6 +121,12 @@ enum ovn_stage { > > #undef PIPELINE_STAGE > > }; > > > > +bool > > +is_command_line_args_parsed(void) > > +{ > > + return g_command_line_args_parsed; > > +} > > + > > /* Due to various hard-coded priorities need to implement ACLs, the > > * northbound database supports a smaller range of ACL priorities than > > * are available to logical flows. This value is added to an ACL > > @@ -2490,6 +2498,7 @@ parse_options(int argc OVS_UNUSED, char *argv[] > > OVS_UNUSED) > > } > > > > free(short_options); > > + g_command_line_args_parsed = true; > > } > > > > static void > > diff --git a/third-party/function_tracer.c b/third-party/function_tracer.c > > new file mode 100644 > > index 0000000..422fccd > > --- /dev/null > > +++ b/third-party/function_tracer.c > > @@ -0,0 +1,126 @@ > > +/* > > + * This file implements routines needed to log all function calls' > > + * entry and exit timestamps along with it's hex address. With > > + * python tool generate_ft_report.py, this log can be converted with > > + * symbol names for offline analysis. > > + */ > > + > > +#include <stdio.h> > > +#include <sys/types.h> > > +#include <unistd.h> > > +#include <time.h> > > +#include <sys/time.h> > > +#include <string.h> > > +#include "openvswitch/vlog.h" > > + > > +VLOG_DEFINE_THIS_MODULE(trace); > > + > > +#define LOG_FILE_NAME_LEN 256 > > +#define LOG_DIR_NAME_LEN 128 > > +#define LOG_FILENAME_PREFIX "func_trace" > > +#define CURRENT_LOG_LEVEL this_module.min_level > > + > > +/* File pointer for logging the trace output. */ > > +static FILE *log_fp; > > + > > +/* External functions used here */ > > +extern bool is_command_line_args_parsed(); > > + > > +/* Prototypes for the functions declared/used in this file. */ > > +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); > > +int __attribute__ ((no_instrument_function)) format_time(struct timeval > > *lt, > > + char *buf, > > + size_t size); > > + > > +void __attribute__ ((constructor,no_instrument_function)) > > +ft_begin(void) > > +{ > > + /* Nothing at this point, but needed */ > > +} > > + > > +void __attribute__ ((no_instrument_function)) > > +ft_log_open(void) > > +{ > > + char log_name[LOG_FILE_NAME_LEN]; > > + char dir_name[LOG_DIR_NAME_LEN]; > > + > > + vlog_directory(dir_name, LOG_DIR_NAME_LEN); > > + snprintf(log_name, LOG_FILE_NAME_LEN, "%s/%s_%d.log", > > + dir_name, LOG_FILENAME_PREFIX, getpid()); > > + if ((log_fp = fopen(log_name, "w")) == NULL) { > > + fprintf(stderr, "Failed to open output trace file: %s\n", > > log_name); > > + } > > +} > > + > > + > > +void __attribute__ ((destructor,no_instrument_function)) > > +ft_end(void) > > +{ > > + if (log_fp != NULL) { > > + fclose(log_fp); > > + } > > +} > > + > > +/* Gets the current timestamp into the input buffer in ascii format */ > > +int __attribute__ ((no_instrument_function)) > > +format_time(struct timeval *lt, char *buf, size_t size) > > +{ > > + struct tm gm_time; > > + int bytes_written = -1; > > + > > + gmtime_r(<->tv_sec,&gm_time); > > + bytes_written = strftime(buf, size, "%Y-%m-%dT%H:%M:%S", &gm_time); > > + if ((bytes_written > 0) && ((size_t) bytes_written < size)) { > > + int tmp = snprintf(buf + bytes_written, > > + size - (size_t) bytes_written, ".%06d", > > + (int) lt->tv_usec); > > + bytes_written = (tmp > 0) ? bytes_written + tmp : -1; > > + } > > + return bytes_written; > > +} > > + > > + > > +void __attribute__ ((no_instrument_function)) > > +ft(const char *direction, void *func, void *caller) > > +{ > > + char timestr[64]; > > + struct timeval ltime; > > + > > + if (log_fp == NULL && is_command_line_args_parsed()) { > > + ft_log_open(); > > + } > > + if ((!is_command_line_args_parsed()) || (log_fp == NULL)) { > > + return; > > + } > > + if (gettimeofday(<ime, NULL) != 0) { > > + return; > > + } > > + if (format_time(<ime, timestr, sizeof(timestr)) <= 0) { > > + return; > > + } > > + /* Trace only if log level is >= DEBUG */ > > + if (CURRENT_LOG_LEVEL >= VLL_DBG) { > > + fprintf(log_fp, "%s>%s>%p>%p\n", timestr, > > + direction, func, caller); > > + } > > + fflush(log_fp); > > +} > > + > > +void __attribute__ ((no_instrument_function)) > > +__cyg_profile_func_enter(void *func, void *caller) > > +{ > > + ft("entry", func, caller); > > +} > > + > > +void __attribute__ ((no_instrument_function)) > > +__cyg_profile_func_exit(void *func, void *caller) > > +{ > > + ft("exit", func, caller); > > +} > > diff --git a/third-party/generate_ft_report.py > > b/third-party/generate_ft_report.py > > new file mode 100644 > > index 0000000..7e49489 > > --- /dev/null > > +++ b/third-party/generate_ft_report.py > > @@ -0,0 +1,80 @@ > > +#!/usr/bin/env python > > +# Copyright (c) 2016 Red Hat, 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. > > +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, this 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 > > + """ > > + date_obj1 = datetime.strptime(time1, '%Y-%m-%dT%H:%M:%S.%f') > > + date_obj2 = datetime.strptime(time2, '%Y-%m-%dT%H:%M:%S.%f') > > + delta = date_obj2 - date_obj1 > > + return delta > > + > > +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 "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,exe) > > + update_and_print(tokens[0], tokens[1], tokens[2], > > + tokens[3], serial, exe) > > + > > +if __name__ == "__main__": > > + main() > > diff --git a/utilities/automake.mk b/utilities/automake.mk > > index 1cc66b6..747cb36 100644 > > --- a/utilities/automake.mk > > +++ b/utilities/automake.mk > > @@ -57,6 +57,7 @@ EXTRA_DIST += \ > > utilities/ovs-vlan-test.in \ > > utilities/ovs-vsctl-bashcomp.bash \ > > utilities/qemu-wrap.py \ > > + third-party/generate_ft_report.py \ > > utilities/checkpatch.py > > MAN_ROOTS += \ > > utilities/ovs-appctl.8.in \ > > diff --git a/vswitchd/automake.mk b/vswitchd/automake.mk > > index 8d7f3ea..bc4cd54 100644 > > --- a/vswitchd/automake.mk > > +++ b/vswitchd/automake.mk > > @@ -1,3 +1,8 @@ > > +if ENABLE_FT > > +CFLAGS += -g -finstrument-functions \ > > + `pkg-config --cflags glib-2.0` \ > > + `pkg-config --libs glib-2.0` -ldl -export-dynamic -lrt > > +endif > > sbin_PROGRAMS += vswitchd/ovs-vswitchd > > man_MANS += vswitchd/ovs-vswitchd.8 > > DISTCLEANFILES += \ > > @@ -11,6 +16,9 @@ vswitchd_ovs_vswitchd_SOURCES = \ > > vswitchd/system-stats.h \ > > vswitchd/xenserver.c \ > > vswitchd/xenserver.h > > +if ENABLE_FT > > +vswitchd_ovs_vswitchd_SOURCES += third-party/function_tracer.c > > +endif > > vswitchd_ovs_vswitchd_LDADD = \ > > ofproto/libofproto.la \ > > lib/libsflow.la \ > > diff --git a/vswitchd/ovs-vswitchd.c b/vswitchd/ovs-vswitchd.c > > index 72448bb..ba985fd 100644 > > --- a/vswitchd/ovs-vswitchd.c > > +++ b/vswitchd/ovs-vswitchd.c > > @@ -51,6 +51,7 @@ > > > > VLOG_DEFINE_THIS_MODULE(vswitchd); > > > > +static bool g_command_line_args_parsed = false; > > /* --mlockall: If set, locks all process memory into physical RAM, > > preventing > > * the kernel from paging any of its memory to disk. */ > > static bool want_mlockall; > > @@ -60,6 +61,12 @@ static unixctl_cb_func ovs_vswitchd_exit; > > static char *parse_options(int argc, char *argv[], char **unixctl_path); > > OVS_NO_RETURN static void usage(void); > > > > +bool > > +is_command_line_args_parsed(void) > > +{ > > + return g_command_line_args_parsed; > > +} > > + > > int > > main(int argc, char *argv[]) > > { > > @@ -240,6 +247,7 @@ parse_options(int argc, char *argv[], char > > **unixctl_pathp) > > VLOG_FATAL("at most one non-option argument accepted; " > > "use --help for usage"); > > } > > + g_command_line_args_parsed = true; > > } > > > > static void > > -- > > 1.9.1 > > > > _______________________________________________ > > dev mailing list > > dev@openvswitch.org > > http://openvswitch.org/mailman/listinfo/dev > > > _______________________________________________ > dev mailing list > dev@openvswitch.org > http://openvswitch.org/mailman/listinfo/dev _______________________________________________ dev mailing list dev@openvswitch.org http://openvswitch.org/mailman/listinfo/dev
