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 182297 - [69cat] Scanning Projecs is taking longer than in 6.8
Summary: [69cat] Scanning Projecs is taking longer than in 6.8
Status: CLOSED DUPLICATE of bug 186285
Alias: None
Product: ide
Classification: Unclassified
Component: Performance (show other bugs)
Version: 3.x
Hardware: PC Windows XP
: P3 normal (vote)
Assignee: Jaroslav Tulach
URL:
Keywords: PERFORMANCE
Depends on: 182800
Blocks:
  Show dependency tree
 
Reported: 2010-03-18 12:06 UTC by stefan79
Modified: 2011-05-25 11:40 UTC (History)
3 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments
Current Build - Logfile. (38.74 KB, application/octet-stream)
2010-03-18 12:07 UTC, stefan79
Details
NB6.8 - Message -Log. (34.12 KB, application/octet-stream)
2010-03-18 12:08 UTC, stefan79
Details
Snapshot while Initial-Scan at build 201003190200. (774.16 KB, application/octet-stream)
2010-03-19 08:16 UTC, stefan79
Details
I´ve tested it. (1.28 MB, application/octet-stream)
2010-03-24 10:56 UTC, stefan79
Details
I made a new performance test. (1.24 MB, application/octet-stream)
2010-03-31 11:20 UTC, stefan79
Details
Dev - Logfile (201004280200). (243.55 KB, application/octet-stream)
2010-04-29 11:41 UTC, stefan79
Details
6.8-Logfile. (171.68 KB, application/octet-stream)
2010-04-29 11:41 UTC, stefan79
Details
A Snapshot while Initial-Scan. (216.89 KB, application/octet-stream)
2010-04-29 13:42 UTC, stefan79
Details

Note You need to log in before you can comment on or make changes to this bug.
Description stefan79 2010-03-18 12:06:43 UTC
[ BUILD # : 200912041610 ]
[ JDK VERSION : 1.6.* ]

Scanning projects is now really slower.

Initial-Scan (same project, all files are local):
-) Current build (201003180200): 16 min
-) 6.8 (200912041610): 6,5 min

Current-Build Message-Log:
---
Resolving dependencies took: 3.094 ms
WARNING [org.netbeans.JarClassLoader]: Opening C:\Programme\NetBeans Dev
201003180200\ide\modules\org-netbeans-modules-versioning-util.jar took 938 ms
WARNING [org.netbeans.JarClassLoader]: Opening C:\Programme\NetBeans Dev
201003180200\java\modules\ext\javac-api-nb-7.0-b07.jar took 1234 ms
Complete indexing of 18 binary roots took: 596422 ms
Indexing of: file:/E:/Entwicklung65/src/ took: 277579 ms (New or modified
files: 3674, Deleted files: 0)
Complete indexing of 1 source roots took: 277579 ms (New or modified files:
3674, Deleted files: 0)
Resolving dependencies took: 0 ms
Complete indexing of 0 binary roots took: 0 ms
Indexing of: file:/E:/Entwicklung65/test/ took: 4156 ms (New or modified files:
68, Deleted files: 0)
Indexing of:
jar:file:/C:/Programme/NetBeans%20Dev%20201003180200/ide/jsstubs/allstubs.zip!/
took: 4953 ms (New or modified files: 189, Deleted files: 0)
Complete indexing of 2 source roots took: 9109 ms (New or modified files: 257,
Deleted files: 0)
---


6.8 Output in Message-Log:
--
Resolving dependencies took: 2.578 ms
Complete indexing of 18 binary roots took: 148266 ms
Indexing of: jar:file:/C:/Programme/NetBeans%206.8/ide12/jsstubs/allstubs.zip!/
took: 3656 ms (New or modified files: 189, Deleted files: 0)
Indexing of: file:/E:/Entwicklung65/src/ took: 173063 ms (New or modified
files: 3674, Deleted files: 0)
Indexing of: file:/E:/Entwicklung65/test/ took: 5625 ms (New or modified files:
68, Deleted files: 0)
Complete indexing of 3 source roots took: 182344 ms (New or modified files:
3931, Deleted files: 0)
--

I´ll attach the message-logs.
Comment 1 stefan79 2010-03-18 12:07:36 UTC
Created attachment 95364 [details]
Current Build - Logfile.
Comment 2 stefan79 2010-03-18 12:08:02 UTC
Created attachment 95365 [details]
NB6.8 - Message -Log.
Comment 3 esmithbss 2010-03-18 17:54:12 UTC
I just waited for 20 minutes for the IDE to finish scanning my 4 projects.  When the IDE completed, the IDE dumped the following line into my log:

