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 186285 - Regression in initial scanning
Summary: Regression in initial scanning
Status: VERIFIED FIXED
Alias: None
Product: editor
Classification: Unclassified
Component: Parsing & Indexing (show other bugs)
Version: 6.x
Hardware: PC Windows Vista
: P2 normal (vote)
Assignee: Vitezslav Stejskal
URL:
Keywords: PERFORMANCE
: 182297 (view as bug list)
Depends on:
Blocks:
 
Reported: 2010-05-18 09:00 UTC by Tomas Pavek
Modified: 2010-07-07 14:17 UTC (History)
9 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments
log from NB 6.8 (157.25 KB, text/plain)
2010-05-18 09:01 UTC, Tomas Pavek
Details
log from NB 6.9 (173.84 KB, text/plain)
2010-05-18 09:01 UTC, Tomas Pavek
Details
snapshot from 6.8 (184.77 KB, application/octet-stream)
2010-05-18 13:41 UTC, Tomas Pavek
Details
snapshot from 6.9 (53.13 KB, application/octet-stream)
2010-05-18 13:41 UTC, Tomas Pavek
Details
correct snapshot for 6.9 (200.36 KB, application/octet-stream)
2010-05-18 14:23 UTC, Tomas Pavek
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Tomas Pavek 2010-05-18 09:00:31 UTC
We consistently observe ~105 regression in initial scanning time of Limewire project [1]. E.g. measured here: http://wiki.netbeans.org/NB69ScanningMeasurements

Here are fresh numbers with current build (measured time of first opening of project till scanning is finished - via stopwatch, also added times reported by RepositoryUpdater).

NB 6.8
* 107.3s (complete indexing 46 binary roots: 16765ms, 2 source roots: 81750ms)
* 106.2s (complete indexing 46 binary roots: 17937ms, 2 source roots: 85969ms)
* 111.9s (complete indexing 46 binary roots: 18030ms, 2 source roots: 86219ms)

NB 6.9 201005132200
* 119.1s (complete indexing 46 binary roots: 20328ms, 2 source roots: 90125ms)
* 118.7s (complete indexing 46 binary roots: 19797ms, 2 source roots: 90625ms)
* 118.9s (complete indexing 46 binary roots: 20313ms, 2 source roots: 90437ms)

Going to attach messages.log with detailed info. Not able to create comparable NPS yet, sorry.

[1] http://hg.netbeans.org/binaries/FDCBE13B6CA7B154F6EE29BEF3B9404F7A7B1A57-lime6.zip
Comment 1 Tomas Pavek 2010-05-18 09:01:03 UTC
Created attachment 99119 [details]
log from NB 6.8
Comment 2 Tomas Pavek 2010-05-18 09:01:29 UTC
Created attachment 99120 [details]
log from NB 6.9
Comment 3 Vitezslav Stejskal 2010-05-18 10:41:41 UTC
From 6.8's log:
Indexing of: jar:file:/C:/BuildNB1/ide12/jsstubs/allstubs.zip!/ took: 3843 ms (New or modified files: 189, Deleted files: 0)
Indexing of: file:/D:/Projects/NetBeans/lime_69/lime6/src/ took: 80954 ms (New or modified files: 2531, Deleted files: 0)

From 6.9's log:
Indexing of: jar:file:/C:/BuildNB2/ide/jsstubs/allstubs.zip!/ took: 5859 ms (New or modified files: 189, Deleted files: 0) [Adding listeners took: 0 ms]
Indexing of: file:/D:/Projects/NetBeans/lime_69/lime6/src/ took: 86453 ms (New or modified files: 2531, Deleted files: 0) [Adding listeners took: 500 ms]

The slowdown is in both source roots - lime6/src (java) and allstubs.zip (javascript). However, it's much bigger in the javascript source root - around 50% comparing to approx. 7% slowdown in the java source root. I'm investigating this further...

