Community
Participate
Working Groups
Build Identifier: I20100520-1744 Our project has a legacy subsystem when a couple of header files contain many (> 10000) auto-generated static function declarations, e.g. static int func(); I realize this is bad code, but there is nothing we can do about it in the short term. Whenever a source file includes such a header (and does not provide an implementation for each such function) GCC produces a warning similar to the following: foo.h.h:3574: warning: 'int func()' declared 'static' but never defined So there may be over 10000 warnings per file. When a build is performed from a KDE Konsole or Gnome terminal, those warnings take just a few seconds to be displayed. However, when a build is performed from Eclipse CDT, build console takes well over 10 minutes to display these warnings and almost universally dies at the end with a broken pipe error. I've tried increasing the build console buffer size to 100000 lines, but that makes no difference. Reproducible: Always
You provided eclipse version but what CDT version are you using? (Window->About->[Installation details]) Could you try most recent CDT build and tell if it got worse with introduction of build logging? I concur that console sluggishness is a problem which should be looked into. Regardless, you could use some workarounds. One is to *decrease* buffer size. Another one, which I would recommend, is to create an error parser where you "Ignore" most offending patterns (in Preferences) and put it as the first one in project properties.
(In reply to comment #0) > However, when a build is performed from Eclipse CDT, build console takes well > over 10 minutes to display these warnings and almost universally dies at the end > with a broken pipe error. Do you have any related exception in the log? There is also bug 311691 having broken pipe problem.
Hi Andrew, here is the CDT version information (it's the RC2 candidate build): Version: 7.0.0.201005211239 Build id: 201005211239 I'll check the Eclipse log next time I get the broken pipe error.
(In reply to comment #3) > here is the CDT version information (it's the RC2 candidate build): OK, it got the logging feature then. You can disable it in project properties. Please report what difference each workaround does make.
Defining custom error parsers speeds up the display of warnings by a factor of 4. However, the broken pipe error remains. Limiting build console to 500 lines make very little difference. When the broken pipe error occurs, there are no exceptions in the standard Eclipse log in .metadata/.log. The eclipse build log in .metadata/.plugins/org.eclipse.cdt.ui/<project>.build.log ends with the following (/home/vadymk/bin/runmake is a simple shell wrapper that passes DEBUG or RELEASE configuration variables to make, invokes make, and tee's the make output to a file): foo.h:2540: warning: ‘func’ declared ‘static’ but never defined tee: standard output: Broken pipe tee: write error /home/vadymk/bin/runmake: line 18: echo: write error: Broken pipe /home/vadymk/bin/runmake: line 39: echo: write error: Broken pipe
Disabling build logging in project properties makes no noticeable difference in performance.
Thanks for reporting. It confirms that we need to look at BuildConsolePartitioner to optimize.
A user called me as they couldn't cancel a build. I had a look and there was no make running. However the console continued to fill up. It turned out the build had ended many minutes previously but the console was 'catching-up'. The console seems to be performing very badly since the highlighting was introduced.
Created attachment 188168 [details] test with many #warnings This is astonishing. A file with 2000 warnings (think of a broken header in a large project) takes: time gcc hw.c real 0m0.092s user 0m0.023s sys 0m0.029s In Eclipse: Timing around the core build itself shows 9s: Wed Feb 02 17:02:27 GMT 2011 - [Worker-12] Top-level build-start of: hw; [], INCREMENTAL_BUILD Wed Feb 02 17:02:27 GMT 2011 - [Worker-12] Invoking (FULL_BUILD) on builder: CommonBuilder(bug_335476; []) Wed Feb 02 17:02:35 GMT 2011 - [Worker-12] Builder finished: CommonBuilder(bug_335476; []) time: 8270ms Wed Feb 02 17:02:35 GMT 2011 - [Worker-12] Invoking (FULL_BUILD) on builder: ScannerConfigBuilder(bug_335476; []) Wed Feb 02 17:02:35 GMT 2011 - [Worker-12] Builder finished: ScannerConfigBuilder(bug_335476; []) time: 428ms Wed Feb 02 17:02:35 GMT 2011 - [Worker-12] Top-level build-end time: 8698 However it's a full 39.8s until the UI is usable. When dealing with errors, eclipse seems to have a 400x performance hit to compilation!
Created attachment 188225 [details] work in progress Some simple performance analysis: - BuildConsoleParitioner schedules an asyncExec for every console update generated by every error needing to be shown to the user. The above ayncExec UI runnable does an unhealthy amount of work: Logging to un-buffered stream. Performing I/O: flushing and refreshing resources on each call Calculating whether the console has over-flowed. - Marker generation is expensive as ACBuilder#addMarker iterates over all the attributes of all markers on the document. The Marker map is actually backed by an array which leads to very pecimal performance O(n-attributes * number of markers per document). The attached patch is a work in progress. It batches UI updates processing many queue entries in one go. I want to get the time down for running a build to an acceptable level with the attached document. Ideally eclipse should be able to process build output as quickly as the build process can generate -- after all we're only display text, not peforming compilation!
IMHO logging should be unbuffered and flush immediately, by the same reason why stderr is unbuffered. We could have a dedicated thread in order not to block UI thread. Well, according to comment 6 the logging is not bottleneck here.
(In reply to comment #11) > IMHO logging should be unbuffered and flush immediately, by the same reason why > stderr is unbuffered. We could have a dedicated thread in order not to block UI > thread. Well, according to comment 6 the logging is not bottleneck here. Doing I/O on the UI thread is always a no-no -- you're effectively making the UI thread I/O bound which is very bad for interactivity. When writing a log-file, all writes should go through the same file-descriptor so what reasons would you not do buffered I/O?
(In reply to comment #12) > (In reply to comment #11) > > IMHO logging should be unbuffered and flush immediately, by the same reason > why > > stderr is unbuffered. We could have a dedicated thread in order not to block > UI > > thread. Well, according to comment 6 the logging is not bottleneck here. > Doing I/O on the UI thread is always a no-no -- you're effectively making the UI > thread I/O bound which is very bad for interactivity. So I assume that you intend to move the I/O out from the UI thread? > When writing a log-file, all writes should go through the same file-descriptor > so what reasons would you not do buffered I/O? And unbuffered output should not be the issue then? The reasons I'd prefer unbuffered logging: - in case of an unexpected exception or crash you don't lose the output - if buffered, the last portion of output could get stuck in the buffer until the next build starts - the logging output is in sync with console, for example currently you can open the log file in eclipse (or outside of eclipse) and it got the most recent output. If it is buffered it looks like log is losing lines.
(In reply to comment #13) > So I assume that you intend to move the I/O out from the UI thread? Yes, and the refresh. Acquiring resource lock isn't a good idea here. > > When writing a log-file, all writes should go through the same file-descriptor > > so what reasons would you not do buffered I/O? > And unbuffered output should not be the issue then? The reasons I'd prefer > unbuffered logging: > - in case of an unexpected exception or crash you don't lose the output You're assuming there's no buffering in the system above. This isn't a valid assumption: - On HEAD there is already up to 10000 characters of buffering - + latency from scheduling the asyncExec to it actually outputting the entries (up to 38s worth) - There's buffering on the input from running the commands. The risk of 'losing output' needs to be put in context. For critical files flush() should be used appropriately. The point of buffering is to minimize the frequency of system calls which can have a detrimental effect to the performance of the entire app: http://download.oracle.com/javase/tutorial/essential/io/buffers.html If you don't use buffered I/O for a log file, then where do you use buffered I/O? > - the logging output is in sync with console, for example currently you can > open the log file in eclipse (or outside of eclipse) and it got the most recent > output. If it is buffered it looks like log is losing lines. By logging outside of the UI thread, even with buffering the log will hit disk before it hits UI... > - if buffered, the last portion of output could get stuck in the buffer until > the next build starts This would be a bug. The file must be close()d at the end of the build so we don't leak file descriptors, and the Java buffers must be flushed by this point.
(In reply to comment #14) > (In reply to comment #13) > By logging outside of the UI thread, even with buffering the log will hit disk > before it hits UI... If this assumption of it working fast holds I have no problem with buffering. It was clearly a problem when log was done line by line from the UI thread busy with adding markers in between.
Created attachment 196854 [details] patch This patch takes build console performance from 32s -> <4s = ~8x speed up over what's on HEAD for a file with lots of errors. The patch addresses a number of issues and most of the change is in the BuildConsolePartitioner: - BuildConsolePartition: Change implementation to prevent massive object churn when the console overflows. Instead of re-creating the objects, we just update the offset and length in place. - BuildConsoleParitioner: - Remove I/O from UI loop. - Don't schedule thousands of asyncExecs. Run UI loop for 50ms at a time, batch processing items. - Append to the Document + check overflow at the end of each round of UI processing. Manipulating the document is expensive. - BuildConsoleViewer: Show end of document: widget.setCaretOffset(getDocument().getLength() - 1); is much faster than the previous complicated line-calculation logic... - selectPartition's redrawing of the _entire_ document when the 'selected' region changes leads to very long UI pauses. Just redraw what's needed. - ShowErrorAction: Remove. Up + Down Arrow do this by default, as does double-click. This also prevents the constant flickering issues when the console overflows. cdt.core: - ACBuilder: For a file with many markers, adding new markers is O(n^2) if we compare each new marker with each existing marker. - Regexps are slow. By preventing back tracking we can speed up the GCC regexps.
Andrew if you could review. It's probably too late, but the performance improvement is massive. Before this patch CDT can't keep up with GCC output, but can after.
Just upgraded from 3.6SR2 to 3.7 (Build id: 20110615-0604). Huge regression in terms of build console speed. In 3.6Sr2 I had several custom patterns defined for the CDT GNU C/C++ Error Parser to ignore most of these warnings, and it made a huge difference. In 3.7 these custom patterns no longer seem to work ...
(In reply to comment #16) > Created attachment 196854 [details] > patch > This patch takes build console performance from 32s -> <4s = ~8x speed up over > what's on HEAD for a file with lots of errors. Copy Build Log button on the console stopped working after applying the patch. In some cases I see the log is empty. That might be the result of taking logOpen/logClose out from the event queue. That is an error, those must follow the order of events which is ensured by the queue. > - ShowErrorAction: Remove. Up + Down Arrow do this by default, as does > double-click. This also prevents the constant flickering issues when the > console overflows. I don't feel really strongly on this one but the idea of the un-toggling "Show Error In Editor" is to be able to navigate the markers on the console without an unwanted editor jumping on you (which can generate lots of Codan markers for example). > cdt.core: > - ACBuilder: For a file with many markers, adding new markers is O(n^2) if we > compare each new marker with each existing marker. I see a problem with that. It is not uncommon that build output will print identical error lines even for resources of current project. A warning in a header could be replicated as many times as the header is included. It is a real problem if big project is being compiled. Are the markers added in UI thread? > - Regexps are slow. By preventing back tracking we can speed up the GCC > regexps. OK. It doesn't look like we quite get into O(n^2) with our patterns but I think it is worth to squeeze performance improvement here. Why don't you commit the patterns, it can be done independently from the rest. And we got a few other regex parsers too. That's for today, but I haven't looked at all pieces yet, more coming.
I am also getting exception like that in some cases. Not sure what causes it. java.lang.IllegalArgumentException: Argument not valid at org.eclipse.swt.SWT.error(SWT.java:4263) at org.eclipse.swt.SWT.error(SWT.java:4197) at org.eclipse.swt.SWT.error(SWT.java:4168) at org.eclipse.swt.custom.StyledText.setCaretOffset(StyledText.java:8434) at org.eclipse.cdt.internal.ui.buildconsole.BuildConsoleViewer.revealEndOfDocument(BuildConsoleViewer.java:127) at org.eclipse.cdt.internal.ui.buildconsole.BuildConsoleViewer.setDocument(BuildConsoleViewer.java:154) at org.eclipse.cdt.internal.ui.buildconsole.BuildConsolePage.setDocument(BuildConsolePage.java:168) at org.eclipse.cdt.internal.ui.buildconsole.BuildConsolePage.selectionChanged(BuildConsolePage.java:441) at org.eclipse.ui.internal.AbstractSelectionService.fireSelection(AbstractSelectionService.java:156) at org.eclipse.ui.internal.AbstractSelectionService$1.selectionChanged(AbstractSelectionService.java:62) at org.eclipse.jface.viewers.Viewer$2.run(Viewer.java:164) at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42) at org.eclipse.ui.internal.JFaceUtil$1.run(JFaceUtil.java:49) at org.eclipse.jface.util.SafeRunnable.run(SafeRunnable.java:175) at org.eclipse.jface.viewers.Viewer.fireSelectionChanged(Viewer.java:162) at org.eclipse.jface.viewers.StructuredViewer.updateSelection(StructuredViewer.java:2188) at org.eclipse.jface.viewers.StructuredViewer.handleSelect(StructuredViewer.java:1211) at org.eclipse.ui.navigator.CommonViewer.handleSelect(CommonViewer.java:478) at org.eclipse.jface.viewers.StructuredViewer$4.widgetSelected(StructuredViewer.java:1241) at org.eclipse.jface.util.OpenStrategy.fireSelectionEvent(OpenStrategy.java:239) at org.eclipse.jface.util.OpenStrategy.access$4(OpenStrategy.java:233) at org.eclipse.jface.util.OpenStrategy$1.handleEvent(OpenStrategy.java:403) at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:84) at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1053) at org.eclipse.swt.widgets.Display.runDeferredEvents(Display.java:4165) at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3754) at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2696) at org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2660) at org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2494) at org.eclipse.ui.internal.Workbench$7.run(Workbench.java:674) at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332) at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:667) at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149) at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:123) at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196) at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110) at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79) at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:344) at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:622) at org.eclipse.equinox.launcher.Main.basicRun(Main.java:577) at org.eclipse.equinox.launcher.Main.run(Main.java:1410) at org.eclipse.equinox.launcher.Main.main(Main.java:1386)
I can't upgrade to Eclipse 3.7 because of this bug. Our project is BIG and this makes eclipse+CDT completely unusable. Is someone looking into this?
I have been hit by this too. My code isn't large, but it makes heavy use of templates. A warning generated somewhere in a template may easily duplicate a few hundred times, each warning showing the complete path to the template instance, which leads to quite a few thousand lines. Scrolling them through in a terminal takes a second, while the console window in eclipse seems to be occupied for almost a minute. At least nothing blocks anymore :-) If this can't be sped up, how about a optional timeout, where the console window gives up trying to catch up 5 seconds after the compiler finished?
Runs even slower in Indigo Service Release 2(Build id: 20120216-1857) with CDT 8.0.2.201202111925 than in SR1.
James patch in comment #16 helped me to work around an issue which is related to this bug, so I'd like to contribute the following info, which may give some additional insight: I have several projects with large build logs, and switching between the projects takes several seconds during which the UI is not responsive (using Indigo SR2). Investigating with jstack I got stack traces similar to comment #20, showing that the majority of the time is spent inside 'BuildConsoleViewer.revealEndOfDocument' calling 'StyledText.setCaretOffset' and its descendants. Seeing the call to 'isAutoScroll()' in 'revealEndOfDocument' led me to try out the scroll lock button in the build console view. The result: When the scroll lock is active, switching between projects is fast.
*** cdt git genie on behalf of Andrew Gvozdev *** Bug 314428: [Slightly modified JBB patch] Build console is too slow when build output contains >10000 warnings from a single file. [*] http://git.eclipse.org/c/cdt/org.eclipse.cdt.git/commit/?id=edec7d86a1eb84f6120a261e181f91d1944d3ae3
Please ignore the last cdt git genie entry. That has not been committed to master. It was generated because mistaken push of temporary branch to CDT repo.
Its the same issue with Eclipse CDT Kepler. Version: Kepler Service Release 1 Build id: 20130919-0819 Build console is very slow when it has to display large amount of text. Build has to be cancelled eventually, as it takes too long!
(In reply to Rama Vorray from comment #27) > Its the same issue with Eclipse CDT Kepler. > > Version: Kepler Service Release 1 > Build id: 20130919-0819 > > Build console is very slow when it has to display large amount of text. > Build has to be cancelled eventually, as it takes too long! Yeah, it will always be this way until we get a chance to rearchitect it.
We had a contribution after Kepler was already released that helps in some cases, see bug 419207. Try install a nightly build and see if it improves. Also, I recommend never using wrapping in the Console View, see bug 407405.
I am taking on fixing this bug. I have done some new analysis to make sure I understand where the overheads are. Running different scenarios: project wide - 1000 files, each with 10 warnings project tall - 1 file, 10000 warnings project header - 1000 files, each including the same external header which has 10 warnings Each warning is the same (bad printf): ../Lotsofwarnings.c:10001:9: warning: format ‘%d’ expects argument of type ‘int’, but argument 2 has type ‘double’ [-Wformat=] printf("!!!Hello World!!! %d\n", 1.0); ^ so there is 3 lines of output per warning, meaning each clean build is approximately 30,000 lines of output Different build times (wall time, seconds): wide tall header rnu in terminal[1] make 25 6 22 make > /dev/null 25 <1 22 run in CDT[2] 31 40 30 reported time of above 29 28 24 test1 [3] 27 29 24 reported time of above 27 29 24 test2 [4] 31 38 65 reported time of above 29 3 24 test3 [5] 28 2 24 reported time of above 27 2 24 [1] Using xfce terminal on XUbuntu 16.04. The >/dev/null was redirecting stdout/err to establish performance cost of the terminal itself. For the tall case gcc takes a fraction of a second only. [2] Neon.2 with approximately CDT 9.2, running in dev environment without assertions (no -ea), the next line is how long the console reports the command took (the 23:39:31 Build Finished (took 23s.903ms) line) The difference betwen the run time and the reported time is how long after the non-UI thread finished processing the build output that the ui thread was catching up for. As you can see, case tall has the biggest lag. [3] First modifcation, disabling passing marker from ErrorParserManager to the console. This means all the error markers are created and console has all text, but the console has no highlighting and no hyperlinking. This was done by passing null instead of marker to ErrorParserManager.outputLine(String, ProblemMarkerInfo). The result now shows that (within the noise) the console updating is accounting for the lag between the backend (non-ui thread) processing and the displaying. [4] Second modifcation (does not include first mod above), disabling the O(n^2) or worse test for the marker already existing. This means commenting out the " Try to find matching markers and don't put in duplicates" block in ACBuilder.addMarker(ProblemMarkerInfo). As the numbers show, this bit of code is primarily responsible for the massive slowdown building tall. But the UI operations continue to run for a very long time after the build has completed. (This hacky change causes 10,000 markers to be created for header project instead of the proper 10.) [5] Compbine test1 and test2 together. With these two changes together it is easy to see that the vast majority of the overhead problems can be solved by properly addressing case 3 and case 4.
(In reply to Jonah Graham from comment #30) > [1] Using xfce terminal on XUbuntu 16.04. As it turns out the xfce terminal is quite slow. Running make under xterm is almost as fast as redirecting output to /dev/null.
New Gerrit change created: https://git.eclipse.org/r/86879
Very cool. Thanks Jonah! Got hit with this a few days ago as I'm porting a driver from Linux to QNX. I have always thought it was the console update. Interesting about the marker deduplication. Will definitely help test this. (And would be awesome to get into 9.2.1).
New Gerrit change created: https://git.eclipse.org/r/87000
Created attachment 265839 [details] 6 test projects, each having 10,000 to 100,000+ warning (all in a 40k file :-) I have attached the test projects I have been using to test this bug. Some of the projects generate 100,000+ warning per file (project tall). A few others, in different arrangements, have 1000 files each including the same header file which has 10 warning, causing 10,000 warning in a single build. Some benefits of the patch: - The build time in CDT compared to master is *much* faster, with speedups most significant on builds where large number of warnings or errors are generated. (For example a file with 10,000 warnings is now 25x faster build time on my machine.) - The build time is comparable in CDT compared to running in gnome-terminal for most projects. - The cancel button does something fairly instantaneous - The code is designed to limit the amount of UI thread used to ensure the UI stays responsive. - The "took" time reported is accurate There is one user visible change (to very perceptive users :-) the console maximum number of lines is no longer fixed, but instead fuzzy as this improves the processing time and complexity significantly. I have added a tooltip on the preference setting for this.
(In reply to Doug Schaefer from comment #33) > Very cool. Thanks Jonah! Got hit with this a few days ago as I'm porting a > driver from Linux to QNX. I have always thought it was the console update. > Interesting about the marker deduplication. Will definitely help test this. Great, the gerrits are up for review and test. We'll be testing it out a bit more over the next couple of days here. > (And would be awesome to get into 9.2.1). OK, but that would need an API exception as I believe I made (minor) API changes. I am having issues with API tooling at the moment, so I haven't added @since's or changed any versions yet.
(In reply to Jonah Graham from comment #36) > > (And would be awesome to get into 9.2.1). > OK, but that would need an API exception as I believe I made (minor) API > changes. I am having issues with API tooling at the moment, so I haven't > added @since's or changed any versions yet. This might be important enough to bump the March release to 9.3 if only for this feature. We'll see once we get it into master.
Gerrit change https://git.eclipse.org/r/86879 was merged to [master]. Commit: http://git.eclipse.org/c/cdt/org.eclipse.cdt.git/commit/?id=f14ee6a61df8a45a4add07ceeaede9811b7ab026
Gerrit change https://git.eclipse.org/r/87000 was merged to [master]. Commit: http://git.eclipse.org/c/cdt/org.eclipse.cdt.git/commit/?id=b564575d51280452f7ee04394c985ca9058fd022
New Gerrit change created: https://git.eclipse.org/r/97322
Gerrit change https://git.eclipse.org/r/97322 was merged to [master]. Commit: http://git.eclipse.org/c/cdt/org.eclipse.cdt.git/commit/?id=b48696a6ea1964aece1b51b9c3fef7b57ffc7982
The new implementation of build console in Oxygen is much faster than in previous releases. Build output is definitely displayed almost as quickly as from KDE konsole. However, it still seems to make the rest of Eclipse UI relatively unresponsive, even on my desktop with an quad-code Intel(R) Core(TM) i7-4790 CPU @ 3.60GHz + 32Gb ram. E.g. caret pauses during typing, stops blinking for several seconds, etc. Also, the output is not very "smooth", seems as if it replaces one "page" of build output with another, skipping 2-3 intermediate pages.
(In reply to Vadym Krevs from comment #42) Thanks for the feedback! I have created Bug 519125 to try and address the balance on the UI thread.