INFO [org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater]: Complete indexing of 5 source roots took: 9450 ms (New or modified files: 183, Deleted files: 0)

Additionally, the projects were moved from a Linux environment so they had a bad platform reference to 'Ruby'.  This is apparent based on hundreds of lines indicating:

INFO [org.netbeans.api.ruby.platform.RubyPlatformProvider]: Platform with id 'Ruby' does not exist. Using default platform.


If the system is continuously trying to find the bad platform, then this is likely a major cause of the problem for ruby project scanning.  If it isn't in the IDE already, the IDE needs a mechanism to identify whether the platform exists and cache the response.  Then use the cached result instead of trying to find it each time.

*** This appears to only affect projects moved from one platform to another ***
Comment 4 stefan79 2010-03-19 08:16:01 UTC
Created attachment 95411 [details]
Snapshot while Initial-Scan at build 201003190200.

In my case it´s no Platform-Problem (it´s the same project).
Comment 5 Jan Lahoda 2010-03-19 17:54:49 UTC
esmithbss, sounds like a Ruby related problem, please report it to the Ruby support.

Otherwise, this seems quite bad. Looking at the snapshot, I see a lot of time spent in disk-related activities, and there is a lot of time (more than 4 minutes) spent in filesystem refresh. So, it is possible that the cause for this are the recursive listeners added to the source roots. Tomas will add an option to disable them. stefan79, once the option exists and is part of a build, could you please test the scanning with the recursive listeners disabled? Thanks.
Comment 6 stefan79 2010-03-22 07:10:43 UTC
> stefan79, once the option exists and is part of a
> build, could you please test the scanning with the recursive listeners
> disabled?
Yes. No problem. 
Tell me when i can test it.
Comment 7 Tomas Zezula 2010-03-22 16:48:52 UTC
I've added the option to disable recursive listeners, jet-main 62eaf85bb67e
When it will be available in night build I will notify  stefan79 to test it.
The cmd line option is -J-Dnetbeans.indexing.notRecursiveListener=true
Comment 8 Quality Engineering 2010-03-24 05:23:30 UTC
Integrated into 'main-golden', will be available in build *201003240200* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main/rev/62eaf85bb67e
User: Tomas Zezula <tzezula@netbeans.org>
Log: #182297:Scanning Projecs is taking longer than in 6.8
Comment 9 stefan79 2010-03-24 10:56:12 UTC
Created attachment 95664 [details]
I´ve tested it.

The result is a little bit strange: Now I takes always about 10 Minutes (activated or deactivated parameter).
I´ve attached two Snapshots (activated and deactivated) and the Message-Logfiles.
Comment 10 Tomas Zezula 2010-03-24 14:41:26 UTC
Thanks Stefan for the snapshots.
It seems that the slow scan is caused by disk (IO)  contention among indexer and several other thread doing FS.refresh (System Clipboard Synchronizer, DefaultRequestProcessor).
The indexer is spending most of time in IO (File.lastModified, open).
Also 54 seconds is spent in recursive listener.
Comment 11 Jaroslav Tulach 2010-03-25 10:14:48 UTC
I guess it is time to merge my earlier work. It displays progress and makes the refresh less I/O intensive: core-main#7c5f5b8074fe

Please wait for next build and remeasure, I am curious to know the results. Ii expect visible improvement, I am not sure whether we'll get back to 6.8 numbers with only this fix.
Comment 12 Quality Engineering 2010-03-26 05:33:47 UTC
Integrated into 'main-golden', will be available in build *201003260201* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main/rev/7c5f5b8074fe
User: Jaroslav Tulach <jtulach@netbeans.org>
Log: Merge of indices-168237 branch. This time to fix issue #182297.
Comment 13 stefan79 2010-03-31 11:20:09 UTC
Created attachment 96417 [details]
I made a new performance test.
Comment 14 stefan79 2010-04-29 11:36:32 UTC
Today I made a test:
-) Cleared the two cache-Directory (6.8 and Dev)
-) First I started DEV 
-) Waited until Scanning projects finished and then closed the IDE
-) Then I started 6.8
-) Waited until Scanning projects finished and then closed the IDE

