MantisBT - CMake
View Issue Details
IDProjectCategoryView StatusDate SubmittedLast Update
0012381CMakeCTestpublic2011-08-02 11:202016-06-10 14:31
ReporterSean McBride 
Assigned ToKitware Robot 
PriorityhighSeveritymajorReproducibilityalways
StatusclosedResolutionmoved 
PlatformOSOS Version
Product VersionCMake 2.8.5 
Target VersionFixed in Version 
Summary0012381: ctest uses a lot of CPU time doing regular expressions, significantly slowing builds
DescriptionOur developers normally do everything in Xcode itself, but our internal nightly builds and dashboard use a combination of the command line xcodebuild and ctest.

The latter are literally 10x slower than the former.

Profiling reveals much CPU time is spent like so (best viewed with monospaced font):

main
 cmCTest::Run(std::vector<std::basic_string<char, std::char_traits<char>, std::allocator<char> 
>, std::allocator<std::basic_string<char, std::char_traits<char>, std::allocator<char> 
> > >&, std::basic_string<char, std::char_traits<char>, std::allocator<char> 
>*)
  cmCTestScriptHandler::ProcessHandler()
   cmCTestScriptHandler::RunConfigurationScript(std::basic_string<char, std::char_traits<char>, 
std::allocator<char> > const&, bool)
    cmCTestScriptHandler::ReadInScript(std::basic_string<char, std::char_traits<char>, std::allocator<char> 
> const&)
     cmMakefile::ReadListFile(char const*, char const*, std::basic_string<char, std::char_traits<char>, 
std::allocator<char> >*, bool)
      cmMakefile::ExecuteCommand(cmListFileFunction const&, cmExecutionStatus&)
       cmCommand::InvokeInitialPass(std::vector<cmListFileArgument, std::allocator<cmListFileArgument> 
> const&, cmExecutionStatus&)
        cmCTestBuildCommand::InitialPass(std::vector<std::basic_string<char, std::char_traits<char>, 
std::allocator<char> >, std::allocator<std::basic_string<char, std::char_traits<char>, 
std::allocator<char> > > > const&, cmExecutionStatus&)
         cmCTestHandlerCommand::InitialPass(std::vector<std::basic_string<char, std::char_traits<char>, 
std::allocator<char> >, std::allocator<std::basic_string<char, std::char_traits<char>, 
std::allocator<char> > > > const&, cmExecutionStatus&)
          cmCTestBuildHandler::ProcessHandler()
           cmCTestBuildHandler::RunMakeCommand(char const*, int*, char const*, int, std::basic_ofstream<char, 
std::char_traits<char> >&)
            cmCTestBuildHandler::ProcessBuffer(char const*, int, unsigned long&, unsigned long, std::basic_ofstream<char, 
std::char_traits<char> >&, std::deque<char, std::allocator<char> >*)
             cmCTestBuildHandler::ProcessSingleLine(char const*)
              cmsys::RegularExpression::find(char const*)
               cmsys::regtry(char const*, char const**, char const**, char const*)
                cmsys::regmatch(char const*)


Our hypothesis is that all the output generated by xcodebuild takes forever to grep for errors/warnings.

It would be nice if this could be optimized. It appears to be single threaded currently, perhaps parallelization is an option?
Steps To Reproduce
Additional Information
TagsNo tags attached.
Relationships
Attached Filespng CMake Instruments.png (259,912) 2011-09-16 14:46
https://public.kitware.com/Bug/file/4053/CMake%20Instruments.png
png

