This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 250833 - Big multimodule MAVEN projects – slow to open, weirdly slow background scan
Summary: Big multimodule MAVEN projects – slow to open, weirdly slow background scan
Status: RESOLVED WORKSFORME
Alias: None
Product: projects
Classification: Unclassified
Component: Maven (show other bugs)
Version: 8.1
Hardware: PC Windows 7
: P2 normal with 1 vote (vote)
Assignee: Tomas Stupka
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-03-02 19:09 UTC by NukemBy
Modified: 2015-04-24 10:37 UTC (History)
1 user (show)

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments
pack of selfsampler (2.67 MB, application/x-zip-compressed)
2015-03-02 19:09 UTC, NukemBy
Details
test project (787 bytes, application/x-zip-compressed)
2015-03-02 19:13 UTC, NukemBy
Details
20 seconds of self sampler while bg scan was running for 10 minutes (260.86 KB, application/octet-stream)
2015-03-03 10:18 UTC, NukemBy
Details
IDE log for the same (15.72 KB, application/octet-stream)
2015-03-03 10:18 UTC, NukemBy
Details
Hot points from the npss attached before (76.17 KB, image/png)
2015-03-03 10:20 UTC, NukemBy
Details
Hot points from the npss attached before - dig deeper (63.57 KB, image/png)
2015-03-03 10:20 UTC, NukemBy
Details
Capture from process monitor - see: https://technet.microsoft.com/en-us/library/bb896645.aspx (8.66 MB, application/x-zip-compressed)
2015-03-03 11:25 UTC, NukemBy
Details
selfsampler with "Invalidating facelets libraries due to a library descriptor change" (306.68 KB, application/octet-stream)
2015-03-03 18:00 UTC, NukemBy
Details
selfsampler with "Invalidating facelets libraries due to a library descriptor change" (screenshot) (54.98 KB, image/png)
2015-03-03 18:02 UTC, NukemBy
Details

Note You need to log in before you can comment on or make changes to this bug.
Description NukemBy 2015-03-02 19:09:03 UTC
Created attachment 152329 [details]
pack of selfsampler

es) and experience weird performance issues with this. 

I can’t share sources of my project, but I’ve created similar setup using ‘open-source’ apache maven projects.

Below are the use-cases (Netbeans  & Java x64 - -J-XX:PermSize=256M -J-Xmx3500M,  Win7, intel Core i5-3470 3.2GHz, sources are on SSD drive).

1. Extract BackgroundScan.zip
2. Launch get-sources.cmd (script is for Findows, for linux has to be converted to *.sh)
3. After all sources are downloaded ...
4. ... Open root module in 1_all\pom.xml -> right-click 
    -> Open All Required Projects 
	-> then Close IDE – (wait until modules are opened, 
	   but do not waiting for background scan to start)
	   
5. Start NetBeans - it will start reopening last workspace
6. ... around 1 minute takes "opening of projects" – this is the message in status bar.
    Of this time
    a.	30 seconds progress bar does not appear 
       (see: selfsampler - opening project - 0 - starting.npss)
    b.	30 seconds something happens with progress bar going from 0 to 100% 
       (see: selfsampler - opening project - 1 - in-progress.npss)
7. ... after that message "Background scan of the projects" appears – it takes *6 minutes*

8. Close IDE and Start it once again ...
9. ... "opening of projects" again takes around 1 minute
10. ... "Background scan" finished in around 15 seconds (that is good timing)

11. Close IDE
12. Go to "1_all" and execute 
    mvn -fae install -Dmaven.test.skip=true
	
    this builds all source modules, some errors are possible but I don’t care 
    for this test – build takes really long (mostly to download required.
    artifacts). To speedup build same command can be executed in parallel 
    in each sub-folder, these sources are independant.

13. After build is finished -  start IDE once again ...
    a.	... "opening of projects" takes around 1 minute as usual
    b.	... "Background scan" runs around 6 minutes instead of 15 seconds 
        (why it takes so long? - i've captured selfsampler "bg-scan" 
        at 1%, 10% and 100% - last 100% took around 30 seconds)
	
14. Restart IDE once again ...
    a.	... "opening of projects" takes around 1 minute as usual
    b.	... "Background scan" runs around 1:30 minutes ...
	
15. Now try creating new empty project – it will take around 30 seconds 
    (just to close current modules). This means switch between workspaces is a real pain.
	
These were use-cases I was able reproduce more-or-less stably. 
Below are the problems I experience from time to time, but I do not 
have stable way to reproduce:

1. Initial background scan of the sources takes around 6 minutes

2. On my particular project I’m receiving following message in IDE log
    "Invalidating facelets libraries due to a library descriptor change"
    Comes from: web.jsf.editor\src\org\netbeans\modules\web\jsf\editor\facelets\FaceletsLibrarySupport.java

    In regular conditions background scan finishes in around 1:30 minutes 
    and I get around 5 such messages, but sometime loading takes 6-10 minutes 
    and I get plenty (100..200..???) of such messages 

3. After refactoring/renaming method in IDE 'background scan' typically takes 
    around 5 seconds and prevents renaming of next method until scan 
    is completed. Sometime scan also runs unexpectedly long – minute or so.


PS: I've tried to see what NetBeans is doing during "background scan" ... it appears that on compiled maven projects NONE of .java files are read during opening of project and scan (i used process monitor to identify that - https://technet.microsoft.com/en-us/library/bb896645.aspx, applied filter "Operation" contains "Read", "Path" ends with ".java"). This sounds weird to me.
Comment 1 NukemBy 2015-03-02 19:13:16 UTC
Created attachment 152330 [details]
test project
Comment 2 NukemBy 2015-03-03 10:18:14 UTC
Created attachment 152348 [details]
20 seconds of self sampler while bg scan was running for 10 minutes
Comment 3 NukemBy 2015-03-03 10:18:47 UTC
Created attachment 152349 [details]
IDE log for the same
Comment 4 NukemBy 2015-03-03 10:20:03 UTC
Created attachment 152350 [details]
Hot points from the npss attached before
Comment 5 NukemBy 2015-03-03 10:20:24 UTC
Created attachment 152351 [details]
Hot points from the npss attached before - dig deeper
Comment 6 NukemBy 2015-03-03 10:51:27 UTC
Things sometime are getting worse - for no obvious reason today that same "test apache project" was bg-scanned for 10+ minutes.

The only difference between previous test is the way i get to opening that project:

1. Start NB with project group containing my production MAVEN projects - ~300 modules, 7000 files.
2. Switch to "(none)" Project Group
3. Switch to "Apache Test" project group - bg scan was running for more than 10 minutes

Somewhere in-between I've started SelfProfiler - i was not surprised that almost all time goes into MAVEN-related classes - see https://bugzilla-attachments-250833.netbeans.org/bugzilla/attachment.cgi?id=152350.
Comment 7 NukemBy 2015-03-03 11:25:24 UTC
Created attachment 152355 [details]
Capture from process monitor - see: https://technet.microsoft.com/en-us/library/bb896645.aspx
Comment 8 NukemBy 2015-03-03 11:43:01 UTC
According to process monitor - during 15 seconds of bg scan NB queried attributes of various folders 213000 times - 14200/second (All of these are calls to parent operating system). Such implementation cannot be quick.
Comment 9 Geertjan Wielenga 2015-03-03 16:00:30 UTC
Which version of the JDK are you using? Can you use the latest one and try this process again?

https://jdk8.java.net/download.html
Comment 10 NukemBy 2015-03-03 17:58:07 UTC
On the daily basis I'm using Jdk7 (1.7.0_72), because my production project is still on Java7. I've started NB with Java8-u32/x64 and have got absolutely same behavior as on Java7, and by the way have reproduced another strange problem - it looks like in-memory "indexes" keep alive after switching to another Project group.

Here are the steps i did right now:

1. Started NB (with Java8)

2. It opened last "Project Group" - it was the "my production one"

3. I switched to the "(none)" Project Group, waited until all processes are stopped

4. I switched to "big Apache" test Project Group - background scan is currently still running for somewhat 10+ minutes and ... I see plenty of messages "INFO [FaceletsLibrarySupport]: Invalidating facelets libraries due to a library descriptor change." in IDE log. I've never seen this message with "Apache sources" when I open that project in fresh IDE (on startup). This means that my initial "production project" which was opened initially still somehow affects scanning of currently open "Apache" project, but they are compleeetly unrelated.
Comment 11 NukemBy 2015-03-03 18:00:37 UTC
Created attachment 152378 [details]
selfsampler with "Invalidating facelets libraries due to a library descriptor change"
Comment 12 NukemBy 2015-03-03 18:02:57 UTC
Created attachment 152379 [details]
selfsampler with "Invalidating facelets libraries due to a library descriptor change" (screenshot)
Comment 13 NukemBy 2015-03-03 18:21:43 UTC
BTW: my sources have nothing to do with JSF - I have no idea why JSF comes in during background scan.
Comment 14 NukemBy 2015-03-03 18:37:05 UTC
And one more weird thing, just got into that use-case ...