The result is very difficult (for me):
-) allstubs.zip: 6.8=3812ms, DEV20100428=5063ms, Diff=1251ms = 25% (slower)
-) rt.jar: 6.8=7735ms, DEV20100428=6172ms, Diff=-1563ms = -25% (faster)
-) G:/develop: 6.8=585406ms, DEV20100428=482578ms, Diff=-102828ms = -21% (faster)
-) softline16.jar: 6.8=2016ms, DEV20100428=2141ms, Diff=125ms = 6% (slower)
-) E:/Entwicklung65/src: 6.8=253766ms, DEV20100428=307125ms, Diff=53359ms = 17% (slower)
-) e:/Entwicklung65/test: 6.8=4187ms, DEV20100428=4453ms, Diff=266ms = 6% (slower)
-) 18 binary roots: 6.8=601548ms, DEV20100428=499063ms, Diff=-102485ms = -21% (faster)
Comment 15 stefan79 2010-04-29 11:41:14 UTC
Created attachment 98271 [details]
Dev - Logfile (201004280200).
Comment 16 stefan79 2010-04-29 11:41:41 UTC
Created attachment 98272 [details]
6.8-Logfile.
Comment 17 stefan79 2010-04-29 13:42:54 UTC
Created attachment 98284 [details]
A Snapshot while Initial-Scan.
Comment 18 Jaroslav Tulach 2010-04-29 14:48:43 UTC
39s in the previous snapshot are spend in safeAddRecursiveListener...
Comment 19 Tomas Pavek 2010-04-29 17:09:25 UTC
> 39s in the previous snapshot are spend in safeAddRecursiveListener...

That is indeed in the snapshot, but according to the logs it was about 4s (which seems more reasonable). The snapshot is also strange in that it shows complete indexing of binaries, but no source indexing. Is it really a clean initial scan? In the logs both binaries and source indexing takes several minutes.

As for the times in the logs comparing 6.8 and 6.9 (20100428), I'd say it shows basically the same performance. 6.8 appears faster in indexing sources, while 6.9 seems faster in indexing binaries. The difference about 20% is IMHO very small given the way it was measured (and not repeated). The total time is same or even better in 6.9. So it does not look like a regression to me. (Mainly compared to originally reported regression which was 6.5min vs 16min - that problem seems to be fixed. Or not?)
Comment 20 stefan79 2010-05-03 12:48:54 UTC
(In reply to comment #19)
> That is indeed in the snapshot, but according to the logs it was about 4s
> (which seems more reasonable). The snapshot is also strange in that it shows
> complete indexing of binaries, but no source indexing. Is it really a clean
> initial scan? In the logs both binaries and source indexing takes several
> minutes.
Yes it´s an initial scan, but Snapshot stops now after 5 Minutes automatically.

> As for the times in the logs comparing 6.8 and 6.9 (20100428), I'd say it shows
> basically the same performance. 6.8 appears faster in indexing sources, while
> 6.9 seems faster in indexing binaries. The difference about 20% is IMHO very
> small given the way it was measured (and not repeated). The total time is same
> or even better in 6.9. So it does not look like a regression to me. (Mainly
> compared to originally reported regression which was 6.5min vs 16min - that
> problem seems to be fixed. Or not?)

Faster Binary-Indexer is fine, but what´s the reason for a slower Source-Indexing?
Maybe there´s something to make source + binary-Indexer faster. ;-)
Comment 21 Jaroslav Tulach 2010-05-06 13:37:27 UTC
(In reply to comment #20)
> (In reply to comment #19)
> > The total time is same
> > or even better in 6.9. So it does not look like a regression to me.
> Maybe there´s something to make source + binary-Indexer faster. ;-)

Making something faster, does not qualify for P2 classification. Making P3. I'll see whether I can provide some special API to parsing to merge the doubled processing of file timestamps in each source root.
Comment 22 stefan79 2010-05-06 14:38:50 UTC
> Making something faster, does not qualify for P2 classification. Making P3.
Makes sense now.
At the begin of the issue it was really a P2-Bug (6,5min vs. 16min).

> I'll see whether I can provide some special API to parsing to merge the doubled
> processing of file timestamps in each source root.
Ok.
Comment 23 Jaroslav Tulach 2010-05-17 04:53:07 UTC
Alas. Improving this would very likely complicate future integration of native listening. Rather than that, let's stay on par with 6.8 version.
Comment 24 Jaroslav Tulach 2010-06-15 22:08:58 UTC
Btw. fixing bug 186655 could have positive effect on this issue too.
Comment 25 Jaroslav Tulach 2010-07-01 08:00:41 UTC
I've just noticed similar bug fixed recently. May I mark as duplicate and ask for verification?

*** This bug has been marked as a duplicate of bug 186285 ***