[ovs-dev] [PATCH V5] Function tracer to trace all function calls
Daniele Di Proietto
diproiettod at ovn.org
Wed Jun 15 18:06:37 UTC 2016
Hi Hui,
I've never used oprofile, from what I read it's pretty similar to perf.
To compile OVS for profiling or debugging I use the ovs-dev.py script,
which adds "-fno-omit-frame-pointer" to CFLAGS. It would be equivalent to
calling configure like this:
./configure CFLAGS="-O2 -g -fno-omit-frame-pointer"
Then I launch perf for 5 seconds on the nortd process like this:
perf record -p `pidof ovn-northd` sleep 5
This generates the perf.data file which can be inspected with `perf report
-i perf.data` to generate an output like the following:
24.24% ovn-northd libc-2.19.so [.] vfprintf
9.83% ovn-northd libc-2.19.so [.] _IO_default_xsputn
5.62% ovn-northd ovn-northd [.] hash_bytes
4.92% ovn-northd ovn-northd [.] ovsdb_idl_next_row
4.84% ovn-northd libc-2.19.so [.] __strcmp_sse2_unaligned
4.40% ovn-northd ovn-northd [.] build_lflows
3.90% ovn-northd libc-2.19.so [.] _int_malloc
3.50% ovn-northd libc-2.19.so [.] __strchrnul
3.46% ovn-northd libc-2.19.so [.] strlen
2.93% ovn-northd ovn-northd [.] ovs_scan__
2.15% ovn-northd ovn-northd [.] ovsdb_datum_compare_3way
2.12% ovn-northd libc-2.19.so [.] _IO_strn_overflow
2.12% ovn-northd libc-2.19.so [.] malloc_consolidate
2.02% ovn-northd ovn-northd [.] scan_int
1.86% ovn-northd libc-2.19.so [.] _IO_padn
1.40% ovn-northd ovn-northd [.] main
1.24% ovn-northd ovn-northd [.] hexits_value
1.16% ovn-northd libc-2.19.so [.] _int_free
0.87% ovn-northd libc-2.19.so [.] malloc
0.86% ovn-northd ovn-northd [.] ovn_lflow_add
0.86% ovn-northd libc-2.19.so [.] read_int
0.85% ovn-northd libc-2.19.so [.] _itoa_word
0.79% ovn-northd ovn-northd [.] resize
0.75% ovn-northd libc-2.19.so [.] _IO_vsnprintf
0.73% ovn-northd ovn-northd [.] ds_put_format_valist
0.72% ovn-northd ovn-northd [.] json_serialize_string
0.71% ovn-northd libc-2.19.so [.] _IO_str_init_static_internal
0.68% ovn-northd libc-2.19.so [.] _IO_old_init
0.65% ovn-northd ovn-northd [.] build_port_security_l2
0.52% ovn-northd libc-2.19.so [.] free
0.50% ovn-northd ovn-northd [.] xstrdup
By adding the -g option while recording, perf tries to reassemble the
current stack trace and group function accordingly
perf record -g -p `pidof ovn-northd` sleep 5
+ 40.50% 0.00% ovn-northd libc-2.19.so [.] __libc_start_main
+ 40.07% 1.39% ovn-northd ovn-northd [.] main
+ 36.63% 0.86% ovn-northd libc-2.19.so [.] _IO_vsnprintf
+ 26.95% 26.94% ovn-northd libc-2.19.so [.] vfprintf
+ 26.61% 4.26% ovn-northd ovn-northd [.] build_lflows
+ 12.46% 12.44% ovn-northd libc-2.19.so [.] _IO_default_xsputn
+ 11.34% 0.00% ovn-northd [unknown] [.] 0x702d30777322203d
+ 6.88% 0.00% ovn-northd [unknown] [.] 0x262620646e202626
+ 5.12% 5.10% ovn-northd ovn-northd [.] hash_bytes
+ 4.24% 0.00% ovn-northd [unknown] [.] 0x002b26db3bd7b800
+ 4.15% 0.66% ovn-northd ovn-northd [.] ovn_lflow_add
+ 3.80% 3.74% ovn-northd libc-2.19.so [.] _int_malloc
+ 3.76% 3.74% ovn-northd libc-2.19.so [.] strlen
+ 3.55% 0.26% ovn-northd ovn-northd [.]
ovn_port_update_sbrec
+ 3.34% 0.11% ovn-northd ovn-northd [.]
ovn_datapath_from_sbrec
+ 3.27% 3.25% ovn-northd libc-2.19.so [.] __strchrnul
+ 3.23% 3.23% ovn-northd ovn-northd [.] ovsdb_idl_next_row
+ 3.21% 0.11% ovn-northd ovn-northd [.] smap_get_uuid
+ 3.13% 0.19% ovn-northd ovn-northd [.]
extract_lport_addresses
+ 3.10% 3.07% ovn-northd libc-2.19.so [.]
__strcmp_sse2_unaligned
+ 3.00% 0.00% ovn-northd [unknown] [.] 0x30303a3030203d3d
+ 2.93% 0.03% ovn-northd ovn-northd [.] ovs_scan_len
+ 2.77% 2.77% ovn-northd ovn-northd [.] ovs_scan__
+ 2.44% 2.42% ovn-northd libc-2.19.so [.] _IO_strn_overflow
+ 2.41% 0.31% ovn-northd ovn-northd [.]
ovsdb_idl_txn_write__
+ 2.38% 0.35% ovn-northd ovn-northd [.]
build_port_security_l2
+ 2.33% 2.33% ovn-northd ovn-northd [.] scan_int
+ 2.27% 0.00% ovn-northd ovn-northd [.]
eth_addr_from_string
+ 2.25% 0.08% ovn-northd ovn-northd [.] ovs_scan
+ 2.05% 0.04% ovn-northd ovn-northd [.] ovsdb_datum_equals
+ 1.95% 1.95% ovn-northd libc-2.19.so [.] malloc_consolidate
+ 1.95% 0.02% ovn-northd ovn-northd [.]
build_port_security_ip
+ 1.80% 1.80% ovn-northd libc-2.19.so [.] _IO_padn
+ 1.73% 0.10% ovn-northd ovn-northd [.] ds_put_format
+ 1.69% 1.69% ovn-northd libc-2.19.so [.] _int_free
+ 1.67% 0.12% ovn-northd ovn-northd [.] uuid_from_string
+ 1.56% 1.56% ovn-northd ovn-northd [.]
ovsdb_datum_compare_3way
+ 1.51% 0.00% ovn-northd [unknown] [.] 0x2b26db3bd7b80000
+ 1.42% 1.06% ovn-northd ovn-northd [.]
ds_put_format_valist
+ 1.39% 0.00% ovn-northd [unknown] [.] 0x3030303030303030
+ 1.39% 1.39% ovn-northd ovn-northd [.] hexits_value
+ 1.39% 0.21% ovn-northd ovn-northd [.]
sbrec_port_binding_set_mac
+ 1.35% 1.35% ovn-northd libc-2.19.so [.] malloc
+ 1.33% 0.00% ovn-northd [unknown] [.] 0000000000000000
+ 1.29% 0.06% ovn-northd ovn-northd [.] ovn_port_create
You can expand each "+" to understand who calls the function. It's not
100% reliable (it's a sampling profiler after all).
It's also possible to "annotate" each function to show where the samples
are taken with an assembly instruction level granularity.
I guess this process works to optimize high CPU usage if your functions are
executed over and over in a loop (for example, in OVS-DPDK, we call
miniflow_extract for each packet).
That said, I don't know how much of this is applicable to ovn-northd, where
the input varies highly.
In this example I run in parallel a for loop with ovn-nbctl invocation that
constantly change the database, but that's probably a totally unrealistic
use case. I have no idea if it's worth doing this kind of
micro-optimization for a distributed system like OVN. Some might be worth,
like commit 76adea871d0d("lib/util.c: Optimise bitwise_rscan.")
Again, I just wanted to share my experience about profiling the datapath.
This looks like a different problem and it probably requires other tools.
Thanks,
Daniele
2016-06-14 22:02 GMT-07:00 Hui Kang <kangh at us.ibm.com>:
> 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 <diproiettod at ovn.org>
> > To: Nirapada Ghosh/San Jose/IBM at IBMUS
> > Cc: "dev at openvswitch.org" <dev at 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-bounces at 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 <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 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 <nghosh at 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 at openvswitch.org
> > > http://openvswitch.org/mailman/listinfo/dev
> > >
> > _______________________________________________
> > dev mailing list
> > dev at openvswitch.org
> > http://openvswitch.org/mailman/listinfo/dev
>
>
More information about the dev
mailing list