If I close NB with Project Group full of Maven modules and then start it - initial opening and bg scan of that project group takes at least 2+ minutes. (this is my typical performance test).

If I close NB with "(none)" Project Group (i.e. NB is empty), Start empty NB and only then switch to Project Group with plenty of Maven Modules - "opening of the projects" takes 35 seconds (vs. typical 60-65 seconds) + "bg scan" completes in 15 seconds (vs 1:00..1:30 minutes) - with total of 50 seconds. Tested this twice with the same result. Isn't it strange? Why same action has such different performance?
Comment 15 Martin Balin 2015-03-03 19:18:00 UTC
We will look at this problem.
Comment 16 NukemBy 2015-04-01 18:34:04 UTC
Not sure, this problem can be partially related - 
https://netbeans.org/bugzilla/show_bug.cgi?id=251571 

JSF related staff with methods like 'scanFinished()' in stack trace cause performance problems also in JavaScript intellisense
Comment 17 Tomas Stupka 2015-04-22 14:13:09 UTC
thanks for the thorough report

lets summarize the particular problems:

1.) external mvn install causes a long background scan in a subsequent IDE start

at least in the given example the mvn install command generates java files which then have to be scanned. This of course takes longer as when there are no new or modified files. You can also compare the particular log output ...

e.g. 
a bg scan right after mvn install was executed before IDE start

Complete indexing of 1,615 source roots took: 293,052 ms (New or modified files: 1,823, Deleted files: 0)

vs 
a bg scan after a restart when everything was already scanned and no files were changed

Complete indexing of 1,613 source roots took: 31,013 ms (New or modified files: 0, Deleted files: 0)


2.) closing project group with many mvn projects takes a long time

i believe this is tracked in issue #250869

3.) some long background scans correlate with many JSF related logs even though there are no JSF related projects opened in the IDE

seems like JFS is jumping into scanning even though it doesn't have to. 
Filed a separate issue #251973 

as a workaround - you can try to deactivate the JSF in your IDE

4.) sometimes refactorings cause an unusually long background scan

the time necessary to rescan depends on how many files were affected by the particular change. If a significant part of your projects was touch by the refactoring then also the scan will take a while. In case you think there is something specific to it and that it perhaps isn't addressed by other points at this place then feel free to file a new issue. Please, if possible, also attach a complete snapshot and message.log from such refactoring action. 

5.) switching big project groups triggers an unusually long scan
unfortunately, we weren't able to reproduce - each try resulted into times in accord with the times listed in 1.) - if there were no touched files then the overall scan time did not overreach what would be expected

6.) project open and scanning times differ when starting NB with a project group vs starting NB with no project opened and switching to a project group afterwards

similar as in 5.) we weren't able to properly reproduce. There was a slight difference between those two times (starting with none and switching to PG was aprox 13%-25% faster then starting directly with a PG). Please note that while it seems to be the same actions, things might differ on implementation level as well as in interference with other IDE processes during and right after startup (actually this action was also a big longer). Do far hard to say what could be the particular problem ...

7.) MavenForBinaryQueryImpl is heavy on work during bg scan (https://bugzilla-attachments-250833.netbeans.org/bugzilla/attachment.cgi?id=152350)

There might be some potential for a faster performance but not sure about possible side effects and afaik those particular calls are happening only during some phases and it probably won't have any dramatic effect on the overall time. Filed issue #251990 to cover that  

will close this as worksforme as the to be fixed problems are now tracked in separated issues

thanks
Comment 18 NukemBy 2015-04-22 14:47:13 UTC
Thanks for attention to this issue.

Will recheck behavior after MavenForBinaryQueryImpl$BinResult.getRoots() problem will get fixed.
Comment 19 NukemBy 2015-04-24 10:37:24 UTC
I've checked current status. It seems that fixing MavenForBinaryQueryImpl.getRoots() reduced time of bgscan from 1.5 minutes to around 40 seconds. Thanks.

Meanwhile overall 1.5 minutes to open the project still seems to me to be too long for that action. I've analysed current selfprofiler on my real project and filed 2 other issues:

Optimize 'Open Projects' phase of the 'Open Project Group' action
https://netbeans.org/bugzilla/show_bug.cgi?id=252068

Optimize 'Background Scan' phase of the 'Open Project Group' action
https://netbeans.org/bugzilla/show_bug.cgi?id=252069