This page last changed on Jun 11, 2008 by smaddox.

Symptom

  • Slow response times and/or out-of-date issue results from searches and in issue navigator and portlets.
  • The JIRA log file (e.g. catalina.out for Tomcat) contains output similar to the following:
2007-05-10 09:39:53,580 TP-Processor68 ERROR [jira.issue.index.DefaultIndexManager] Lock attempt timed out - waited 30000 milliseconds
com.atlassian.jira.issue.index.IndexException: Lock timout - waited 30000 milliseconds
    at com.atlassian.jira.issue.index.DefaultIndexManager.getIndexLock(DefaultIndexManager.java:451)
    at com.atlassian.jira.issue.index.DefaultIndexManager.reIndexIssues(DefaultIndexManager.java:279)
    at com.atlassian.jira.issue.index.DefaultIndexManager.reIndexIssues(DefaultIndexManager.java:244)
  .
  .
  .

followed by, at the end of the stack trace:

2007-05-10 09:39:53,608 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper] ************* Start Thread Dump 1178807993608 *******************
2007-05-10 09:39:53,608 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]  -- Memory Details --
2007-05-10 09:39:53,608 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper] Total Memory = 2023MB
2007-05-10 09:39:53,608 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper] Used Memory = 1360MB
2007-05-10 09:39:53,608 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper] Free Memory = 663MB
2007-05-10 09:39:53,608 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]  --- --- --- ---
2007-05-10 09:39:53,609 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper] Thread= TP-Processor15 daemon prio=5id=60 RUNNABLE
2007-05-10 09:39:53,609 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.net.SocketInputStream.socketRead0(Native Method)
2007-05-10 09:39:53,609 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.net.SocketInputStream.read(SocketInputStream.java:129)
2007-05-10 09:39:53,609 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
2007-05-10 09:39:53,609 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.io.BufferedInputStream.read1(BufferedInputStream.java:256)
2007-05-10 09:39:53,609 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.io.BufferedInputStream.read(BufferedInputStream.java:313)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    org.apache.jk.common.ChannelSocket.read(ChannelSocket.java:620)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    org.apache.jk.common.ChannelSocket.receive(ChannelSocket.java:558)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:685)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:889)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.lang.Thread.run(Thread.java:595)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]  --- --- --- ---
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper] Thread= http-8588-Processor5 daemon prio=5id=22 WAITING
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.lang.Object.wait(Native Method)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.lang.Object.wait(Object.java:474)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:656)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.lang.Thread.run(Thread.java:595)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]  --- --- --- ---
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper] Thread= TP-Processor45 daemon prio=5id=96 RUNNABLE
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.net.SocketInputStream.socketRead0(Native Method)
2007-05-10 09:39:53,610 TP-Processor68 ERROR [jdk.utilities.threaddump.ThreadDumper]    java.net.SocketInputStream.read(SocketInputStream.java:129)
  .
  .
  .

What is going on?

A Lucene index lock timeout has occurred. JIRA v3.7 and later automatically performs a thread dump (into the log file) in the event of index lock timeouts.

The thread dump is only generated if JIRA is running with JDK 1.5 or later. JDK 1.4 and earlier do not support programmatically generating a thread dump.

See Indexing in JIRA for a description of Lucene indexing, index locks, and index lock timeout.

What can you do?

Again, read Indexing in JIRA for common causes of poor indexing performance. If you still need help after that, create a support request. We are here to help. Make sure you include the log file.

If you like getting your hands dirty...

If you are from a software development background, and you would like to know more about what is going on, read on...

If you are keen, but you are not familiar with how to interpret Java stack traces and thread dumps, this article will help.

It is useful to know which thread had the lock when the timeout occurred. Look for a thread in a runnable state that contains Atlassian specific code. For example, the following output indicates that a Bulk Edit operation had the lock when the timeout occurred:

