[CMake] cmake script profiler

[Alexander Neundorf]

On Tuesday 23 April 2013, Bill Hoffman wrote:
> On 4/23/2013 3:50 PM, Volo Zyko wrote:
> > Hi all,
> > 
> > We have a rather big project and use cmake for building it. At some
> > point our cmake scripts became very slow (around 4 minutes for single
> > cmake run). We are thinking now how to speed up it. Searching the web
> > and this list didn't give any results. It looks like there is no such
> > thing as profiler for cmake scripts. Am I right?
> > 
> > What about adding such capability to cmake? It looks like cmake's trace
> > provides enough info for time profiling, the only thing that it lacks is
> > a time stamp. Below is a small patch that adds time stamp and nesting
> > level (to simplify building a stack trace) to each trace line. Would it
> > be possible to integrate this change to the main line or are there
> > better options for time profiling of cmake?
> 
> That's funny.  I was just playing around with adding a profile option.
> My approach was to sum up all the time spent in each function.  It does
> not have a call stack but, should give you an idea of where it is
> spending the bulk of the time.   I suppose you could post process the
> output of a trace with your change, but that would be more work.
> 
> An example of my output on the ParaView project:
> 
> 4.881 export
> 4.97701 vtk_wrap_python
> 5.15999 vtk_module_export
> 5.45701 VTK_WRAP_ClientServer
> 5.817 QT4_GET_MOC_FLAGS
> 6.159 vtk_module_impl
> 6.38601 pv_pre_wrap_vtk_mod_cs
> 7.08994 if
> 7.23499 vtk_add_python_wrapping
> 7.46001 QT4_WRAP_CPP
> 7.71494 configure_file
> 8.59399 vtk_module_config
> 8.904 pv_process_plugins
> 8.987 vtk_add_cs_wrapping
> 9.64503 set
> 11.654 try_compile
> 12.748 vtk_module_third_party
> 17.007 vtk_module_library
> 37.773 _vtk_module_config_recurse
> 112.788 include
> 158.092 add_subdirectory

When looking at this I wouldn't know immediately where to start when trying to 
make it faster, probably _vtk_module_config_recurse().
set() is probably there because it is called really often.
I would assume that if() is called significantly less often, so maybe this 
could use some optimization.
Can you produce those numbers also for processed files, instead of commands ?


Without measuring anything, there is something else I thought about: there are 
now a bunch of useful, quite complex macros coming with cmake, which are used 
quite often: e.g. ExternalProject, cmake_parse_arguments(), 
find_package_handle_standard_args().
Every find-module or every macro which wants to use them, needs to include() 
them. I haven't measured anything, but maybe reading and parsing those 
relatively big files multiple times also consumes some time.
This could be stripped off if cmake would include some modules by default, so 
that as a user I could simply use them like built-in commands, without the 
need to include() them again.

> Also, thinking of adding some stats to number of times a variable is set
> and how many variables are used.

Hopefully this won't make set() take more time ;-)

Inside cmake, arguments are handed over quite often as const char*, and then 
converted again to std::string. Everytime this is done the end of the string 
has to be searched, memory allocated and copied. Again, I haven't measured 
(but I can remember vaguely from some profiling a few years ago), maybe things 
would be faster if in more places const std::string& would be used internally, 
this would get rid of quite some strlen() calls.

Alex