Bug 516587 - CDT GCC Build Output Parser very slow
Summary: CDT GCC Build Output Parser very slow
Status: NEW
Alias: None
Product: CDT
Classification: Tools
Component: cdt-build (show other bugs)
Version: 9.2.0   Edit
Hardware: PC Linux
: P3 normal with 1 vote (vote)
Target Milestone: ---   Edit
Assignee: cdt-build-inbox@eclipse.org CLA
QA Contact: Jonah Graham CLA
URL:
Whiteboard:
Keywords:
Depends on: 314428 519125
Blocks:
  Show dependency tree
 
Reported: 2017-05-12 11:22 EDT by Jonah Graham CLA
Modified: 2020-04-06 18:57 EDT (History)
6 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Jonah Graham CLA 2017-05-12 11:22:01 EDT
While working on Bug 314428 I have been investigating the remaining slow parts of  a build with lots of output.

This bug is for the "CDT GCC Build Output Parser" and related code. 

To reproduce, do a build with 100,000s lines of output to the console with the Error Parsers off. (In my case I am running with ~300,000 lines of output.) Then toggle the "CDT GCC Build Output Parser" on and off. I am seeing build times of ~8 seconds with it on and ~1 second with it off.

The problem is org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractBuildCommandParser.parseResourceName(String), on each line of output recreates the regex Pattern objects.

By creating and caching the Pattern objects, I decrease build time to ~2 with the setting on.

In other words, the "CDT GCC Build Output Parser" was spending about 85% of its time compiling patterns.
Comment 1 Jonah Graham CLA 2017-05-12 11:35:48 EDT
As it turns out about 1/2 wasted time is doing:
org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractBuildCommandParser.makePattern(String)
and 1/2 is doing Pattern.compile().

To cache the compiled pattern will require understanding the lifecycle of these classes. AFAICT the classes get created "early", i.e well before the build is run. Also, they are created with Object.clone(), so no constructor to tie into.

While I would like the speed-up, I am not sure how to achieve the reusing of Pattern without causing a caching bug. The kind of bugs are the AbstractBuildCommandParser not acknowledging setting changes because they are already compiled into the pattern.
Comment 2 Eclipse Genie CLA 2017-05-12 11:47:48 EDT
New Gerrit change created: https://git.eclipse.org/r/96971
Comment 3 Doug Schaefer CLA 2017-05-12 13:52:45 EDT
(In reply to Jonah Graham from comment #1)
> As it turns out about 1/2 wasted time is doing:
> org.eclipse.cdt.managedbuilder.language.settings.providers.
> AbstractBuildCommandParser.makePattern(String)
> and 1/2 is doing Pattern.compile().
> 
> To cache the compiled pattern will require understanding the lifecycle of
> these classes. AFAICT the classes get created "early", i.e well before the
> build is run. Also, they are created with Object.clone(), so no constructor
> to tie into.

Ugh, really? That's awful but then a lot of the Managed Build models were done that way.

> While I would like the speed-up, I am not sure how to achieve the reusing of
> Pattern without causing a caching bug. The kind of bugs are the
> AbstractBuildCommandParser not acknowledging setting changes because they
> are already compiled into the pattern.

It could be a simple as creating a Map from pattern string to pattern. The Map lookup should be pretty fast. Not great, but avoids unknowns.
Comment 4 Dmitry Nezhevenko CLA 2017-11-01 17:27:49 EDT
Hi,

I'm experiencing same issue with very slow build output parser. Just to make sure it's not build itself, I've replaced whole build system with Makefile that just do 'cat fullbuild.log'. 

My total 'build output' is ~9000 lines. Imported project contains ~115000 files. 
So 'build' (bcasically just cat fullbuild.log) takes insane amount of time (something around one hour). 

I've found that completely disabling "CDT GCC Build Output Parser" reduces build time to something around a few seconds which is pretty OK.

Also disabling 'Using heuristic to resolve paths' reduces build time to something around 10 secs which is much better.

I've tried to use 'kill -3' a few times and found that OutputReader thread is usually busy with something like this:

"OutputReader" #76 daemon prio=5 os_prio=0 tid=0x00007f589c02d800 nid=0x3bbf runnable [0x00007f5879ef4000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.core.internal.dtree.DeltaDataTree.lookup(DeltaDataTree.java:682)
        at org.eclipse.core.internal.watson.ElementTree.includes(ElementTree.java:530)
        - locked <0x00000000891d4800> (a org.eclipse.core.internal.watson.ElementTree)
        at org.eclipse.core.internal.resources.Workspace.getResourceInfo(Workspace.java:1697)
        at org.eclipse.core.internal.resources.Container.getChildren(Container.java:144)
        at org.eclipse.core.internal.resources.Container.members(Container.java:243)
        at org.eclipse.core.internal.resources.Container.members(Container.java:226)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:900)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:902)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:902)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:902)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:902)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:902)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:902)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:902)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findPathInFolder(AbstractLanguageSettingsOutputScanner.java:902)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.findBestFitInWorkspace(AbstractLanguageSettingsOutputScanner.java:929)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.resolvePathEntryInWorkspaceAsBestFit(AbstractLanguageSettingsOutputScanner.java:1098)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.createResolvedPathEntry(AbstractLanguageSettingsOutputScanner.java:1031)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractLanguageSettingsOutputScanner.processLine(AbstractLanguageSettingsOutputScanner.java:474)
        at org.eclipse.cdt.managedbuilder.language.settings.providers.AbstractBuildCommandParser.processLine(AbstractBuildCommandParser.java:274)
        at org.eclipse.cdt.internal.core.ConsoleOutputSniffer.processLine(ConsoleOutputSniffer.java:178)
        - locked <0x000000008bc61948> (a org.eclipse.cdt.internal.core.ConsoleOutputSniffer)
        at org.eclipse.cdt.internal.core.ConsoleOutputSniffer.access$0(ConsoleOutputSniffer.java:174)
        at org.eclipse.cdt.internal.core.ConsoleOutputSniffer$ConsoleOutputStream.checkLine(ConsoleOutputSniffer.java:99)
        at org.eclipse.cdt.internal.core.ConsoleOutputSniffer$ConsoleOutputStream.write(ConsoleOutputSniffer.java:58)
        at java.io.OutputStream.write(OutputStream.java:75)
        at org.eclipse.cdt.internal.core.ProcessClosure$ReaderThread.run(ProcessClosure.java:57)

