| View Issue Details [ Jump to Notes ] | [ Print ] | ||||||||
| ID | Project | Category | View Status | Date Submitted | Last Update | ||||
| 0012381 | CMake | CTest | public | 2011-08-02 11:20 | 2016-06-10 14:31 | ||||
| Reporter | Sean McBride | ||||||||
| Assigned To | Kitware Robot | ||||||||
| Priority | high | Severity | major | Reproducibility | always | ||||
| Status | closed | Resolution | moved | ||||||
| Platform | OS | OS Version | |||||||
| Product Version | CMake 2.8.5 | ||||||||
| Target Version | Fixed in Version | ||||||||
| Summary | 0012381: ctest uses a lot of CPU time doing regular expressions, significantly slowing builds | ||||||||
| Description | Our 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? | ||||||||
| Tags | No tags attached. | ||||||||
| Attached Files |  CMake Instruments.png [^] (259,912 bytes) 2011-09-16 14:46
 tre.patch.tar.gz [^] (66,020 bytes) 2011-11-22 13:24 | ||||||||
| Relationships | |
| Relationships |
| Notes | |
|
(0027285) Bill Hoffman (manager) 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 (reporter) 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 (manager) 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 (reporter) 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 (reporter) 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 (manager) 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 (reporter) 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 (reporter) 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 (reporter) 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 (reporter) 2011-09-16 14:46 |
Attached is a screenshot showing Instruments.app and the hotspots it identifies. |
|
(0027849) Alexandru Ciobanu (reporter) 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 (reporter) 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 (manager) 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 (reporter) 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 (manager) 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 (manager) 2012-08-11 11:46 edited on: 2012-08-11 11:46 |
You can use "..." inside the Description field to get a monospaced font... |
|
(0034106) Brad King (manager) 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 (manager) 2013-10-11 16:25 edited on: 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 (manager) 2013-10-11 16:35 |
Oh, and the patch from 0012381:0027849 is still a good starting point for continued work. |
|
(0041880) Kitware Robot (administrator) 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. |
| Notes |
| Issue History | |||
| Date Modified | Username | Field | Change |
| 2011-08-02 11:20 | Sean McBride | New Issue | |
| 2011-08-29 12:53 | Bill Hoffman | Note Added: 0027285 | |
| 2011-08-29 13:12 | Sean McBride | Note Added: 0027287 | |
| 2011-08-29 13:23 | Bill Hoffman | Note Added: 0027289 | |
| 2011-08-29 16:13 | Sean McBride | Note Added: 0027297 | |
| 2011-08-30 17:20 | Bradley Lowekamp | Note Added: 0027305 | |
| 2011-08-30 17:49 | Bill Hoffman | Note Added: 0027306 | |
| 2011-08-30 17:55 | Bradley Lowekamp | Note Added: 0027307 | |
| 2011-08-30 17:56 | Sean McBride | Note Added: 0027308 | |
| 2011-09-09 06:10 | Pere Mato | Note Added: 0027396 | |
| 2011-09-16 14:46 | Sean McBride | File Added: CMake Instruments.png | |
| 2011-09-16 14:46 | Sean McBride | Note Added: 0027438 | |
| 2011-10-21 14:22 | David Cole | Target Version | => CMake 2.8.7 |
| 2011-11-22 13:24 | Alexandru Ciobanu | File Added: tre.patch.tar.gz | |
| 2011-11-22 13:27 | Alexandru Ciobanu | Note Added: 0027849 | |
| 2011-11-22 17:01 | Alexandru Ciobanu | Note Added: 0027850 | |
| 2011-11-28 08:38 | Brad King | Note Added: 0027855 | |
| 2011-11-29 14:22 | Alexandru Ciobanu | Note Added: 0027872 | |
| 2011-11-29 14:28 | Alexandru Ciobanu | Note Edited: 0027872 | |
| 2011-12-13 19:34 | David Cole | Note Added: 0027974 | |
| 2011-12-13 19:34 | David Cole | Target Version | CMake 2.8.7 => |
| 2012-08-11 11:46 | David Cole | Note Added: 0030321 | |
| 2012-08-11 11:46 | David Cole | Description Updated | |
| 2012-08-11 11:46 | David Cole | Note Edited: 0030321 | |
| 2013-10-11 16:22 | Brad King | Note Added: 0034106 | |
| 2013-10-11 16:25 | Brad King | Note Added: 0034107 | |
| 2013-10-11 16:25 | Brad King | Note Edited: 0034107 | |
| 2013-10-11 16:35 | Brad King | Note Added: 0034108 | |
| 2016-06-10 14:28 | Kitware Robot | Note Added: 0041880 | |
| 2016-06-10 14:28 | Kitware Robot | Status | new => resolved |
| 2016-06-10 14:28 | Kitware Robot | Resolution | open => moved |
| 2016-06-10 14:28 | Kitware Robot | Assigned To | => Kitware Robot |
| 2016-06-10 14:31 | Kitware Robot | Status | resolved => closed |
| Issue History |
| Copyright © 2000 - 2018 MantisBT Team |