Monday, April 18, 2011

Using Thread-dumps to Analyze Unresponsive Intellij UI

One of the frequently faced problems by Intellij users is - Intellij UI either does not respond or responds very slowly. Debugging these Intellij UI slowness issue is bit tricky as it is difficult to reproduce these issues on developer's machines. One solution is - Intellij user collects thread dumps when Intellij is slow and later Intellij developer analyzes these thread dumps to find out root cause of UI unresponsiveness. This blog post covers the following topics:
  • Using thread dumps to analyze Intellij UI unresponsiveness.
  • References to thread dump analyzers, blogs, etc.
  • Other tools - btrace to instrument intellij, yourkit profiler, etc.

Using thread dumps to analyze Intellij UI unresponsiveness:
Thread dumps are very helpful in finding root cause of unresponsive intellij UI. Thread dumps can be collected using jstack <pid>.  It is advised to collect few thread dumps instead of single thread dump as set of thread dumps are more useful in analyzing UI unresponsiveness than a single thread dump.

Here are few scenarios where intellij UI gets unresponsive:

  • AWT-EventQueue thread (aka UI thread) performing lot of computation
  • Other threads in Runnable state are doing lot of computation consuming ~100% of CPU
  • Other reasons (eg., indexing thread gets in to perpetual sleep-state due to out-of-memory exceptions resulting in very slow indexing)
Note that this list is not exhaustive. Here are few example thread dumps along with their analysis:


AWT-EventQueue thread performing lot of computation
Few scenarios where UI thread performs lot of computation instead of delegating to other threads are: i) indexing in foreground (instead of background), ii) lot of graphics related operations.


UI thread doing indexing in foreground:

"AWT-EventQueue-1 9.0.4#IU-95.627, eap:false"at com.intellij.pom.tree.events.impl.TreeChangeEventImpl.c(TreeChangeEventImpl.java:214)
at com.intellij.pom.tree.events.impl.TreeChangeEventImpl.b(TreeChangeEventImpl.java:193)
...
at com.intellij.lang.impl.PsiBuilderImpl.getTreeBuilt(PsiBuilderImpl.java:650)
at com.intellij.lang.javascript.parsing.JSParser.parse(JSParser.java:49)
at com.intellij.psi.tree.IFileElementType.parseContents(IFileElementType.java:43)
at com.intellij.psi.impl.source.tree.LazyParseableElement.b(LazyParseableElement.java:158)
at com.intellij.psi.impl.source.tree.LazyParseableElement.getFirstChildNode(LazyParseableElement.java:177)
at com.intellij.psi.impl.source.tree.LazyParseableElement.getFirstChildNode(LazyParseableElement.java:29)
at com.intellij.psi.impl.source.text.BlockSupportImpl.mergeTrees(BlockSupportImpl.java:250)
...
at java.awt.EventDispatchThread.run(EventDispatchThread.java:138)

