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.

    Friday, September 17, 2010

    Is there a silver bullet to improve intellij indexing performance?

    Its known that Intellij indexing is I/O intensive. Upgrading to a faster storage device like solid-state device seems to be a silver bullet that solves Intellij indexing performance issues. Here are few reasons why this is not the case and why upgrading to SSD doesnt necessarily solve indexing problems:

    Write performance of SSD is quite different from read performance. For random accesses of read operations, SSD performs much better than typical hard-disk. Where as, performance of SSD and hard-disk are almost similar in-case of sequential read operations. Problematic area with SSD is write operations. SSD performs writes at 'erase block' level. It merges write data with data in erase block, basically write operations are at erase block level. Erase blocks will be 1-4MB in size. As a result write performance of SSD is worse compared to typical hard-disks. To make things worse, existing file systems are not optim ized for SSDs. There are few file systems, like ZFS (for solaris) which is optimized for SSD. Here is example to illustrate the effect of write operations on performance of SSD: Intel X25 flash SSD input/output operations per second (IOPS) drops from ~2000 IOPS in pure read mode to ~700 IOPS in 80/20 read/write on 8k blocks. A typical hard-disk can perform ~200 IOPS. (Refer to the following articles for further information related to SSD.)

    Just like input/output has been neglected in compute architecture; it has been neglected in profiling world also. Very few tools are available for input/output profiling of a process. These tools are rudimentary and some collect information from /proc/<pid>/io. These tools does not provide any information on number of read operations, write operations performed by a process. Read/write data volume or, read/write rates is not recommended way of measuring I/O performance. Refer to these articles to know why.

    If we know the mix of read/write operations performed by Intellij, then we could compute effective performance improvement/degradation because of SSD. As we dont know mix of read/write operations, only way to measure the improvement of SSD is by running build/indexing etc with SSD and without SSD. The amount of time taken to build community edition index remained almost same with and without SSD. Here are index times for community edition on 8GB machine, 64-bit JVM and using Intellij 10.5

    Storage Device
    Num Files
    Scanning Files Time
    (secs)
    Indexing Time
    (secs)
    SSD
    78144
    24.51
    128.71
    HardDisk drive
    78144
    15.69
    141.1
    Index times of Intellij community edition code using SSD, normal hard-disk. (Avg of 10 runs)

    To summarize, SSD will be a silver bullet that solves intellij indexing problems only if the underlying filesystem is optimized for SSDs (like ZFS of solaris), number read operations performed is lot more than number of write operations. Till then, we need to find alternate solutions to fix intellij indexing performance issues.

    Some more observations and notes related I/O profiling:

    /proc/<pid>/io contains information about I/O done by the process. Here is amount of I/O performed by Intellij (during rebuild of Intellij community edition): (Refer to proc help to know the terminology used in io file)

    rchar: 4263207814
    wchar: 1363709925
    syscr: 4788271
    syscw: 1342145
    read_bytes: 1504063488
    write_bytes: 3310067712
    cancelled_write_bytes: 405561344

    read_bytes represents number of bytes this process really caused to be read from storage (~1.5GB). write_bytes represents number of bytes this process really caused to be written to storage (~3 GB).
    wchar - The number of bytes which this process has caused to be written is less than write_bytes -

    I/O Profiling Tools:
    collectl can be used to monitor I/O on a system. This has capabilities similar to top command.