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

Ryan Moats rmoats at us.ibm.com
Mon Jul 25 20:44:44 UTC 2016


Nirapada Ghosh/San Jose/IBM wrote on 07/25/2016 03:32:29 PM:

> From: Nirapada Ghosh/San Jose/IBM
> To: Ryan Moats/Omaha/IBM at IBMUS
> Cc: "Ben Pfaff" <blp at ovn.org>, dev at openvswitch.org
> Date: 07/25/2016 03:32 PM
> Subject: Re: [ovs-dev] [PATCH V13] Function tracer to trace all function
calls
>
> Hi Ryan,
>
> Thanks for your detailed review.
>
> I will be happy to implement your suggestions but I think your
> suggestions [first two comments] assume that I can control when the
> instrumentation is started [ft_begin() is called]. Unfortunately,
> this constructor is called by C compiler even before main() is
> invoked. So, when the code is compiled with the -finstrument-functions
> flag, the code/functions have been already instrumented with the
> entry/exit hooks in place and call to constructor [ft_begin] in
> place. Only thing we could control at runtime is -- when to log
> [from entry/exit routines].  So, I do not think we can control these
> entry/exit calls in it's bare minimal form [just check a flag and do
> nothing] when the code is compiled with that option. That's what I
> was trying to do with my patch. I would love to hear your thoughts
> again on this. I might be missing something here, please let me know.
>
> In regards to your other comments:
>
> Yes, I agree.  The way log file name is constructed and timestamps
> are calculated can be made much simpler as you mentioned, will work
> on those ASAP.
>
> Regards,
> Nirapada
>
> From: Ryan Moats/Omaha/IBM
> To: Nirapada Ghosh/San Jose/IBM at IBMUS, "Ben Pfaff" <blp at ovn.org>
> Cc: dev at openvswitch.org
> Date: 07/24/2016 08:34 AM
> Subject: Re: [ovs-dev] [PATCH V13] Function tracer to trace all function
calls
>
> "dev" <dev-bounces at openvswitch.org> wrote on 07/08/2016 07:04:06 PM:
>
> > From: Nirapada Ghosh/San Jose/IBM at IBMUS
> > To: dev at openvswitch.org
> > Date: 07/08/2016 07:04 PM
> > Subject: [ovs-dev] [PATCH V13] Function tracer to trace all function
calls
> > Sent by: "dev" <dev-bounces at openvswitch.org>
> >
> > 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 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>
> > ---
>
> Rather than go through line by line for style, I'm going to
> review the approach this patch takes.  One of my personal
> mantras about instrumentation is that the implementation
> has be really clean and minimalist, so as to not impact
> performance when it isn't being used.  Given that mantra,
> there is (IMHO) way too much calculation going on in this
> patch set:
>
> - Rather than calculate a log directory to use in determining
>   the output filename for holding instrumentation information,
>   simply supply that filename via the command line or
>   ovs-appctl and use that as an additional check before
>   logging instrumentation info.  This would allow running
>   code that is exhibiting odd behavior to be placed into
>   instrumentation mode in-sitsu, rather than requiring a
>   restart and then waiting for the same situation to occur.
> - Rather than asking the instrumentation code to search for
>   a magic symbol to see when to start, just have daemonize_start
>   signal the instrumentation code via ft_begin() as its last
>   instruction.  Note that this implies instrumenting more that
>   this patch does, but since this patch doesn't instrument
>   ovsdb-server, I view it as incomplete anyway.
> - Once ft_begin is used for signalling to start tracing, the
>   code to check and open the instrumentation file can move
>   from __cyg_profile_func_enter and __cyg_profile_func_exit
>   calls to where ft_begin and changes to ovs-appctl would
>   invoke it.
> - There is already a built in function to get the wall clock
>   time in milliseconds (time_wall_msec).  I don't see a
>   compelling reason not to decorate that routine to not be
>   instrumented (to avoid an infinite recursion) and use that
>   rather than making a separate system to get the current time.
> - I also don't see a compelling reason to include time formatting
>   before logging instrumentation information.  That formatting
>   would just have to be undone during postprocessing, so using
>   the raw millisecond time looks to be simpler all the way
>   around.
> - I expect that the above changes will require changes to
>   the new python code, but I've not dug into that for this review.
>
> Lastly (and this is more a question of location than function)
> the more I worked with this, the more I found myself thinking "maybe
> this really should live in the vlog module" - it feels like it
> wants to live there, as it is rather similar in functionality to
> what is already there.  I admit that I haven't tried out that
> idea to see if it would improve the code structure, but I
> think its worth considering.
>
> Ben, if you want to take a deeper look, feel free - I plan on
> marking the patch as "Changes Requested" in patchworks once this
> message shows up in the review change there.
>
> Ryan

In the future, please don't top post...

If ft_begin is invoked the way you say it is, then please change
the comment to explain that fact - what is there didn't make that
clear to me at all.

That being said, I don't see what difference it makes.  If I can't
have the boolean set in ft_begin (i.e. if that causes the boolean to
be set immediately), then I define a new method that sets it and
call that from daemonize_start - the point is to
avoid having to dig through symbols for a magic string...

Ryan




More information about the dev mailing list