Thread= TP-Processor57 daemon prio=5id=108 RUNNABLE
	java.io.RandomAccessFile.writeBytes(Native Method)
	java.io.RandomAccessFile.write(RandomAccessFile.java:456)
	org.apache.lucene.store.FSIndexOutput.flushBuffer(FSDirectory.java:498)
	org.apache.lucene.store.BufferedIndexOutput.flush(BufferedIndexOutput.java:84)
	org.apache.lucene.store.BufferedIndexOutput.writeBytes(BufferedIndexOutput.java:74)
	org.apache.lucene.index.CompoundFileWriter.copyFile(CompoundFileWriter.java:211)
	org.apache.lucene.index.CompoundFileWriter.close(CompoundFileWriter.java:168)
	org.apache.lucene.index.SegmentMerger.createCompoundFile(SegmentMerger.java:145)
	org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:706)
	org.apache.lucene.index.IndexWriter.mergeSegments(IndexWriter.java:658)
	org.apache.lucene.index.IndexWriter.optimize(IndexWriter.java:517)
	com.atlassian.bonnie.ConcurrentLuceneConnection$2.perform(ConcurrentLuceneConnection.java:120)
	com.atlassian.bonnie.ConcurrentLuceneConnection.withWriter(ConcurrentLuceneConnection.java:296)
	com.atlassian.bonnie.ConcurrentLuceneConnection.optimize(ConcurrentLuceneConnection.java:116)
	com.atlassian.jira.issue.index.SingleThreadedIssueIndexer.optimize(SingleThreadedIssueIndexer.java:75)
	com.atlassian.jira.issue.index.DefaultIndexManager.optimize0(DefaultIndexManager.java:393)
	com.atlassian.jira.issue.index.DefaultIndexManager.optimizeIfNecessary(DefaultIndexManager.java:332)
	com.atlassian.jira.issue.index.DefaultIndexManager.reIndexIssues(DefaultIndexManager.java:288)
	com.atlassian.jira.issue.index.DefaultIndexManager.reIndexIssues(DefaultIndexManager.java:244)
	com.atlassian.jira.issue.index.DefaultIndexManager.reIndex(DefaultIndexManager.java:264)
	com.atlassian.jira.event.listeners.search.IssueIndexListener.reIndex(IssueIndexListener.java:114)
	com.atlassian.jira.event.listeners.search.IssueIndexListener.reIndex(IssueIndexListener.java:124)
	com.atlassian.jira.event.listeners.search.IssueIndexListener.issueUpdated(IssueIndexListener.java:55)
	com.atlassian.jira.event.issue.AbstractIssueEventListener.workflowEvent(AbstractIssueEventListener.java:104)
	com.atlassian.jira.event.issue.IssueEventDispatcher.dispatchEvent(IssueEventDispatcher.java:107)
	com.atlassian.jira.event.issue.IssueEventDispatcher.dispatchEvent(IssueEventDispatcher.java:88)
	com.atlassian.jira.issue.util.DefaultIssueUpdater.doUpdate(DefaultIssueUpdater.java:63)
	com.atlassian.jira.action.issue.AbstractIssueUpdateAction.doUpdate(AbstractIssueUpdateAction.java:137)
	com.atlassian.jira.action.issue.AbstractIssueUpdateAction.doUpdate(AbstractIssueUpdateAction.java:127)
	com.atlassian.jira.action.issue.IssueUpdate.doExecute(IssueUpdate.java:75)
	webwork.action.ActionSupport.execute(ActionSupport.java:153)
	com.atlassian.jira.action.JiraActionSupport.execute(JiraActionSupport.java:54)
	com.atlassian.jira.action.JiraNonWebActionSupport.execute(JiraNonWebActionSupport.java:27)
	webwork.dispatcher.GenericDispatcher.executeAction(GenericDispatcher.java:132)
	com.atlassian.core.action.DefaultActionDispatcher.execute(DefaultActionDispatcher.java:34)
	com.atlassian.jira.bulkedit.operation.BulkEditOperation.perform(BulkEditOperation.java:199)
	com.atlassian.jira.web.action.issue.bulkedit.BulkEdit.doPerform(BulkEdit.java:164)
        .
        .
        .

The actual root problem is probably specific to your issue. If you are keen, this might give you enough information to diagnose what is going on. Remember though, Atlassian support is ready to help you.

Related

Logging a thread dump also contains a thread dump analyzer TDA 1.0 Final

Document generated by Confluence on Oct 06, 2009 00:26