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 201476 - CodeCompletion took 33750 ms.
Summary: CodeCompletion took 33750 ms.
Status: RESOLVED INVALID
Alias: None
Product: javaee
Classification: Unclassified
Component: Persistence (show other bugs)
Version: 7.0
Hardware: All All
: P4 normal (vote)
Assignee: Sergey Petrov
URL:
Keywords: PERFORMANCE
Depends on:
Blocks:
 
Reported: 2011-08-31 07:08 UTC by Peter Nabbefeld
Modified: 2012-11-27 10:36 UTC (History)
29 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter: 180139


Attachments
nps snapshot (72.68 KB, application/nps)
2011-08-31 07:08 UTC, Peter Nabbefeld
Details
nps snapshot (35.68 KB, application/nps)
2011-09-05 20:05 UTC, tnleeuw
Details
nps snapshot (77.92 KB, application/nps)
2011-09-05 20:08 UTC, tnleeuw
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Peter Nabbefeld 2011-08-31 07:08:15 UTC
Build: NetBeans IDE Dev (Build 201108220601)
VM: Java HotSpot(TM) Client VM, 20.1-b02, Java(TM) SE Runtime Environment, 1.6.0_26-b03
OS: Windows XP

User Comments:
epdv: Code completion for package import activated (CTRL+space). No scanning active.



Maximum slowness yet reported was 33750 ms, average is 12757
Comment 1 Peter Nabbefeld 2011-08-31 07:08:21 UTC
Created attachment 110294 [details]
nps snapshot
Comment 2 tnleeuw 2011-09-05 20:05:15 UTC
Created attachment 110409 [details]
nps snapshot
Comment 3 tnleeuw 2011-09-05 20:08:16 UTC
Created attachment 110410 [details]
nps snapshot
Comment 4 Sergey Petrov 2011-09-06 12:45:26 UTC
What db is used if any?
Is it always reproducible for some use-cases? if I got it right persistence completion waits in performWhenScanFinished, but the only comment regarding the issue " no scanning"< I may miss something also at initial evaluation.
Is UI blocked/frozen?
Comment 5 Peter Nabbefeld 2011-09-06 13:03:09 UTC
Sorry, not just sitting and waiting for an answer, so after a week it's hard to say what happened.

While saying, there was no scanning active, I've noticed NB sometimes *seems* to scan without showing the progress bar.

