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 224530

Summary: 93s - Maven's DependencyNode performs multiple I/O while holding global lock
Product: platform Reporter: kingpoop
Component: NodesAssignee: Jan Peska <JPESKA>
Status: NEW ---    
Severity: normal CC: Amanjot, bht, emorgado, guyost, issues, jaska_tl, jdbenitez, kganfield, kingpoop, locked, maks_t34, misterm, NiCheng, pleiades, stadelma
Priority: P3 Keywords: PERFORMANCE
Version: 7.2   
Hardware: All   
OS: All   
Issue Type: DEFECT Exception Reporter: 196828
Attachments: nps snapshot
nps snapshot

Description kingpoop 2013-01-06 06:38:53 UTC
Build: NetBeans IDE 7.2 (Build 201207171143)
VM: Java HotSpot(TM) 64-Bit Server VM, 20.12-b01, Java(TM) SE Runtime Environment, 1.6.0_37-b06
OS: Windows 7

User Comments:
kingpoop: i was only debugging - ok that's cool...BUT, when your IDE pops a message like this why don't you offer to show some possible reasons of why it's slow?

GUEST: just scrolling in a facelets template client

GUEST: opening a jsp file in the editor



Maximum slowness yet reported was 10000 ms, average is 7318
Comment 1 kingpoop 2013-01-06 06:38:55 UTC
Created attachment 129928 [details]
nps snapshot
Comment 2 bht 2013-01-07 01:02:24 UTC
Created attachment 129941 [details]
nps snapshot

Only copied 4 files, 20kBytes from the project window into the favorites window. CPU goes to 100% for all the time, computer fan starts howling. I really did not do anything else. The favorites folder is nowhere near IDE managed projects. I think this should be looked at.
Comment 3 bht 2013-01-07 01:20:38 UTC
90 seconds!

Perhaps the IDE is doing something else that it should not be doing at this time.

I was doing something really boring after returning from lunch that did not involve any source code changes at all. Just copied the files. And I am sure that all CPU was consumed by the IDE because I checked the task manager.

I think the IDE performed heavy I/O in a different thread so that the copy operation could not get the CPU it needed to complete. Like scanning spring libraries for a project that I had not touched for days.
Comment 4 Jaroslav Tulach 2013-01-07 09:00:32 UTC
The reason why this become P2 is last report by bht. Here is its analysis:

EDT is blocked by
org.netbeans.spi.project.ui.support.NodeFactorySupport$DelegateChildren$RunnableImpl.run() 
which is waiting to access Children.MUTEX

Children.MUTEX.readAccess seems to by occupied for 93s by 
org.netbeans.modules.maven.nodes.DependencyNode	
doing refresh of a node which (under the lock) does more than a single I/O operation on disk.

There are other threads performing some I/O, which may be the reason why ~25 I/O operations done by DependencyNode takes so long. Still, passing to Maven, I/O operations under global lock should be avoided.
Comment 5 bht 2013-01-07 09:13:16 UTC
Could someone please look into why Maven has such activity? I didn't touch any Maven projects during this session however the IDE seems to be scanning dependencies of Maven projects. It would be very rewarding if that could be prevented.
Comment 6 Milos Kleint 2013-01-07 11:05:17 UTC
related to https://netbeans.org/bugzilla/show_bug.cgi?id=224065#c4, 

http://hg.netbeans.org/core-main/rev/62ac750d1978 gets rid of FileUtil.toFileObject in AWT and File.exists() in getIcon().


I would recommend the reporter to investigate his hardware performance, this sort of extreme slowness appears to be regularly occurring on his computer only. If I'm not mistaken we had discussions about it in a few other issues as well and apparently his computer is either fairly below average industry setup or some of the components are severely failing. I would love to be a false prophet but any of the automated reports filed and fixed don't tackle the underlying problem of extremely slow IO. Until that is fixed, more issues will just raise the level of frustration unfortunately without apparent long term improvement. Increasing RAM memory in the computer (currently 2Gig) might increase the performance (if and only if part of the problem is disk swapping). A large number of following log entries towards the end of the messages log suggests that the disk swapping could be part of the problem.

WARNING [org.openide.filesystems.FileUtil]: FileUtil.normalizeFile(C:\Documents and Settings\name\.m2\repository\com\objectdb\objectdb\2.2.5) took 937 ms. Result is C:\Documents and Settings\name\.m2\repository\com\objectdb\objectdb\2.2.5


reassigning back to nodes.
Comment 7 bht 2013-01-07 18:18:08 UTC
Thanks Milos. You are right. My computer is slow. But I feel impact only since 7.2 and 7.3. I can run 7.1.2 without problems. It is not swapping but CPU starvation when the IDE runs heavy I/O. 

I apologise for the frustration. However I have been able to provide reproducing test cases for long standing issues perhaps due to the slowness of my computer.

In this case, I see at the end of the log:

WARNING [org.openide.filesystems.FileUtil]: FileUtil.normalizeFile(C:\Documents and Settings\name\.m2\repository\org\apache\wicket\wicket-util\1.5.5\wicket-util-1.5.5.jar) took 10,594 ms. Result is C:\Documents and Settings\name\.m2\repository\org\apache\wicket\wicket-util\1.5.5\wicket-util-1.5.5.jar

This I/O and may others has nothing to do with anything I did.

I suspect that these I/Os are part of the problem.

May I ask why NetBeans is calling FileUtil.normalizeFile on files in subdirectories of favorites? I understand that FileUtil.normalizeFile is an expensive operation.

issues\notEntered\SolidDeleteCorruptsSolids\series\06\
Comment 8 Quality Engineering 2013-01-08 02:24:31 UTC
Integrated into 'main-golden', will be available in build *201301080001* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main-golden/rev/62ac750d1978
User: Milos Kleint <mkleint@netbeans.org>
Log: #224530 more tuning in the Dependency node to get the IO touches eliminated
Comment 9 Jaroslav Tulach 2013-01-08 08:42:49 UTC
(In reply to comment #6)
> reassigning back to nodes.

I don't understand why this bug has been reassigned to nodes. Assigning to Tonda.