Please let me know if you need more info for my case.

PS. It's Eclipse Oxygen 20171005-1200
Comment 5 Jonah Graham CLA 2017-11-02 07:03:01 EDT
(In reply to Dmitry Nezhevenko from comment #4)
> I'm experiencing same issue with very slow build output parser. Just to make
> sure it's not build itself, I've replaced whole build system with Makefile
> that just do 'cat fullbuild.log'. 

Thanks Dmitry, you have identified and reduced a great case. This is a different reason (from Comment #0) for the slowdown. I will try to reproduce with a similar sized project (100k+). I may split this into a separate bug.

I will review what improvements can be made in the 9.4 timescale.
Comment 6 Alessandro Fardin CLA 2018-01-31 03:33:14 EST
Are there any plan to fix this on in 9.5 ?
Comment 7 Jonah Graham CLA 2018-02-01 03:57:59 EST
(In reply to Alessandro Fardin from comment #6)
> Are there any plan to fix this on in 9.5 ?

Yes, but I would appreciate some help on this one. This slow code has been around for a long time. If you can review the attached patch to see if it looks on or off track that would be great.
Comment 8 Jonah Graham CLA 2018-05-30 19:41:13 EDT
(In reply to Jonah Graham from comment #7)
> (In reply to Alessandro Fardin from comment #6)
> > Are there any plan to fix this on in 9.5 ?
> 
> Yes, but I would appreciate some help on this one. This slow code has been
> around for a long time. If you can review the attached patch to see if it
> looks on or off track that would be great.

Perhaps in the 9.6 timeframe I can get some help reviewing this patch. I am concerned about breaking things here due to the change in lifecycle. If anyone on the CC list has time to help test this please be in touch or review the gerrit (https://git.eclipse.org/r/96971)
Comment 9 Alessandro Fardin CLA 2018-11-13 17:20:47 EST
any news about thisnone ?
Comment 10 Jonah Graham CLA 2018-11-14 02:03:42 EST
(In reply to Alessandro Fardin from comment #9)
> any news about thisnone ?

Baha is looking at this for the 9.6 timeframe.
Comment 11 Alessandro Fardin CLA 2019-01-17 16:49:53 EST
Any possibility for 9.7 ?
Is this bug still under investigation ?
Comment 12 Marc-André Laperle CLA 2019-02-24 23:16:12 EST
Resetting Target Milestone since 9.6 is already out.
Comment 13 Alessandro Fardin CLA 2019-10-07 19:19:04 EDT
Any news about this One?
Comment 14 Jonah Graham CLA 2019-10-07 20:37:57 EDT
Baha is not looking at this anymore. There is no timeframe.
Comment 15 Alessandro Fardin CLA 2020-04-06 18:57:06 EDT
Clould this related to Bug 168557 - [StyledText] StyledText is very slow with long string + word wrap or other variable line height ?