Ryan Moats/Omaha/IBM wrote on 07/25/2016 01:44:44 PM:
> From: Ryan Moats/Omaha/IBM > To: Nirapada Ghosh/San Jose/IBM@IBMUS > Cc: "Ben Pfaff" <b...@ovn.org>, dev@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@IBMUS > > Cc: "Ben Pfaff" <b...@ovn.org>, dev@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@IBMUS, "Ben Pfaff" <b...@ovn.org> > > Cc: dev@openvswitch.org > > Date: 07/24/2016 08:34 AM > > Subject: Re: [ovs-dev] [PATCH V13] Function tracer to trace all > function calls > > > > "dev" <dev-boun...@openvswitch.org> wrote on 07/08/2016 07:04:06 PM: > > > > > From: Nirapada Ghosh/San Jose/IBM@IBMUS > > > To: dev@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-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 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> > > > --- > > > > 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 _______________________________________________ dev mailing list dev@openvswitch.org http://openvswitch.org/mailman/listinfo/dev