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.
[ BUILD # : 201003160201 ] [ JDK VERSION : 1.6.* ] I attempted to refresh the list of gems installed for my jruby environment and both CPU's pegged at 100% for almost 1 minute. Attached .nps file has trace details.
Created attachment 95335 [details] Profile trace of NB while reloading gem list
Created attachment 95336 [details] log file where update is being performed.
Looking at the snapshot it seems that the thread consuming CPU cycles is some Mylyn related worker (not sure which part of the IDE runs it, probably some of the connected dev modules). Is this reproducible for you? If yes, can you take a couple of thread dumps (http://wiki.netbeans.org/GenerateThreadDump) while the CPUs are pegged?
Here is the full thread dump when the IDE is locked and CPU is 100%. Full thread dump Java HotSpot(TM) Client VM (16.0-b13 mixed mode, sharing): "Inactive RequestProcessor thread [Was:Folder recognizer/org.openide.loaders.FolderList$ListTask]" daemon prio=10 tid=0x09a6b000 nid=0x52d6 waiting for monitor entry [0xaf5fc000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1859) - waiting to lock <0x7e000730> (a java.util.Stack) - locked <0x7ee0eeb8> (a java.lang.Object) "Parsing & Indexing Loop (201003190200)" daemon prio=10 tid=0x09889800 nid=0x52d1 waiting on condition [0xacb7b000] java.lang.Thread.State: RUNNABLE at java.lang.Integer.valueOf(Integer.java:625) at org.netbeans.modules.csl.core.TLIndexerFactory$TLIndexer.getLineStartOffsets(TLIndexerFactory.java:245) at org.netbeans.modules.csl.core.TLIndexerFactory$TLIndexer.index(TLIndexerFactory.java:231) at org.netbeans.modules.parsing.spi.indexing.Indexable$MyAccessor$3.run(Indexable.java:205) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater.runIndexer(RepositoryUpdater.java:231) at org.netbeans.modules.parsing.spi.indexing.Indexable$MyAccessor.index(Indexable.java:203) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Work$3.run(RepositoryUpdater.java:1885) at org.netbeans.modules.parsing.api.ParserManager$UserTaskAction.run(ParserManager.java:151) at org.netbeans.modules.parsing.api.ParserManager$UserTaskAction.run(ParserManager.java:135) at org.netbeans.modules.parsing.impl.TaskProcessor.runUserTask(TaskProcessor.java:190) at org.netbeans.modules.parsing.api.ParserManager.parse(ParserManager.java:103) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Work.indexEmbedding(RepositoryUpdater.java:1858) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Work.doIndex(RepositoryUpdater.java:1694) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Work.access$1200(RepositoryUpdater.java:1403) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Work$2.run(RepositoryUpdater.java:1571) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Work$2.run(RepositoryUpdater.java:1569) at org.netbeans.modules.parsing.impl.indexing.errors.TaskCache.refreshTransaction(TaskCache.java:450) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Work.index(RepositoryUpdater.java:1569) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$AbstractRootsWork.scanSource(RepositoryUpdater.java:3180) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$AbstractRootsWork.scanSources(RepositoryUpdater.java:3082) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$RootsWork.getDone(RepositoryUpdater.java:2833) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Work.doTheWork(RepositoryUpdater.java:1975) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Task._run(RepositoryUpdater.java:3552) at org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$Task.run(RepositoryUpdater.java:3494) at org.netbeans.modules.parsing.impl.TaskProcessor$CompilationJob.run(TaskProcessor.java:574) 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) "Inactive RequestProcessor thread [Was:TimedSoftReference/org.openide.util.TimedSoftReference]" daemon prio=10 tid=0x099ee800 nid=0x52b4 waiting for monitor entry [0xade4f000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1859) - waiting to lock <0x7e000730> (a java.util.Stack) - locked <0x7ec4fad0> (a java.lang.Object) "Inactive RequestProcessor thread [Was:Default RequestProcessor/org.netbeans.modules.ruby.railsprojects.ui.RailsLogicalViewProvider$RailsLogicalViewRootNode]" daemon prio=10 tid=0x099ee000 nid=0x52b3 waiting for monitor entry [0xae452000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1859) - waiting to lock <0x7e000730> (a java.util.Stack) - locked <0x7ec45970> (a java.lang.Object) "Inactive RequestProcessor thread [Was:Default RequestProcessor/null]" daemon prio=10 tid=0x099ed800 nid=0x52b2 waiting for monitor entry [0xaea55000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1859) - waiting to lock <0x7e000730> (a java.util.Stack) - locked <0x7ec4fb18> (a java.lang.Object) "Inactive RequestProcessor thread [Was:Recursive Listener Init/org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$RootsListeners$1]" daemon prio=10 tid=0x099ed000 nid=0x52b1 in Object.wait() [0xb1f65000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x7ec45a68> (a java.lang.Object) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1847) - locked <0x7ec45a68> (a java.lang.Object) "TimedSoftReference" daemon prio=10 tid=0x09b0ac00 nid=0x52ae runnable [0xaec56000] java.lang.Thread.State: RUNNABLE at org.openide.util.RequestProcessor$Processor.put(RequestProcessor.java:1802) - locked <0x7e000730> (a java.util.Stack) at org.openide.util.RequestProcessor.askForWork(RequestProcessor.java:599) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1884) - locked <0x7e00fbc0> (a java.lang.Object) "Inactive RequestProcessor thread [Was:Default RequestProcessor/null]" daemon prio=10 tid=0x09a29800 nid=0x52aa waiting for monitor entry [0xae251000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1859) - waiting to lock <0x7e000730> (a java.util.Stack) - locked <0x7eb45370> (a java.lang.Object) "Logging Flush" daemon prio=10 tid=0x09a02000 nid=0x52a6 runnable [0xae653000] java.lang.Thread.State: RUNNABLE at java.util.Arrays.copyOf(Arrays.java:2882) at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:100) at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:390) at java.lang.StringBuffer.append(StringBuffer.java:224) - locked <0x832befa8> (a java.lang.StringBuffer) at java.text.MessageFormat.subformat(MessageFormat.java:1208) at java.text.MessageFormat.format(MessageFormat.java:836) at java.text.Format.format(Format.java:140) at java.text.MessageFormat.format(MessageFormat.java:812) at java.util.logging.Formatter.formatMessage(Formatter.java:130) - locked <0x7dffffe0> (a org.netbeans.core.startup.TopLogging$NbFormatter) at org.netbeans.core.startup.TopLogging$NbFormatter.print(TopLogging.java:652) at org.netbeans.core.startup.TopLogging$NbFormatter.format(TopLogging.java:641) at java.util.logging.StreamHandler.publish(StreamHandler.java:179) - locked <0x7e00fe80> (a java.util.logging.StreamHandler) at org.netbeans.core.startup.TopLogging$NonClose.run(TopLogging.java:555) at org.openide.util.RequestProcessor$Task.run(RequestProcessor.java:1356) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1894) "DestroyJavaVM" prio=10 tid=0x0973e800 nid=0x5283 waiting on condition [0x00000000] java.lang.Thread.State: RUNNABLE "Inactive RequestProcessor thread [Was:Default RequestProcessor/org.netbeans.core.windows.FloatingWindowTransparencyManager$2]" daemon prio=10 tid=0x09afcc00 nid=0x529c waiting for monitor entry [0xaf7fc000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1859) - waiting to lock <0x7e000730> (a java.util.Stack) - locked <0x7e8e58b8> (a java.lang.Object) "AWT-EventQueue-1" prio=10 tid=0x09baf800 nid=0x529b runnable [0xaf9fd000] java.lang.Thread.State: RUNNABLE at java.lang.Throwable.getStackTraceElement(Native Method) at java.lang.Throwable.getOurStackTrace(Throwable.java:591) - locked <0x832bef80> (a org.openide.util.RequestProcessor$SlowItem) at java.lang.Throwable.getStackTrace(Throwable.java:582) at org.openide.util.RequestProcessor$SlowItem.fillInStackTrace(RequestProcessor.java:1722) at java.lang.Throwable.<init>(Throwable.java:181) at java.lang.Exception.<init>(Exception.java:29) at org.openide.util.RequestProcessor$Item.<init>(RequestProcessor.java:1665) at org.openide.util.RequestProcessor$SlowItem.<init>(RequestProcessor.java:1716) at org.openide.util.RequestProcessor$Task.schedule(RequestProcessor.java:1416) - locked <0x7e8e6548> (a java.lang.Object) at org.openide.util.RequestProcessor$Task.schedule(RequestProcessor.java:1394) at org.netbeans.core.TimableEventQueue.tick(TimableEventQueue.java:182) at org.netbeans.core.TimableEventQueue.dispatchEvent(TimableEventQueue.java:130) 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=10 tid=0x0989f800 nid=0x529a in Object.wait() [0xb117c000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x7e8d8b48> (a javax.swing.TimerQueue) at javax.swing.TimerQueue.run(TimerQueue.java:232) - locked <0x7e8d8b48> (a javax.swing.TimerQueue) at java.lang.Thread.run(Thread.java:619) "Thread-3" daemon prio=10 tid=0x09b43800 nid=0x5299 in Object.wait() [0xafbfe000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x7e7f4218> (a java.util.LinkedList) at java.lang.Object.wait(Object.java:485) at java.util.prefs.AbstractPreferences$EventDispatchThread.run(AbstractPreferences.java:1461) - locked <0x7e7f4218> (a java.util.LinkedList) "AWT-Shutdown" prio=10 tid=0x0989e800 nid=0x5295 in Object.wait() [0xb137d000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x7dffe828> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at sun.awt.AWTAutoShutdown.run(AWTAutoShutdown.java:265) - locked <0x7dffe828> (a java.lang.Object) at java.lang.Thread.run(Thread.java:619) "AWT-XAWT" daemon prio=10 tid=0x09879c00 nid=0x5293 runnable [0xb157e000] java.lang.Thread.State: RUNNABLE at java.lang.Long.valueOf(Long.java:557) at sun.awt.X11.XToolkit.callTimeoutTasks(XToolkit.java:1544) at sun.awt.X11.XToolkit.run(XToolkit.java:540) at sun.awt.X11.XToolkit.run(XToolkit.java:505) at java.lang.Thread.run(Thread.java:619) "Inactive RequestProcessor thread [Was:Default RequestProcessor/org.netbeans.core.windows.FloatingWindowTransparencyManager$2]" daemon prio=10 tid=0x0985d800 nid=0x5292 waiting for monitor entry [0xb177f000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1859) - waiting to lock <0x7e000730> (a java.util.Stack) - locked <0x7dffe980> (a java.lang.Object) "Java2D Disposer" daemon prio=10 tid=0x09854000 nid=0x5291 in Object.wait() [0xb1a74000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x7dffe9f0> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked <0x7dffe9f0> (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) "Inactive RequestProcessor thread [Was:Recursive Listener Init/org.netbeans.modules.parsing.impl.indexing.RepositoryUpdater$RootsListeners$1]" daemon prio=10 tid=0x0982f800 nid=0x528f waiting for monitor entry [0xb2167000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor$Processor.run(RequestProcessor.java:1859) - waiting to lock <0x7e000730> (a java.util.Stack) - locked <0x7dffec28> (a java.lang.Object) "CLI Requests Server" daemon prio=10 tid=0x0982e400 nid=0x528e runnable [0xb2367000] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390) - locked <0x7dffecc0> (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:965) "Active Reference Queue Daemon" daemon prio=10 tid=0x097fdc00 nid=0x528d in Object.wait() [0xb38f5000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x7dffee48> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked <0x7dffee48> (a java.lang.ref.ReferenceQueue$Lock) at org.openide.util.lookup.implspi.ActiveQueue$Impl.run(ActiveQueue.java:62) at java.lang.Thread.run(Thread.java:619) "Timer-0" daemon prio=10 tid=0x09801400 nid=0x528c waiting for monitor entry [0xb3af6000] java.lang.Thread.State: BLOCKED (on object monitor) at org.openide.util.RequestProcessor.enqueue(RequestProcessor.java:544) - waiting to lock <0x7e00fbc0> (a java.lang.Object) at org.openide.util.RequestProcessor$EnqueueTask.run(RequestProcessor.java:1311) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) "Low Memory Detector" daemon prio=10 tid=0x09770400 nid=0x5289 runnable [0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x0976e800 nid=0x5288 waiting on condition [0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0976cc00 nid=0x5287 waiting on condition [0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=10 tid=0x09764800 nid=0x5286 in Object.wait() [0xb46cb000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x7dfff090> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked <0x7dfff090> (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=0x09763000 nid=0x5285 waiting for monitor entry [0xb48cc000] java.lang.Thread.State: BLOCKED (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x7dffea18> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x7dffea18> (a java.lang.ref.Reference$Lock) "VM Thread" prio=10 tid=0x09761800 nid=0x5284 runnable "VM Periodic Task Thread" prio=10 tid=0x09774000 nid=0x528a waiting on condition JNI global references: 1823
Thanks. It seems that basically it's the JRuby process running the gem command that is taking the cycles; not sure why it takes so much time on your box (about 10 times more than on my box, but this was only with the bundled gems installed - the number of installed gems probably makes some difference). I'm not sure what can be done about this, but at minimum I should make the IDE gem runner to use the client mode for the JVM (this seems to one place where the IDE still doesn't specify it - you probably recall we solved this in other contexts for 6.8). If you run something like the following (replace the paths to java and jruby): /home/erno/java/jdk1.6.0_18/jre/bin/java -Xverify:none -da -Xmx512m -Xss1024k -classpath /home/erno/work/ruby-main/nbbuild/netbeans/ruby/jruby-1.4.0/lib/jruby.jar:/home/erno/work/ruby-main/nbbuild/netbeans/ruby/jruby-1.4.0/lib/profile.jar -Djruby.base=/home/erno/work/ruby-main/nbbuild/netbeans/ruby/jruby-1.4.0 -Djruby.home=/home/erno/work/ruby-main/nbbuild/netbeans/ruby/jruby-1.4.0 -Djruby.lib=/home/erno/work/ruby-main/nbbuild/netbeans/ruby/jruby-1.4.0/lib -Djruby.shell=/bin/sh -Djruby.script=jruby org.jruby.Main -I/home/erno/work/ruby-main/nbbuild/netbeans/ruby/jruby-1.4.0/lib /home/erno/work/ruby-main/nbbuild/netbeans/ruby/jruby-1.4.0/bin/gem list --local you should see the CPUs pegged. When run from the IDE it takes a bit more CPU cycles as the IDE automatically refreshes the file system for the gem folders after running the command, but that should be maybe +10% or so. I'm going to add the -client switch in any case, but can you also try how big difference adding the switch makes in your case? Thanks.
I set up a script to do my gem loading outside of the IDE where it uses the -client switch. The difference is unbelievable. I go from 100% CPU to mostly single digits with a few peaks in the low teens. The issue appears to be a general issue with the JVM on low power hyperthreading enabled CPU's. When the HT capabilities are discovered by the JVM, it decides to use the -server flag which simply kills performance. My personal recommendation is threefold for this: 1) Use the -client switch everywhere as a default. 2) Provide a mechanism within the configuration options to enable the -server flag if the machine is capable of doing so. 3) Provide some helpful text around the configuration setting defining what the flag does and how it can affect performance.
Thanks for testing this. I already meant to make the client switch the default everywhere before 6.8, but unfortunately there was some duplicate code (after an incomplete refactoring) so the gem runner still didn't use it. I've fixed that and got rid of the duplicated code in 36534a93a66d. That's interesting wrt. the server mode and low power CPUs, on my Core 2 Duo there was practically no difference between the modes. Wrt. 2), if you explicitly specify the -server option in the JVM args the IDE will preserve it, otherwise the client switch is used. A more user friendly way would be nice of course. I'm closing this as fixed as per 36534a93a66d.
Integrated into 'main-golden', will be available in build *201003240200* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress) Changeset: http://hg.netbeans.org/main/rev/36534a93a66d User: Erno Mononen <emononen@netbeans.org> Log: #182261 - [69cat] Reloading gem list takes 2 CPU box to 100% on both CPUs - using the -client switch when running the gem tool - removed duplicated code in RPC and ExecutionUtils