gz tre.patch.tar.gz (66,020) 2011-11-22 13:24
https://public.kitware.com/Bug/file/4122/tre.patch.tar.gz
Issue History
Date ModifiedUsernameFieldChange
2011-08-02 11:20Sean McBrideNew Issue
2011-08-29 12:53Bill HoffmanNote Added: 0027285
2011-08-29 13:12Sean McBrideNote Added: 0027287
2011-08-29 13:23Bill HoffmanNote Added: 0027289
2011-08-29 16:13Sean McBrideNote Added: 0027297
2011-08-30 17:20Bradley LowekampNote Added: 0027305
2011-08-30 17:49Bill HoffmanNote Added: 0027306
2011-08-30 17:55Bradley LowekampNote Added: 0027307
2011-08-30 17:56Sean McBrideNote Added: 0027308
2011-09-09 06:10Pere MatoNote Added: 0027396
2011-09-16 14:46Sean McBrideFile Added: CMake Instruments.png
2011-09-16 14:46Sean McBrideNote Added: 0027438
2011-10-21 14:22David ColeTarget Version => CMake 2.8.7
2011-11-22 13:24Alexandru CiobanuFile Added: tre.patch.tar.gz
2011-11-22 13:27Alexandru CiobanuNote Added: 0027849
2011-11-22 17:01Alexandru CiobanuNote Added: 0027850
2011-11-28 08:38Brad KingNote Added: 0027855
2011-11-29 14:22Alexandru CiobanuNote Added: 0027872
2011-11-29 14:28Alexandru CiobanuNote Edited: 0027872bug_revision_view_page.php?bugnote_id=27872#r459
2011-12-13 19:34David ColeNote Added: 0027974
2011-12-13 19:34David ColeTarget VersionCMake 2.8.7 =>
2012-08-11 11:46David ColeNote Added: 0030321
2012-08-11 11:46David ColeDescription Updatedbug_revision_view_page.php?rev_id=764#r764
2012-08-11 11:46David ColeNote Edited: 0030321bug_revision_view_page.php?bugnote_id=30321#r766
2013-10-11 16:22Brad KingNote Added: 0034106
2013-10-11 16:25Brad KingNote Added: 0034107
2013-10-11 16:25Brad KingNote Edited: 0034107bug_revision_view_page.php?bugnote_id=34107#r1281
2013-10-11 16:35Brad KingNote Added: 0034108
2016-06-10 14:28Kitware RobotNote Added: 0041880
2016-06-10 14:28Kitware RobotStatusnew => resolved
2016-06-10 14:28Kitware RobotResolutionopen => moved
2016-06-10 14:28Kitware RobotAssigned To => Kitware Robot
2016-06-10 14:31Kitware RobotStatusresolved => closed

Notes
(0027285)
Bill Hoffman   
2011-08-29 12:53   
Not sure we can go threaded for this. I guess Xcode just has tons and tons of output. It dumps all the env for each run. We even do some pre-filtering in the xcodebuild calls. Did this just become an issue? I am wondering if something changed in ctest/cmake to make things worst.
(0027287)
Sean McBride   
2011-08-29 13:12   
Bill, I don't think it's a regression. It wasn't something we bothered investigating until a few months ago, and I didn't get around to creating this bug until weeks after that.

Indeed, parallelization is not always a feasible solution, it was just a random thought.

But it is a whole order of magnitude slower than xcodebuild alone, which surely could be improved upon. If it was only twice as slow I would be elated. :)
(0027289)
Bill Hoffman   
2011-08-29 13:23   
The real trouble is that xcodebuild is so crazy verbose. One solution would be to limit more output in cmakexbuild.cxx.

Currently it does this:
  // if the bug is hit, no more output should be generated
    // because it may contain bogus errors
    // also remove all output with setenv in it to tone down
    // the verbosity of xcodebuild
    if(!hitbug && (line.find("setenv") == line.npos))

I guess most projects do not notice this because they use the default of 50 warnings, and after 50 it stops looking.
(0027297)
Sean McBride   
2011-08-29 16:13   
Just to be clear, our internal dashboard is very green, and thus the enormous slowdown (that this bug is about) is not because of many warnings being emitted.

If one does have many warnings, this bug exacerbates the problem. But the problem is there with no warnings too.

We use ITK, and lazily used a recursive include statement (in our Xcode project) to get access to all its headers. Xcode expanded all the paths and output them in the xcodebuild output. When we trimmed our include paths down to only the actual subset of ITK we used, it improved build time drastically.

Profiling shows time spent doing regexes. I think it's simply a matter of having lots of output to run those regexes over.
(0027305)
Bradley Lowekamp   
2011-08-30 17:20   
A quick look at cmCTestBuildHandler::ProcessSingleLine(char const*), make me wonder if it would be possible to combine all the regex into one. This would reduce the number of times that it is needed to traverse the data.

I don't know if the error and warning regex include the CTestCustom customizations to ignore, or what the number of regex that are there, but it's a thought.
(0027306)
Bill Hoffman   
2011-08-30 17:49   
Brad, can you just comment out the regex stuff altogether and see if it is faster? That would prove it was the regex that was causing the trouble. It might just be the reading of every line that does it.
(0027307)
Bradley Lowekamp   
2011-08-30 17:55   
Bill or Sean,