According to the release rules (please correct me if I'm wrong) this is a post cut-off P2, which means no waiver is needed. And on the performance meeting on Monday we all agreed that this is not a release stopper, which means that we are not going to escalate it to P1.
Comment 4 Tomas Pavek 2010-05-18 13:40:11 UTC
Not a stopper, does not have to be waived, IMO...

I've managed to create profiling snapshots with the same sampling method in both IDEs, attaching.
Comment 5 Tomas Pavek 2010-05-18 13:41:20 UTC
Created attachment 99134 [details]
snapshot from 6.8
Comment 6 Tomas Pavek 2010-05-18 13:41:49 UTC
Created attachment 99135 [details]
snapshot from 6.9
Comment 7 Jan Lahoda 2010-05-18 14:18:08 UTC
The 6.9 snapshot seems strange - there does not seem to be any indexing activity. Isn't it snapshot from first editor opening?
Comment 8 Tomas Pavek 2010-05-18 14:23:54 UTC
Created attachment 99140 [details]
correct snapshot for 6.9

Attached something else for 6.9, sorry. Here it is...
Comment 9 Tomas Pavek 2010-05-18 14:54:29 UTC
As for different slowdown for the 2 source roots (allstubs.zip and lime6/src): note that they are processed in different order. NB 6.9 starts with allstubs.zip, so might be just warming up on it...
Comment 10 Vitezslav Stejskal 2010-05-18 14:58:56 UTC
Well, comparing the snapshots I think we can safely attribute the slowdown to the new javac...

parse:      32316 vs 34096 ~ +5.5%
generate:   26746 vs 26510 ~ -0.01%
analyze:     5585 vs  5514 ~ -0.01%
enterTrees:  3550 vs  6111 ~ +72%
--
total:      73516 vs 79713 ~ +8%
Comment 11 Vitezslav Stejskal 2010-05-18 14:59:37 UTC
(In reply to comment #4)
> I've managed to create profiling snapshots with the same sampling method in
> both IDEs, attaching.

Thanks a lot for the snapshots, Tomasi!
Comment 12 Tomas Zezula 2010-05-18 16:20:47 UTC
Here are some observations:

- scanBinaries 19124ms vs 20804ms
        but in 6.9 seems to be a new SpringBinaryIndexer (1931ms)

-scanSources 87599ms vs 96767ms
       -Crawler.getResources() 6567ms vs 6914ms but in average with rest of the methods except index the same.
       -index 80824ms vs 89240ms
            -JavaCustomIndexer 75239ms vs 82012ms
                    -parse 31209ms vs 33576ms
                            -FileInputStream.<init> 26243ms vs 28740ms - the additional work done by TopSecurityManager
                             -addAptGenerated - 1767ms new and can be removed when no apt and probably optimized for apt by some contract among FM and CW.
                              -enterTrees 3550 vs 6053 - apt related - Dusan know how to improve this when no ap.

              

             -COSIndexer - takes longer time, but it seems to be the first to initialize libraries - not important
-indexEmbedding 3574ms vs 5553ms
      -JSIndexer 847ms vs 1763ms - TokenSequence.moveNext 18ms vs 544ms
      -HtmlIndexer seems to be added or it's slower
Comment 13 Petr Jiricka 2010-05-18 16:57:31 UTC
> but in 6.9 seems to be a new SpringBinaryIndexer (1931ms)

But Limewire does not use Spring, right? So there should not be any penalty; Spring support should not cause slowdown for projects that don't use Spring. Or, only very minimal slowdown.

The regressions in JavaScript and HTML should also be looked into - there are almost no JS/HTML files in this project.
Comment 14 Marek Fukala 2010-05-19 08:58:52 UTC
HtmlIndexer is new to 6.9; indexing of only 3 files took 620ms which is quite a lot. 

Even given the fact that the time contains initialization of one DTD model (269ms) which also involves classloading. 

There are also two calls to HtmlGSFParser.parse() which took 91ms.
Comment 15 Marek Fukala 2010-05-21 12:13:09 UTC
As for the HTML indexing I forgot to mention that a significat portion of the time is spent in classloading. Since there are only four indexed html files in the project the aggregated time may seem to be quite high per file. But if the classloading and initializations which happens only once per ide session are substracted, the performance seem reasonable to me. Given that I do not plan to do any improvements on this area.
Comment 16 Alexey Butenko 2010-05-21 14:28:36 UTC
So, it seems that SpringBinaryIndexer is not efficient since it is checking for org.springframework.core.SpringVersion class inside every
library. The idea was to collect all xsd inside spring jars to use them in code completion in spring config files. But it seems that presence of the spring framework should be checked somehow (or at least the name of the library),  before searching the class inside the library.
Comment 17 Alexey Butenko 2010-05-21 15:31:41 UTC
Added fix which should decrease the scanning time
http://hg.netbeans.org/web-main/rev/1c4bb559d4f2
Comment 18 Alexey Butenko 2010-05-21 15:34:11 UTC
Added fix which should decrease the scanning time
http://hg.netbeans.org/web-main/rev/1c4bb559d4f2
Comment 19 Jan Lahoda 2010-05-25 15:45:31 UTC
The javacard's annotation processor no longer uses the hardcoded APs approach:
http://hg.netbeans.org/jet-main/rev/81006548facb
Comment 20 Dusan Balek 2010-05-25 16:08:39 UTC
APT processing should not bring any overhead when there no processors to run:
http://hg.netbeans.org/jet-main/rev/862e25c637e9
Comment 21 Quality Engineering 2010-05-26 07:21:01 UTC
Integrated into 'main-golden', will be available in build *201005260001* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main/rev/81006548facb
User: Jan Lahoda <jlahoda@netbeans.org>
Log: #186285: javacard's annotation processor should run using standard AnnotationProcessorQuery.Result, rather than hardcoded processors.
Comment 22 Vitezslav Stejskal 2010-06-14 11:38:17 UTC
I assume this is now fixed.
Comment 23 Oleg Khokhlov 2010-06-30 13:51:01 UTC
6.8 FCS: 110179ms
6.9 FCS: 133865ms
20100630: 111414ms
Comment 24 Jaroslav Tulach 2010-07-01 08:00:41 UTC
*** Bug 182297 has been marked as a duplicate of this bug. ***
Comment 26 Oleg Khokhlov 2010-07-07 14:17:13 UTC
verified in 6.9.1