BTW, cannot open npss files into the profiler, because it is not "Nimbus compatible".
Comment 6 Sergey Petrov 2011-09-06 13:46:37 UTC
ok, thanks, anyway, I saw unusual 'npss' also but after rename to nps was able to open in nb. also I hope other reporters can provide some more information.
Comment 7 Peter Nabbefeld 2011-09-06 13:48:11 UTC
(In reply to comment #6)
> ok, thanks, anyway, I saw unusual 'npss' also but after rename to nps was able
> to open in nb. also I hope other reporters can provide some more information.

npss is for IDE snapshots, while nps is for "regular" ones.
Comment 8 Peter Nabbefeld 2011-09-06 14:00:20 UTC
(In reply to comment #6)
> ok, thanks, anyway, I saw unusual 'npss' also but after rename to nps was able
> to open in nb. also I hope other reporters can provide some more information.

Well, while I cannot open the npss file (while I should be able to open it as IDE snapshot, which doesn't work), the nps works. In my case, it's waiting for about 33s in WinXP file system, just for testing, if a file exists.

What does Windows cause to be waiting there??? Probably there's some tool to detect that?

As I've just used code completion, I even doubt, that there's the necessity to test for file existance synchronously.
Comment 9 Sergey Petrov 2011-09-06 14:15:19 UTC
initially it's executed by request processor, and the entire task is asyncronous, it may not have any sense to split completion internally in more asynch tasks. I don't see yet 30 seconds to check file existence but in code completion it's 30 seconds to try to acquire lock in javac as I see, it may be caused by background scanning and may be valid (but may be not).
Main question (for me as it affect severity of the issue) if UI was frozen or not and if proper "scanning" message was shown in completion window etc.
Comment 10 Sergey Petrov 2011-09-06 14:29:32 UTC
on other side if there is any scanning it should enqueue task and quite the method quite fast and it there is no scanning it shouldn't wait for so long, may need some help from java team or it may be javac issue also.

Tomas, Jan, can you take a look if it's an issue in parsing etc.?
Comment 11 Sergey Petrov 2011-09-08 09:43:04 UTC
ok, found File.exists() call in Parsing&Indexing loop and it takes 32 seconds, still not sure if it's java/parsing issue but it's good to get some feedback.
Comment 12 Peter Nabbefeld 2011-09-08 09:54:29 UTC
(In reply to comment #11)
> ok, found File.exists() call in Parsing&Indexing loop and it takes 32 seconds,
> still not sure if it's java/parsing issue but it's good to get some feedback.

Probably it's a problem of cache design:
My var\cache\index contains 15305 files in 15384 folders
with a total size of 115 MB (121.235.609 Bytes)

A database (e.g. using javadb) might solve these locking problems.
Comment 13 Tomas Zezula 2011-09-08 09:58:38 UTC
Seems as OS problem, the fs dir operation does not depend on the size of nodes in subfolder.
>A database (e.g. using javadb) might solve these locking problems.
There is no locking it's optimistic. The javadb was something like 10 times slower :-)
Comment 14 Peter Nabbefeld 2011-09-08 10:06:15 UTC
See(In reply to comment #13)
> Seems as OS problem, the fs dir operation does not depend on the size of nodes
> in subfolder.
> >A database (e.g. using javadb) might solve these locking problems.
> There is no locking it's optimistic. The javadb was something like 10 times
> slower :-)

Seems a Windows-specific problem (when opening folders with many files in the explorer, it takes some time, too). That's why I'd prefer sth. like a big file containing everything, such as databases usually use it, so windows wouldn't know anything about opening files. Otherwise NB will be usable for Linux and similar OSs. :-(
Comment 15 Tomas Zezula 2011-09-08 10:12:16 UTC
It seem as the "getBooleanAttribute" issue. We have some issue where we duplicate these problems.
I don't know much about NTFS but it seems that it does not even depend on size it can happen even for folder with single file. It seems like some transaction update which sometimes blocks the FS metadata operations. But I don't know it's only my guess. I will try to find more about this problem.
Comment 16 Sergey Petrov 2011-09-09 13:09:03 UTC
Tomas, is it more parsing&indexing issue on nb side in your opinion or there still may be some improper usage from persistence code? If first I'm going to reassign to parsing or may be editor/completion.
Comment 17 Tomas Zezula 2011-09-09 13:13:01 UTC
It should be set as a duplicate of gBA umbrella.
I will try to find it and let you know.
Comment 18 Sergey Petrov 2011-10-04 15:04:32 UTC
Tomas, any news? What is gBA?
Comment 19 Peter Nabbefeld 2011-10-05 13:46:07 UTC
gBA = getBooleanAttribute
Comment 20 Sergey Petrov 2011-10-11 15:38:04 UTC
thanks. can't find any umbrella myself but see reference to getBooleanAttribute in issue 187715 but it's assigned to php.
Comment 21 Tomas Zezula 2011-10-11 15:56:10 UTC
I've asked about the umbrella issue and it's not yet created.
The policy is: If there are few calls of gBA which took long time (sec per one call) you can close the issue.
Comment 22 Sergey Petrov 2011-10-21 14:15:08 UTC
ok, just put to P4 before close, not sure what is better in this case.
Comment 23 Sergey Petrov 2011-12-07 10:16:37 UTC
Most latest reports seems to be caused by long time in completion during scanning. If it's "getBooleanAttribute" issue wonder why it's mostly jpa completion issue, may need to reevaluate.
Comment 24 Sergey Petrov 2011-12-07 11:34:35 UTC
at least back to P3 for now, 
and these is thread on netcat with "slowness on autocompletion" subj
Comment 25 Sergey Petrov 2011-12-08 11:47:45 UTC
ok, some more investigation, there is two query in code completionm one is JavaCompletionQuery and second one is JpaCompletionQuery, both are present in nps, both futuretask.get() usage and it wait for parsing to complete. 
what may be good is to optimize api to combine this tasks in one "get()" call instead of two separate, but not sure it will fix the issue, just jpa query may be first and it cause report to be jpa report instead of java. It seems out of my control to fix or at least improve right now, may be something can be done in parsing (longest reports have 1000+ calls to getBooleanAttribute) is there really nothing we can do?
Comment 26 monezz 2011-12-08 12:32:58 UTC
Triggered by Sergey's suggestion the source of the slowness is in JPA I closed my model project (which is the only project with a jpa dependency and entities). Slowness in autocompletion seem to have disappeared after that.

It is very hard to reproduce this issue in a controlled project structure ( I tried with a pretty extensive dummy project)

I can reliable reproduce it with the AgroSense project
https://hg.java.net/hg/agrosense~core

Slowness does occur with the model module open, and doesnt with the model module closed.
Comment 27 Sergey Petrov 2011-12-08 13:33:23 UTC
In real it shouldn't depend on project opened with jpa usage or I don't see such dependency, I also tried something similar having slow completion (in this case long "please wait"), tried to disable jpa and restart and got it fast but after check if jpa is disabled I found jpa is enabled, so it's not proper test in my case. 
I'lltry suggested project, how to checkout/build it?
Comment 28 monezz 2011-12-08 13:55:50 UTC
> I'lltry suggested project, how to checkout/build it?

Commandline (assuming installed mercurial and maven and both on path)

hg clone https://hg.java.net/hg/agrosense~core
cd agrosense~core
mvn clean install

You can also do a clone from netbeans.(Team->Mercurial->Clone Other)
or open the cloned the root project after commandline clone(+open required projects) in Netbeans and then clean build the root project (AgroSense - Netbeans Platform Application)
Comment 29 Tomas Zezula 2011-12-08 13:57:12 UTC
In replay to comment #25.
>nps, both futuretask.get() usage and it wait for parsing to complete. 
>what may be good is to optimize api to combine this tasks in one "get()" call
>instead of two separate
The tasks are waiting until some other priority task ends. Combining them makes no sense. If they operate on the same file none of these tasks do parsing.

>It seems out of my control to fix or at least improve right now, may be something can be done
>in parsing (longest reports have 1000+ calls to getBooleanAttribute) is there
>really nothing we can do?
The real problem is very slow IO (1 invocation of gBA on the first snapshot takes 33s). Obviously parsing api cannot help.

Does the JPA code completion correct cancelling of the Future when the CC is closed?

Can you point me to the nps which has 1000+ calls of gBA? I will look if it can be optimized.
But nothing can be done with 1 invocation of gBA on the first snapshot takes 33s.
Comment 30 Sergey Petrov 2011-12-08 14:15:35 UTC
Thanlks for your help, I'm looking into http://statistics.netbeans.org/exceptions/exception.do?id=549108
It's also Linux.
I can see 1165 calls to getBooleanA, but may be i'm not yet good in nps analisys, as If I looks from tree view i can see one only.
Comment 31 Tomas Zezula 2011-12-08 14:36:38 UTC
Thanks!
I will look at it and let you know.
Comment 32 Sergey Petrov 2011-12-08 16:28:31 UTC
haven't look at possible problem with cancelling, but there may be the issue even with first completion invocation and also as I assumed before, I test and see JPA query is called first and Java query is called second, I can't find any position attribute in CompletioProviders registration but it's likely if there is a way to change order the issue can be switcched from JPA into Java (of cause it have no sense, just some theory)
Comment 33 Sergey Petrov 2012-04-23 12:47:59 UTC
added one cancelled check, latest report is just 2 sec also, previous biggest one is with getBA > 13 sec, may be heavily loaded fs etc or just win issue, to P4 once again.
Comment 34 Quality Engineering 2012-04-24 10:02:52 UTC
Integrated into 'main-golden', will be available in build *201204240400* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main-golden/rev/2ff6b4fbb3ec
User: Sergey B. Petrov <sj-nb@netbeans.org>
Log: #201476 check if cancelled is added
Comment 35 Sergey Petrov 2012-11-27 10:23:26 UTC
2 latest reports are different a bit and contain jpa completion + some other.
latest one have 4.7 in jpa, 2.7 in javadoc, 2.3 in websvc,2.2 in java completions from 12 seconds total. it seems dfferent from previous cases, I'm closing this one as suggested above + to get new statistic in new issue. also nps show more then 5 seconds in getBolean so it may be the same but in differnt context.
Comment 36 Sergey Petrov 2012-11-27 10:36:44 UTC
change to invalide as old snapshots are not valid fr new 7.3 code in my opinion. latest report is separated from duplicates list.