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 191450 - rewrite lazy menu loading
Summary: rewrite lazy menu loading
Status: NEW
Alias: None
Product: platform
Classification: Unclassified
Component: Window System (show other bugs)
Version: 6.x
Hardware: PC Windows Vista
: P2 normal (vote)
Assignee: Stanislav Aubrecht
URL:
Keywords:
Depends on:
Blocks: 208734
  Show dependency tree
 
Reported: 2010-10-28 22:51 UTC by greggwon
Modified: 2012-04-16 13:31 UTC (History)
2 users (show)

See Also:
Issue Type: TASK
Exception Reporter:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description greggwon 2010-10-28 22:51:58 UTC
Here is another place where late binding is being run inside of the EDT and causing real problems in getting access to the IDE functions.  I logged back into my windows session after the screen saver had locked, and probably the disk was idle.  When I brought the IDE to the foreground, it painted, but when I clicked on the File Menu, it was greeted with "nothing", no busy cursor, or any other visual indication of "wait we are doing good things for you".

The IDE's dynamic, late menu binding can be useful, but there is really no reason why any of this activity besides menu manipulation should be done on the EDT.  The JMenu hierarchy can be dynamically modified inside of the EDT, while menus are visible, and then menus can be repainted (invalidate() and repaint()) to make the changes visible to the user.

At a minimum, an empty menu should pop up, or some other indication of the fact that the menu system is experiencing delays in being able to show the menu.

On windows in particular, we know how lousy of a VM implementation there is, and how me bringing the IDE to the foreground would have triggered numerous activities that would cause a change in the RSS for associated processes as things are shuffled around.  Thus, the IDE needs to make sure the user has a valid opportunity to be productive.

It seems like this late binding needs something different to happen.  Something should tell the menu system to expect to find "changes" in the menus so that it could tell the user that there may be some delay perhaps?

2010-10-28 17:39:47
Full thread dump Java HotSpot(TM) Client VM (16.0-b13 mixed mode, sharing):

"Refresh-After-WindowActivated" daemon prio=2 tid=0x05bcd000 nid=0x109c runnable [0x0a07f000]
   java.lang.Thread.State: RUNNABLE
        at java.util.AbstractCollection.toArray(AbstractCollection.java:121)
        at java.util.Collections$SynchronizedCollection.toArray(Collections.java:1566)
        - locked <0x1b52e6b8> (a java.util.Collections$SynchronizedMap)
        at java.util.ArrayList.addAll(ArrayList.java:472)
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.FileObjectFactory.getSize(FileObjectFactory.java:146)
        - locked <0x1b52e6b8> (a java.util.Collections$SynchronizedMap)
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.RootObj.invokeRefreshFor(RootObj.java:184)
        at org.netbeans.modules.masterfs.filebasedfs.fileobjects.RefreshSlow.run(RefreshSlow.java:64)
        at org.netbeans.core.ui.warmup.MenuWarmUpTask$NbWindowsAdapter.run(MenuWarmUpTask.java:298)
        at org.openide.util.RequestProcessor$Task.run(RequestProcessor.java:1418)
        at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1957)

"Inactive RequestProcessor thread [Was:Logging Flush/org.netbeans.core.startup.TopLogging$NonClose]" daemon prio=2 tid=0x05bcec00 nid=0x404 in Object.wait() [0x09e7f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1910)
        - locked <0x1532ad38> (a java.lang.Object)

"Inactive RequestProcessor thread [Was:Timeable Event Queue Watch Dog/org.netbeans.core.TimableEventQueue$1R]" daemon prio=2 tid=0x05bce800 nid=0x136c in Object.wait() [0x086af000]

   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1910)
        - locked <0x158c7510> (a java.lang.Object)

"Inactive RequestProcessor thread [Was:Logging Flush/org.netbeans.core.startup.TopLogging$NonClose]" daemon prio=2 tid=0x05bce000 nid=0x1544 in Object.wait() [0x068cf000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1910)
        - locked <0x1532a7c0> (a java.lang.Object)

"Parsing & Indexing Loop (201007282301)" daemon prio=2 tid=0x07e4a000 nid=0xcd4 waiting on condition [0x0b47f000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x1d045778> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.PriorityBlockingQueue.take(PriorityBlockingQueue.java:220)
        at org.netbeans.modules.parsing.impl.TaskProcessor$CompilationJob.run(TaskProcessor.java:573)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)