Analysis:
Intellij is indexing in foreground which is blocking the UI thread. Normally, intellij indexes in background without blocking the UI thread. This seems to be an issue with javascript plugin. This is reported here (http://youtrack.jetbrains.net/issue/IDEA-66699)

Turning off synchronize files on frame activation, closing structure view seems to avoid some of these foreground indexing related issues.

UI thread performing lot of graphics related operations:

"AWT-EventQueue-1 9.0.3#IU-95.429, eap:false" prio=10 tid=0x60dfb400 nid=0x5b1f runnable [0x5fffd000..0x5fffee84]
java.lang.Thread.State: RUNNABLE
at sun.java2d.loops.MaskFill.MaskFill(Native Method)
at sun.java2d.pipe.AlphaColorPipe.renderPathTile(AlphaColorPipe.java:55)
at sun.java2d.pipe.AAShapePipe.renderPath(AAShapePipe.java:135)
at sun.java2d.pipe.AAShapePipe.fill(AAShapePipe.java:65)
at sun.java2d.pipe.PixelToShapeConverter.fillRect(PixelToShapeConverter.java:62)
at sun.java2d.pipe.ValidatePipe.fillRect(ValidatePipe.java:76)
at sun.java2d.SunGraphics2D.fillRect(SunGraphics2D.java:2319)
...
at java.awt.EventDispatchThread.run(EventDispatchThread.java:138)

Analysis:
   This mostly happens when you are using OpenJDK (instead of SunJDK). Disabling pmoffscreen flag seems to solve intellij rendering issues. (-Dsun.java2d.pmoffscreen=false).

Threads in Runnable state are consuming ~100% CPU
Some times threads in Runnable state consume ~100% of CPU resulting in unresponsive UI. If  version control system mappings are incorrect and if they map your entire repository instead of specific directories, intellij starts scanning all the files under your repository which results in unresponsive UI.

Runnable thread scanning entire repository and unresponsive UI thread at that time."
Alarm pool(own)" prio=10 tid=0x59d72800 nid=0x11e3 runnable [0x5b9ad000..0x5b9ae184] java.lang.Thread.State: RUNNABLE
at java.io.UnixFileSystem.getLastModifiedTime(Native Method)
at java.io.File.lastModified(File.java:843)
at com.intellij.openapi.vfs.impl.local.LocalFileSystemBase.getTimeStamp(LocalFileSystemBase.java:144)
...
at com.intellij.openapi.vfs.newvfs.persistent.PersistentFS.list(PersistentFS.java:127)
at com.intellij.openapi.vfs.newvfs.persistent.PersistentFS.listIds(PersistentFS.java:190)
at com.intellij.openapi.vfs.newvfs.impl.VirtualDirectoryImpl.getChildren(VirtualDirectoryImpl.java:199)
...
at git4idea.vfs.GitRootTracker.hasUnmappedSubroots(GitRootTracker.java:322)
...
at java.lang.Thread.run(Thread.java:636)

"AWT-EventQueue-1 9.0.2#IU-95.66, eap:false" prio=10 tid=0x0834e000 nid=0x4dd1 in Object.wait() [0x5c569000..0x5c569e84] java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method) - waiting on <0x67211fb8> (a com.intellij.util.concurrency.WriterPreferenceReadWriteLock$WriterLock)
...
at java.awt.EventDispatchThread.run(EventDispatchThread.java:138)


Analysis:
Its difficult to identify root cause of this issue without looking at the files being visited by intellij. You can use btrace to find out files being visited by intellij. In the above example, btrace displayed files being visited by Intellij and from that we came to know that Intellij is scanning entire source repository due to incorrect version control mappings. This can be fixed by correctly mapping required source repositories directories to Intellij's VCS mappings.

Other Scenarios

There are other scenarios where Intellij gets slow. These could be slow indexing, UI is unresponsive due to a dead-lock caused by shared resource like userPrefs.

Slow indexing due to indexing thread getting into perpetual sleep due to OutOfMemory error:

"ApplicationImpl pooled thread" prio=10 tid=0x1790e000 nid=0xcc5 waiting on condition [0x192ab000..0x192ac0c4]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method) at sun.nio.ch.FileChannelImpl.map(FileChannelImpl.java:795)
at com.intellij.util.io.ReadWriteMappedBufferWrapper.map(ReadWriteMappedBufferWrapper.java:48)
at com.intellij.util.io.MappedBufferWrapper.buf(MappedBufferWrapper.java:68)
...
at com.intellij.util.indexing.FileBasedIndex.indexFileContent(FileBasedIndex.java:1293)
...
at com.intellij.openapi.application.impl.ApplicationImpl$1$1.run(ApplicationImpl.java:125)
Analysis:
In the given thread dump, indexing thread is in sleep state (TIMED_WAITING => due to .sleep() call) From FileChannelImpl.java source (line: 795): sun.nio.ch.FileChannelImpl.map() threw OutOfMemoryError - inside try/catch block, garbage collector is invoked and indexing thread put to sleep for 100ms. This results in slow indexing of the project.