Do you have a suggested better way to test this? Running the 12hr ITK build in not an effective way to test hypothesis.
(0027308)
Sean McBride   
2011-08-30 17:56   
Bradley, sure, just use CMake to build CMake. :) Much faster than ITK, but the problem is still perceptible with Xcode vs Unix Makefiles generators.
(0027396)
Pere Mato   
2011-09-09 06:10   
Hi. I am having the same problem of ctest_build() basically struck in cmCTestBuildHandler::ProcessSingleLine(char const*) on a Linux system using plain make with no errors or warnings being produced. The problem is that the link command of one of the libraries is 120K bytes long and is always output. I guess a way to avoid the problem would be to disable the printing of the link command. The make option -s does not help in this case. Do you have any over suggestion?
(0027438)
Sean McBride   
2011-09-16 14:46   
Attached is a screenshot showing Instruments.app and the hotspots it identifies.
(0027849)
Alexandru Ciobanu   
2011-11-22 13:27   
I am attaching a patch (tre.patch.tar.gz) that solves the problem by using the TRE regexp library.

Here's what the patch does:
  - adds Utilities/cmtre/ and all the necessary files to compile it
  - adds cmFastRegularExpression.{h,cxx} files that use TRE for regex
  - replace all uses of RepgularExpression with cmFastRegularExpression in files in Source/
  - files in Source/kwsys/ are unchanged

The only tests that don't pass are the ones that try to compile CMake but are unaware of TRE:
  - Bootstrap
  - complex
  - complexOne

This builds on Mac OS X, and I expect it to build on other UNIX-like environments, but I don't know about other platforms.

I understand that more work needs to be done to integrate this properly. Here I want to make sure that the approach is correct.
(0027850)
Alexandru Ciobanu   
2011-11-22 17:01   
I forgot to add that the patch is based on the following commit:

   commit 5675ec5e493e01e10d9ad8d8b60eac62033f31c2
   Author: KWSys Robot <kwrobot@kitware.com>
   Date: Wed Nov 9 00:01:05 2011 -0500

       KWSys Nightly Date Stamp
(0027855)
Brad King   
2011-11-28 08:38   
The current proposal after discussion on cmake-developers last week is here:

  http://www.cmake.org/pipermail/cmake-developers/2011-November/002642.html [^]
(0027872)
Alexandru Ciobanu   
2011-11-29 14:22   
(edited on: 2011-11-29 14:28)
We found a workaround for the problem, that does not require source code modifications.

In our case we are invoking the build through CTest in the following way:
    $ ctest -S CTestScript.cmake

where the content of the script file is something as simple as this:
    # ...
    SET (CTEST_BUILD_COMMAND "/bin/sh xcodeScript.sh")
    # ...
    CTEST_START()
    CTEST_BUILD()
    CTEST_SUBMIT()

The xcodeScript.sh is trivial:
    cd somedir
    /usr/bin/xcodebuild -project BS.xcodeproj -target BS -configuration Debug clean build

This is very slow because CTest is parsing each line of build command output multiple times. It is especially slow when there are long lines in the output. Xcode generates long lines when invoking the compiler; they look something like this:
    /Developer/usr/bin/clang ...(lots of include paths, options, etc.)... -o someStuff.o

So we filtered those out in xcodeScript.sh:
    cd somedir
    /usr/bin/xcodebuild -project BS.xcodeproj -target BS -configuration Debug clean build | grep -v "^ /Developer/usr/bin"

This reduces our build time by a factor of 10.

The only drawback would be that when an error happens, the compile command that triggered it will be filtered out of the logs, but it is bearable because Xcode prints other lines that say which file is compiled.
(0027974)
David Cole   
2011-12-13 19:34   
Unset target version field; too late for a fix to go into 2.8.7; deferred until a future version.

(See previous notes for a workaround...)
(0030321)
David Cole   
2012-08-11 11:46   
You can use "
 ...
" inside the Description field to get a monospaced font...
(0034106)
Brad King   
2013-10-11 16:22   
Gmane link to cmake-developers discussion:

 http://thread.gmane.org/gmane.comp.programming.tools.cmake.devel/2205 [^]
(0034107)
Brad King   
2013-10-11 16:25   
The (?#TRE) prefix approach to switch to the TRE implementation was proposed here:

 http://thread.gmane.org/gmane.comp.programming.tools.cmake.devel/2331/focus=2332 [^]

IIRC that is where this was last left off.
(0034108)
Brad King   
2013-10-11 16:35   
Oh, and the patch from 0012381:0027849 is still a good starting point for continued work.
(0041880)
Kitware Robot   
2016-06-10 14:28   
Resolving issue as `moved`.

This issue tracker is no longer used. Further discussion of this issue may take place in the current CMake Issues page linked in the banner at the top of this page.