"AWT-EventQueue-1" prio=6 tid=0x05bcb000 nid=0xef8 runnable [0x09a7e000]
   java.lang.Thread.State: RUNNABLE
        at java.util.zip.ZipFile.open(Native Method)
        at java.util.zip.ZipFile.<init>(ZipFile.java:114)
        at java.util.jar.JarFile.<init>(JarFile.java:133)
        at java.util.jar.JarFile.<init>(JarFile.java:112)
        at org.netbeans.JarClassLoader$JarSource$1.call(JarClassLoader.java:468)
        at org.netbeans.JarClassLoader$JarSource$1.call(JarClassLoader.java:461)
        at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
        at java.util.concurrent.FutureTask.run(FutureTask.java:138)
        at org.netbeans.JarClassLoader$JarSource.getJarFile(JarClassLoader.java:490)
        at org.netbeans.JarClassLoader$JarSource.resource(JarClassLoader.java:526)
        at org.netbeans.Archive.getData(Archive.java:199)
        at org.netbeans.JarClassLoader$JarSource.doGetResource(JarClassLoader.java:504)
        at org.netbeans.JarClassLoader$Source.getResource(JarClassLoader.java:337)
        at org.netbeans.JarClassLoader.findResource(JarClassLoader.java:272)
        at org.netbeans.ProxyClassLoader.getResource(ProxyClassLoader.java:375)
        at org.openide.util.NbBundle.loadBundle(NbBundle.java:551)
        at org.openide.util.NbBundle.getBundleFast(NbBundle.java:515)
        - locked <0x1c2e04f0> (a java.util.HashMap)
        at org.openide.util.NbBundle.getBundle(NbBundle.java:441)
        at org.openide.util.NbBundle.getBundle(NbBundle.java:394)
        at org.openide.util.NbBundle.getMessage(NbBundle.java:637)
        at org.netbeans.modules.print.util.UI.i18n(UI.java:247)
        at org.netbeans.modules.print.action.PageSetupAction.getName(PageSetupAction.java:69)
        at org.openide.util.actions.SystemAction.getValue(SystemAction.java:183)
        at org.openide.awt.Actions$MenuBridge.updateState(Actions.java:1119)
        at org.openide.awt.Actions$MenuItem.synchMenuPresenters(Actions.java:1433)
        at org.openide.awt.DynaMenuModel.checkSubmenu(DynaMenuModel.java:190)
        at org.openide.awt.MenuBar$LazyMenu.setPopupMenuVisible(MenuBar.java:618)
        at javax.swing.JPopupMenu.menuSelectionChanged(JPopupMenu.java:1416)
        at javax.swing.MenuSelectionManager.setSelectedPath(MenuSelectionManager.java:100)
        at javax.swing.plaf.basic.BasicMenuUI.appendPath(BasicMenuUI.java:202)
        at javax.swing.plaf.basic.BasicMenuUI.access$200(BasicMenuUI.java:32)
        at javax.swing.plaf.basic.BasicMenuUI$Handler.mousePressed(BasicMenuUI.java:441)
        at javax.swing.plaf.basic.BasicMenuUI$MouseInputHandler.mousePressed(BasicMenuUI.java:322)
        at java.awt.Component.processMouseEvent(Component.java:6260)
        at javax.swing.JComponent.processMouseEvent(JComponent.java:3267)
        at java.awt.Component.processEvent(Component.java:6028)
        at java.awt.Container.processEvent(Container.java:2041)
        at java.awt.Component.dispatchEventImpl(Component.java:4630)
        at java.awt.Container.dispatchEventImpl(Container.java:2099)
        at java.awt.Component.dispatchEvent(Component.java:4460)
        at java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:4574)
        at java.awt.LightweightDispatcher.processMouseEvent(Container.java:4235)
        at java.awt.LightweightDispatcher.dispatchEvent(Container.java:4168)
        at java.awt.Container.dispatchEventImpl(Container.java:2085)
        at java.awt.Window.dispatchEventImpl(Window.java:2478)
        at java.awt.Component.dispatchEvent(Component.java:4460)
        at java.awt.EventQueue.dispatchEvent(EventQueue.java:599)
        at org.netbeans.core.TimableEventQueue.dispatchEvent(TimableEventQueue.java:137)
        at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:269)
        at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:184)
        at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:174)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:169)
        at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:161)
        at java.awt.EventDispatchThread.run(EventDispatchThread.java:122)