UI gets hung due to deadlock caused by shared resource:
at java.awt.EventDispatchThread.run(EventDispatchThread.java:121)
"AWT-EventQueue-1 9.0.4#IU-95.627, eap:false" prio=10 tid=0x243be400 nid=0x2971 in Object.wait() [0x22f6a000..0x22f6af80]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x40474b20> (a com.intellij.util.concurrency.WriterPreferenceReadWriteLock$WriterLock)
at java.lang.Object.wait(Object.java:485)
at com.intellij.util.concurrency.WriterPreferenceReadWriteLock$WriterLock.acquire(WriterPreferenceReadWriteLock.java:241)
- locked <0x40474b20> (a com.intellij.util.concurrency.WriterPreferenceReadWriteLock$WriterLock)
at com.intellij.openapi.application.impl.ApplicationImpl.runWriteAction(ApplicationImpl.java:741)
...
at com.intellij.openapi.options.SchemesManagerImpl.save(SchemesManagerImpl.java:725)
Analysis:
Just stack trace is not sufficient to analyze this issue. We need to find out the file being used by intellij. You can use either btrace or strace to find file being used by intellij.

Intellij uses java.util.prefs, which by default writes data to ~/.java/.userPrefs/ and uses ~/.java/.userPrefs/.user.lock.<username> as a lock. It does this writing from the AWT thread, causing a hung UI.

Work-around:
Change intellij to use local disk instead of your home directory for prefs by adding this line to your idea.vmoptions:
-Djava.util.prefs.userRoot=/usr/local/google/<username>/

Thread dump analysis tools:
  • Categorizes threads based on state 
  • Checks for deadlocks
Blogs, documents on thread dump analysis
Has good amount of information about thread dumps; comments on this blog point to other sources on thread dumps.
Introductory article on Java stack traces, explains different
On how to diagnose java resource starvation using ibm thread dump analysis tool.
    Appendix: Using btrace to find out files being visited by Intellij
    Look at sample btrace files to find out how to trace a running java process.

    Usage:
        btrace <pid> <instrumentation file> 

    Here is code for LastModified.java which prints files being visited by intellij.
    1:  import com.sun.btrace.annotations.*;  
    2:  import static com.sun.btrace.BTraceUtils.*;  
    3:  import java.io.File;  
    4:  // every time File.lastModified is called, print the file name  
    5:  @BTrace  
    6:  public class LastModified {  
    7:    @OnMethod(  
    8:    clazz="java.io.File", method="lastModified"  
    9:    )  
    10:   public static void onLastModified(File self) {  
    11:     print("got timestamp for: ");  
    12:     println(self);  
    13:   }  
    14: }  
    Notes on btrace:
    1. btrace accepts 'pure' read-only tracing programs. So, its not possible to invoke methods on objects passed to a method being traced. BTraceUtils provides utility functions (like: print, str, strcat etc), we need to use only those functions in the btrace tracing program.
    2. You can access fields/members of parameters, but you are not allowed to invoke methods on parameters. http://kenai.com/projects/btrace/forums/forum/topics/1366-Drilling-into-a-method-argument-s-properties
    3. Sample btrace programs at: http://kenai.com/projects/btrace/sources/hg/show/samples
    When to use btrace?
    Btrace is useful for cases
    i) there is no other way of instrumenting it (like: java.* classes)
    ii) you are doing a simple operations like: get params, compute time taken, etc.

    Its not suited for cases where you want to do
     i) some processing (invoke methods on params) to gather required data,
    ii) capture local/temp variable data.
    Ex:- FileBasedIndex.indexFileContent() - here we would like capture file name, size of file and time taken to index that. But, file name, size of file are not passed as params to indexFileContent(). Computing these values involves invoking methods on the parameters, which is not allowed by btrace. In this case, better option is to modify source code of FileBasedIndex and add the required logging information.