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.
Description
nleck
2008-08-15 23:28:49 UTC
Created attachment 67591 [details]
two ctrl+\ while IDE is locked up
Created attachment 67593 [details]
screen shot while locked up. ( NO user feed back at all)
It seems to be a dup of #139839. *** This issue has been marked as a duplicate of 139839 *** This is NOT a deadlock and nothing to do with the "open file dialog" so not a duplicate of #139839. This is a major performance issue when compared to Eclipse running on the same machine on the same source folders. The IDE will respond again after a number of seconds but if you have a number of folders it can take many minutes to open a tree of ~6 folders deep, all the time the Eclipse users are laughing at us :-( Peter, could you please check if you duplicated a correct issue? Those two does not seem to be similar by the description. Could you please tell us if there is some information in the thread dump that makes these two issues duplicate (some info from developpers, for example)? I think this one looks quite similar by the description: http://www.netbeans.org/issues/show_bug.cgi?id=143661 nleck: can you please just post us the information from "Help>About" here? I think it is a nice practice assuring that we know the exact build number. There are currently being some major changes made in all the explorers (http://wiki.netbeans.org/FitnessViaLaziness) Here is the version numbers from the help menu:- Product Version: NetBeans IDE 6.5 Beta (Build 200808111757) Java: 1.5.0_14; Java HotSpot(TM) Client VM 1.5.0_14-b03 System: SunOS version 5.10 running on sparc; ISO646-US; en (nb) Userdir: /opt/dataciti/home/nl32178/nb6.5b1 Sorry, it was done by accident, more issues opened at the same time. Petr, you are right it really seems to be a dup of #143661. Reassigning to "openide" for further evaluation. Just found a mail from the reporter on nbusers where he says the sources are on a network drive: ----- %< ----- Do you guys ever see the code completion database getting corrupt ie "go to Type.." can't find Java classes that have existed for years ? This seems to happen very often to us. Also our sources are on a NFS mount ( mandatory ) but the machines is large 32gigs and 8 cpus shared by a number of developers. The navigation of the source files is much slower than other IDEs in this environment. ----- %< ----- BTW I don't see why this should be a duplicate of issue 143661. The thread dumps look quite different. nleck, can you say how big your code base is (number of source files and libraries)? What IDE installation you have - is it the full (aka Kitche Sink) distribution? Would you say there's some difference compared to previous NB versions? Thanks Yes, the sources are on NFS mount. The netbeans user directory is on a local disk the the machine so the code completion database (seperate issue) should not be effected by the NFS mount. I'm currently using netbeans-6.5beata-200808111757-java.zip The project is a "freeform" project, not sure if that makes any difference. See below for the sizes etc. find . -name "*java" |wc 5356 5356 262978 find . -name "*jar" |wc 97 97 2280 find . -name "*java" -exec cat {} \; |wc 2025226 6456766 67522238 The only problem I can see in http://www.netbeans.org/nonav/issues/showattachment.cgi/67591/nb.stackdump is at org.netbeans.modules.java.source.parsing.SourceFileObject.isOpened(SourceFileObject.java:362). Imho it is really inefficient to initialize creation of DataObjects only to find out that they are not opened yet. Ouptions: 1. add new method to loaders to verify if the data object is really created, 2. listen on OperationListener and keep your cache, 3. Check for DataObject.Registry to find out modified objects, 4. Get list of all TopComponents and extract their dataobjects. Any solution is good, just do not ask for recognition of new data objects, please. Imho, reassign to java. To reporter: the thread dump does not explain to me why the IDE should be locked. It just shows possible inefficiency. Well, what we have is a FileObject, what we need is a Document for this file, if it exists, or null if it does not. The journey how we get the Document is not very important for us. But, from your description, all possible solutions look like hacks. Not sure that we should introduce these hacks into the Java support - it would be much better if there were an API method that would get a FO and would produce DataObject.find(file).getCookie(EditorCookie.class).getDocument(), efficiently. Then we could use the method through the IDE (I would assume the other language supports and/or GSF would use very similar approach). Created attachment 68063 [details]
many more stack dumps.
From the stack dumps we see File IO on the AWT-EventQueue which would lock up the UI wouldn't it ? "AWT-EventQueue-1" prio=10 tid=0x001b1e18 nid=0x1e runnable [0x2097d000..0x2097fca8] at java.io.UnixFileSystem.getBooleanAttributes0(Native Method) at java.io.UnixFileSystem.getBooleanAttributes(UnixFileSystem.java:228) at java.io.File.exists(File.java:702) at org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager.exists(FileChangedManager.java:96) at org.netbeans.modules.masterfs.filebasedfs.fileobjects.FileObjectFactory.touchExists(FileObjectFactory.java:368) at org.netbeans.modules.masterfs.filebasedfs.fileobjects.FileObjectFactory.issueIfExist(FileObjectFactory.java:307) BTW: Once a folder is opened, it is very quick to close and open it again. The last thread dumps also show lots of versioning (subversion or cvs). Nigel - do you have your sources under version control system? You could make a small test and disable cvs, subversion and mercurial modules in plugin manager to see if it makes any difference. BTW how big is the folder you expand - number of files directly in the folder? Is expanding the only situation where the explorer locks? Yes, it's a lot faster when I disable cvs, subversion and mercurial ( I enabled just CVS and it was slow again) We use CVS. The folders would normally have 10-30 or so Java files and then a number of sub folders. I don't think the total sub folders per folder would be more than 20 ie. not huge. Yes, explaning folders for the first time ( or long time later) is the only sitution I know of when the IDE locks up. The only other issues are to do with "Go to type..." and back ground scanning. I have reported issue 144852 to track the problem in JavaSource. I have added logging. Use -J-Dorg.openide.loaders.FolderChildren.level=100 to turn it on. That way we can find out how much time is wasted in visibility query: changeset: 97484:0f530fc23894 tag: tip user: Jaroslav Tulach <jtulach@netbeans.org> date: Fri Aug 22 15:02:46 2008 +0200 summary: #144131: Adding logging to measure how much it takes to find if fileobject is supposed to be visible or not I am moving this issue to versioncontrol systems. Imho there has to be some inefficiency there. My logging can just show how much. Maybe guys in versioning want to add more logging themselves? I've just checked the version control system code and there seems to be some kind of logging already (present in beta). Please run NetBeans with -J-Dorg.netbeans.modules.versioning.level=100 and attach more logs. Thanks. Integrated into 'main-golden', available in build *200808230201* on http://bits.netbeans.org/dev/nightly/ Changeset: http://hg.netbeans.org/main/rev/0f530fc23894 User: Jaroslav Tulach <jtulach@netbeans.org> Log: #144131: Adding logging to measure how much it takes to find if fileobject is supposed to be visible or not Created attachment 68215 [details]
logs after setting org/netbeans.modules.versiong.level=100
from the log it looks like you were expanding folders under "/home/nl32178/src/DC-eqrap4d/", right? there doesn't seem to be anything wrong from what was traced in versioning. could you please check the size of $nb_userdir/var/cache/cvscache ? if you invoke the cvs/show changes action for such a folder - how log does it take until the status information is completely shown? thanks added some logging and caching (should do no harm) into cvs - a97e828f62dd. It would be great if you could run an actual build with all mentioned switches and attach your log -J-Dorg.netbeans.modules.versioning.system.cvss.CvsVersioningSystem.level=100 -J-Dorg.netbeans.modules.versioning.level=100 -J-Dorg.openide.loaders.FolderChildren.level=100 thanks i've just pushed the changes... cvscache is a directory so not large in itself see below for the listing eqrap4d:/home/nl32178$ ls -l /opt/dataciti/home/nl32178/nb6.5*/var/cache/cvscache total 28 -rw-r--r-- 1 nl32178 eqrdev 544 Aug 25 03:03 10.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:48 108.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:46 122.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:46 136.bin -rw-r--r-- 1 nl32178 eqrdev 156 Aug 25 02:46 137.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:46 153.bin -rw-r--r-- 1 nl32178 eqrdev 190 Aug 25 02:46 155.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:46 156.bin -rw-r--r-- 1 nl32178 eqrdev 2402 Aug 25 03:03 165.bin -rw-r--r-- 1 nl32178 eqrdev 674 Aug 25 02:46 174.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:46 180.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:49 196.bin -rw-r--r-- 1 nl32178 eqrdev 586 Aug 25 02:46 2.bin -rw-r--r-- 1 nl32178 eqrdev 1708 Aug 25 03:03 211.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:46 219.bin -rw-r--r-- 1 nl32178 eqrdev 158 Aug 25 02:46 298.bin -rw-r--r-- 1 nl32178 eqrdev 180 Aug 25 03:03 34.bin -rw-r--r-- 1 nl32178 eqrdev 0 Aug 25 02:46 43.bin -rw-r--r-- 1 nl32178 eqrdev 146 Aug 25 02:46 87.bin -rw-r--r-- 1 nl32178 eqrdev 566 Aug 25 02:46 92.bin Yes calling "show changes" can take a while but you would expect that as it needs to talk to the CVS server. We wouldn't be doing that each time we open a folder ( I hope) Integrated into 'main-golden', available in build *200808260201* on http://bits.netbeans.org/dev/nightly/ Changeset: http://hg.netbeans.org/main/rev/a97e828f62dd User: Tomas Stupka <tstupka@netbeans.org> Log: #144131 - frequent long pauses ( lock ups) while navigating file explorer Created attachment 68327 [details]
messages.log after logger changes in newest daily build.
what was the folder you expanded? I opened a number of folders just to get a sample of the times. A good example is "com/aspc/commander/sql" which took a while to open. from the attached thread dumps it looked like nb was hanging a lot in ... at o.n.m.versioning.system.cvss.util.Utils.containsMetadata(Utils.java:479) at o.n.m.versioning.system.cvss.CvsVersioningSystem.getTopmostManagedParent(CvsVersioningSystem.java:434) at o.n.m.versioning.system.cvss.CVS.getTopmostManagedAncestor(CVS.java:79) ... but it didn't seem to be the case from the attached log file. CVS.getTopmostManagedAncestor was called for com/aspc/commander/sql and it's children only a few times and spent only a couple of millis. However, there seems to be some traffic in versioning after all children nodes were created. I'll add more logging to check the particular visibility queries in versioning and the cvs annotator added more logging to cover the cvs annotator and VQ please run with: -J-Dorg.netbeans.modules.versioning.system.cvss.CvsVersioningSystem.level=100 -J-Dorg.netbeans.modules.versioning.level=100 -J-Dorg.openide.loaders.FolderChildren.level=100 -J-Dorg.netbeans.modules.subversion.level=100 reproduce the issue (1 case should be enough) and post messages.log and the folders name thanks and it would be great if you could shoot few more threaddumps while waiting for the folder to expand thanks pushed 95d0429f0183 9186f27da260 Created attachment 68387 [details]
log of opening com/aspc/commander/sql
Searches are also very slow when compared to the command line search ( minutes versus seconds) find . -name "*.java" -exec grep "ABC" {} \; Is this the same issue or should I create a different bug ? The issue with searching files is tracked as issue #134558 (http://www.netbeans.org/issues/show_bug.cgi?id=134558). You have been on its Cc: list since May. IT is not just nleck having this problem - It is very slow for me too. It's not just navigating through the tree, the "Go to File" is also really slow I don't think it was always this slow - I never seemed to have problems when I used Netbeans 4.1 ( or maybe there were just not so many versions of each file back in those days :-( ) sorry, i've forgot to mention - you need a new build. I'm missing some output in the log file. Could it be you run the same build as with the previously attached log? I ran it with the next's day build. 200808261401 Which build has your logging changes ? I'll download and do again. Integrated into 'main-golden', available in build *200808280201* on http://bits.netbeans.org/dev/nightly/ Changeset: http://hg.netbeans.org/main/rev/9186f27da260 User: Tomas Stupka <tstupka@netbeans.org> Log: #144131 - frequent long pauses ( lock ups) while navigating file explorer checked the latest build it's still at 200808261401... is there a way to get the build with the new loggings messages in it. Now there's already build 200808281401 available. Note if you need a latest build and don't want to wait for the official nightly, you can also download a continuous build from Hudson: http://deadlock.netbeans.org/hudson/job/trunk/lastSuccessfulBuild/ Created attachment 68701 [details]
message log
I've attached the logs for me opening the folder com/aspc/commander/sql which is quite slow. nleck:
> opening the folder com/aspc/commander/sql which is quite slow.
looking at the log i would say it was a bit more than 30s. Or could it be we are still missing something and the whole
action lasted quite longer?
most calls measured in versioning and cvs were < 1 millisecond, but the the interesting part seem to be log entries like:
FINE [org.netbeans.modules.versioning.system.cvss.CvsVersioningSystem]: isVisible
/home/nl32178/src/DC-eqrap4d/com/aspc/commander/sql/BlankCommand.java
FINE [org.netbeans.modules.versioning.system.cvss.CvsVersioningSystem]: isVisible returns true in 1 millis
FINE [org.netbeans.modules.subversion]: isVisible /home/nl32178/src/DC-eqrap4d/com/aspc/commander/sql/BlankCommand.java
FINE [org.netbeans.modules.subversion]: isVisible returns true in 0 millis
FINE [org.openide.loaders.FolderChildren.home.nl32178.src.DC-eqrap4d.com.aspc.commander.sql]: createNodes:
/home/nl32178/src/DC-eqrap4d/com/aspc/commander/sql/BlankCommand.java took: 650 ms
There were created ~50 nodes under .../com/aspc/commander/sql/ all with return times over 600ms
each node creation took over half a second while the particular vcs visibility queries returned in almost no time, so
the question at this point is what else was happening in that scope.
it was mentioned that uninstalling the vcs modules had a positive impact, unfortunately, we have no idea at this moment
what else from vcs could be involved
reassigning back for further evaluation
I think now there is a time to do little bit of profiling. nleck, please run two version of NetBeans (with different userdir) and attach profiler from one to the other: 1. Profile/Attach Profiler 2. Analyse Performance 3. define root method, add manual: class name: org.openide.loaders.FolderChildren method name: createNodes signature: (Lorg/openide/filesystems/FileObject;)[Lorg/openide/nodes/Node; 4. filter: exclude java core classes 5. attach (choose local + direct attach) 6. run netbeans with -Jand_the_command_line_suggested_by_the_attach_dialog 7. reproduce your test case 8. take snapshot 9. check that it really contains some data about createNodes and methods called from createNodes 10. save the snapshot and attach it here Good luck! In other words, we were not able to find the culprit in versioning modules just via logging. The only chance seems to be the full profiler snapshot of the calls of the method that creates the nodes so long. Let us know if you need help with setting up the profiler session. Thanks yes, in that folder there are about 50 files and it took about 30 seconds to open the folder. Remember this is just a sample and there are many many other folders and 30 seconds each folder is too long. Created attachment 69015 [details]
snap shot of opening folder ( excluding sleep/wait)
Created attachment 69016 [details]
snap shot of opening folder ( including sleep/wait)
I couldn't seem to define the root method so I just reset the results before opening the folder. I guess that means there will be other stuff in the snap shot but I hope it'll give you want you need. I guess both snapshots are somehow strange. They all start only with "run()" methods. It seems to me that you must have defined that your root method is java.lang.Runnable.run(). As such the snapshots are of no use, as they miss the one method we are interested in, e.g. FolderChildren.createNodes. I am afraid I need new ones, I am CCing Tomáš Hůrka, leader of profiler, to advice what can be wrong in your setup. Why only "run()" methods are counted? A bit surprising is that 4s is wasted in HeapView.paintComponent. Maybe slow rendering, I am not sure. Anyway we can eliminate this, if you hide "Memory" toolbar in your next measurement. As nleck already wrote - he did not defined root method. This is clearly visible if you open snapshot and select "Info' tab. If no root method is defined, all Runnable.run() methods are implicitly defined as root methods. The other problem is that instrumentation filter is defined as 'Quick Filter...', which is probably also wrong. I did a "reset" before opening the folders so that you didn't get all the profiling of the start up of the ide. I can do again without doing a reset. Defining the root method didn't seem to work, i double checked the spelling but could see why. Created attachment 69052 [details]
We need to find out why the definition of root method does not work, it works for me in build from 4Sep, 2008, what are your error, if any? Open new bug for profiler...
I'll try again tomorrow morning Oz time. Thanks, Nigel. I'm attaching pre-configured Attach settings with correctly defined root method. Just unzip it into <ide_userdir>/config/Services, start the IDE and invoke Attach Profiler... action, everything should be set: Analyze Performance, Part of application, FolderChildren.createNodes root method, Exclude Java core classes filter, Local Direct attach to Java application. Created attachment 69341 [details]
Profiler attach settings.
Thanks very much Jirka. Now it is time for Nigel to execute the measurements. I want to understand the reasons causing this bug, but we need more data, otherwise we cannot fix it for next IDE version. Created attachment 69382 [details]
new profile
Heuréka! 12s in MecurialVCS.getTopMostManagedAncesor 38s in JsfJavaDataLoader.findPrimaryFile I will create two bugs for these two findings. Thanks a lot. As a workaround disable support for Mercurial and VisualWeb projects, if you want. In a more general view, it seems that the biggest problem in this setup is that NFS is particularly slow when looking for nonexistent files (a thing that both versioning and jsf loader use widely). This is understandable - if the (OS) user look for an explicitly named file that is not in local NFS cache, the server needs to be consulted (every time). Query for >1500 nonexistent files -> >1500 network round trips, which can be at least few milliseconds each. We should revisit the is-there-such-a-file pattern, as I fear it is used much more in the IDE. Have tried to attach an .nps file for three days now, without luck (getting a 500 - "Internal Server Error" each time) Any clues to what goes wrong? I have tried with FF2.x, FF3.x, IE7 and Chrome - same result :( Forgot to mention: after changing my netbeans_jdkhome from a 1.6.0_03 to a 1.6.0_06 installation, the problem almost went away completely. It may still take one second to expand a package with 75 classes, but that's quite a drastic improvement from the values in the minute(s) region I had with 1.6.0_03. To carnit: if you are unable to attach the snapshot here, feel free to mail it to me (tpavek) or jtulach (at netbeans.org) directly. Thanks Both blocking issues has been fixed. I guess it is time for Nigel to verify that we really improved his usecase. |