"TimerQueue" daemon prio=6 tid=0x05bcac00 nid=0xdc0 in Object.wait() [0x074af000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at javax.swing.TimerQueue.run(TimerQueue.java:232)
        - locked <0x1b6bcaf8> (a javax.swing.TimerQueue)
        at java.lang.Thread.run(Thread.java:619)

"Thread-3" daemon prio=6 tid=0x05bca400 nid=0xe08 in Object.wait() [0x088af000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x1b4945a8> (a java.util.LinkedList)
        at java.lang.Object.wait(Object.java:485)
        at java.util.prefs.AbstractPreferences$EventDispatchThread.run(AbstractPreferences.java:1461)
        - locked <0x1b4945a8> (a java.util.LinkedList)

"AWT-Windows" daemon prio=6 tid=0x05bbf800 nid=0xdac runnable [0x072af000]
   java.lang.Thread.State: RUNNABLE
        at sun.awt.windows.WToolkit.eventLoop(Native Method)
        at sun.awt.windows.WToolkit.run(WToolkit.java:295)
        at java.lang.Thread.run(Thread.java:619)

"AWT-Shutdown" prio=6 tid=0x05bbf400 nid=0xce0 in Object.wait() [0x070af000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:485)
        at sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:265)
        - locked <0x1aa1c9f0> (a java.lang.Object)
        at java.lang.Thread.run(Thread.java:619)

"Java2D Disposer" daemon prio=10 tid=0x05b86000 nid=0xf08 in Object.wait() [0x06eaf000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        - locked <0x1aa1ca80> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
        at sun.java2d.Disposer.run(Disposer.java:125)
        at java.lang.Thread.run(Thread.java:619)

"CLI Requests Server" daemon prio=6 tid=0x05b53400 nid=0xf6c runnable [0x066cf000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
        - locked <0x1aa1cc60> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:453)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at org.netbeans.CLIHandler$Server.run(CLIHandler.java:999)

"Active Reference Queue Daemon" daemon prio=2 tid=0x059fcc00 nid=0xda4 in Object.wait() [0x05fef000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        - locked <0x1aa1cde8> (a java.lang.ref.ReferenceQueue$Lock)
        at org.openide.util.lookup.implspi.ActiveQueue$Impl.run(ActiveQueue.java:59)
        at java.lang.Thread.run(Thread.java:619)

"Timer-0" daemon prio=6 tid=0x059fe800 nid=0xbc4 in Object.wait() [0x05def000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.util.TimerThread.mainLoop(Timer.java:509)
        - locked <0x1aa1ce80> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"Low Memory Detector" daemon prio=6 tid=0x023fd800 nid=0x1f4 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x023f8800 nid=0xe0c waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" daemon prio=10 tid=0x023f8000 nid=0xe40 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x023f7800 nid=0xb7c waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x023e5000 nid=0x87c in Object.wait() [0x04fef000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        - locked <0x1aa1d098> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x023e3c00 nid=0xed8 in Object.wait() [0x04def000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x1aa1caa8> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x022dc000 nid=0xf20 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" prio=10 tid=0x023e2400 nid=0xde8 runnable

"VM Periodic Task Thread" prio=10 tid=0x02406400 nid=0x4b0 waiting on condition

JNI global references: 8095

Heap
 def new generation   total 78144K, used 68676K [0x12200000, 0x176c0000, 0x1aa00000)
  eden space 69504K,  95% used [0x12200000, 0x162f8dc0, 0x165e0000)
  from space 8640K,  24% used [0x165e0000, 0x167f83c8, 0x16e50000)
  to   space 8640K,   0% used [0x16e50000, 0x16e50000, 0x176c0000)
 tenured generation   total 173472K, used 144464K [0x1aa00000, 0x25368000, 0x2ba00000)
   the space 173472K,  83% used [0x1aa00000, 0x23714048, 0x23714200, 0x25368000)
 compacting perm gen  total 51456K, used 51280K [0x2ba00000, 0x2ec40000, 0x38200000)
   the space 51456K,  99% used [0x2ba00000, 0x2ec14338, 0x2ec14400, 0x2ec40000)
    ro space 10240K,  54% used [0x38200000, 0x38778290, 0x38778400, 0x38c00000)
    rw space 12288K,  55% used [0x38c00000, 0x3929d1c0, 0x3929d200, 0x39800000)
Comment 1 Stanislav Aubrecht 2010-11-01 10:10:21 UTC
i agree that the lazy menu implementation needs a rewrite but it'll have to wait till the next release.
Comment 2 _ tboudreau 2010-12-17 21:27:23 UTC
FYI, I had to do some dirty tricks to avoid classloading in the EDT in mobility which, while ugly, are applicable here:  In order to meet responsiveness requirements, what I ended up doing is loading classes from a textual list of classes on a low-priority background thread which is started when the first piece of relevant UI is shown (I think this was in the new mobile project wizard).  Not nice, as the list needs to be maintained over time (easy enough to turn on -verbose:gc to get a list of culprits, though).

However, it's not 100% obvious that classloading per-se is the issue here, as opposed to two threads in the same VM trying to do I/O at the same time (which is clearly happening).  File I/O from Java on Windows in particular is much more serialized than on Unix - basically, the calling thread can and will be put to sleep by the OS and queued to be serviced by the filesystem driver.  In the thread dump above there are no locks shared between Refresh-After-WindowActivated and AWT-EventQueue-1, but it's very, very likely (we've seen this before) that AWT-EventQueue-1 is blocked in native OS code waiting for Refresh-After-WindowActivated.  

I don't think it is practical to try and avoid any classloading in the EDT - the design of Java classloading and Swing makes that a near impossibility.

Possibly this particular issue could be fixed by reducing I/O *contention*.  I know that Refresh-After-WindowActivated uses an AWTEventListener and a reschedulable RequestProcessor.Task which runs its background task on a delay after the main window is reactivated.  Possibly the AWTEventListener could be made smarter by increasing the delay before refreshing happens after window activation, and resetting the delay (to delay the task further) if any non mouse-motion InputEvent occurs during the quiet interval after window activation.  That's certainly not a silver bullet - if a menu is shown and the refresh task is running when a submenu needs to be shown you can have the same problem (but submenus are smaller, and the odds of this happening frequently are at least lower).  But it would decrease the likelihood in-VM cross-thread I/O contention by keeping the refresh task from running at exactly the same time I/O in the EDT is very likely to be necessary.

My main point is that the problem here is not classloading per se, but I/O contention - it's not necessarily a big deal that classloading is done on the EDT, the problem is that it is happening while another thread tries to do very heavy I/O.  And that the blockage is at the OS level (can't prove it, just have seen this pattern of hang many times and it is Windows-specific).

For some background on the Windows file I/O issue, see
http://netbeans.org/bugzilla/show_bug.cgi?id=65135#c37
Comment 3 greggwon 2010-12-18 06:29:29 UTC
The main issue, is that no matter what the actual work done, if it does not involve exactly the tasks of "rendering" or "assembling" the components on the screen, it is not work that belongs on the EDT.  The EDT is not a work thread, it is a single purpose thread which needs to be used for specific tasks so that the overall user interface experience can be performant.

I think that the whole issue here perhaps lies in the details of whether these late bound menus are actually working the correct way.  From many perspectives, netbeans uses an inverted responsibility tree.  Instead of requiring the modules to say "this is the state of the world", netbeans is always going around asking "what is the state of the world now".  This ends up wasting a lot of CPU time and thus impacts the users experience (for example the on going posts to the list about "Why is netbeans scanning again" and "Why is netbeans doing X when I asked for Y").

The user interface really needs to be a "static" view that changes over time, rather than a "dynamic" view which netbeans discovers from moment to moment.

The fact that there are so many reported issues (I know that I've reported several) about how EDT use is causing the UI to not be responsive and from developers having problems with "in EDT" or "out of EDT" questions, seems to me, to indicate that there are some responsibilities that are inverted, or deferred till too late, and so large amounts of work are being needed in the EDT.

It seems that there are some opportunities to look at a different perspective of how the same, or similar features might be provided without the EDT being responsible for any discovery of what needs to be rendered/displayed.
Comment 4 greggwon 2011-05-23 14:13:53 UTC
Another part of this issue might be that with CMSEnableClassUnloading in effect, many parts of the IDE might actually be unloaded and this could create additional delays as things are reloaded when the menu system is needed, perhaps?
Comment 5 Stanislav Aubrecht 2011-09-15 08:25:29 UTC
switching issue type to 'task' as this means the complete rewrite of the main menu bar.