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

[Nirapada Ghosh]

Ryan Moats/Omaha/IBM wrote on 07/25/2016 01:44:44 PM:

> From: Ryan Moats/Omaha/IBM
> To: Nirapada Ghosh/San Jose/IBM at IBMUS
> Cc: "Ben Pfaff" <blp at ovn.org>, dev at openvswitch.org
> Date: 07/25/2016 01:44 PM
> Subject: Re: [ovs-dev] [PATCH V13] Function tracer to trace all function
calls
>
> 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

That can be done. I was thinking you are referring to the entry/exit calls
which are happening even when logging was not enabled [nothing is being
logged]. Will work on the next version. Thanks much again,

Nirapada