We updated our Jira Data Center server from 7.19 to 8.13 (stable release) 2 month ago. Our Jira has been clustered in three nodes. All problems were started from when we re-indexed first node. Because our Jira server has thousands issue we have chosen full re-index method.
After that we are always faced with many problems such as full GC (we know Full GC is part of a normal process) but take it too long and subsequently being very slow Jira or sometime have a high CPU or memory doesn’t leave any choices for us unless we restart the Jira Machin.
We have been looking for a specific cause or reason, we don’t know which one of them (log information) are more related or more effective in our service failure.
I want to send you some log information before, during or after problem from all files which Jira saves log in it.
If you need more information from each aspect of server or resources or configurations. Please don’t hesitate to contact us. We would appreciate in advance for any guidance or point that help us to resolve this problem as soon as possible.
We don’t have a right clue for any errors that always happen in our Jira, but I have tried to put them in our request for help.
- We usually see this Error in our atlassian-jira.log:
Caused by: java.rmi.UnmarshalException: Error unmarshaling return header; nested exception is:
java.net.SocketTimeoutException: Read timed out
at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:229)
at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:162)
at net.sf.ehcache.distribution.RMICachePeer_Stub.put(Unknown Source)
- Also after reindex each node we have some error like this:
2021-07-27 16:28:13,526+0430 ISSUE-indexQueue:thread-1 WARN administrator x.x.x.x lztjsx xx.xx.xx.xx /secure/admin/IndexReIndex!reindex.jspa [c.a.jira.index.MonitoringIndexWriter] Detected frequent flushes (every 536 millis) of lucene index which is below warning limit: jira.index.warn.flush.min.interval.millis=1000 millis. This may affect indexing performance. Please visit https://confluence.atlassian.com/x/w0VwOQ for more information.
- Also we have some problem might relate to structure but we are not sure:
2021-07-31 11:26:05,629+0430 https-jsse-nio-8443-exec-4 INFO some_username686x14226596x4 e25akj xx.xx.xx.xx,xx.x.x.x /secure/QueryComponentRendererValue!Default.jspa [
c.a.j.i.s.searchers.transformer.DateSearchInputTransformer] Unable to parse date '1400/04/31'.
2021-07-31 11:26:09,829+0430 https-jsse-nio-8443-exec-105 INFO some_username686x14226679x7 e25akj xx.xx.xx.xx,xx.xx.xx.xx/secure/QueryComponentRendererValue!Default.jspa
[c.a.j.i.s.searchers.transformer.DateSearchInputTransformer] Unable to parse date '1400/04/31'.
2021-07-31 11:26:16,799+0430 ClusterMessageHandlerServiceThread:thread-1 INFO anonymous [c.a.jira.index.MonitoringIndexWriter] [lucene-stats] flush stats: snapshotC
ount=6, totalCount=52783, periodSec=384, flushIntervalMillis=64000, snapshotNoDocs=2, totalNoDocs=20402, indexDirectory=null, indexWriterId=com.atlassian.jira.index.Mon
itoringIndexWriter@12f14318, indexDirectoryId=RAMDirectory@3d4ca07f lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@76555f5b
2021-07-31 11:26:18,839+0430 https-jsse-nio-8443-exec-27 INFO some_username 686x14226943x7 1ko32mb 10.25.113.36,xx.xx.xx.xx/rest/servicedesk/1/CINS/webfragments/sections/sd-
queues-nav,servicedesk.agent.queues,servicedesk.agent.queues.ungrouped [c.a.jira.index.MonitoringIndexWriter] [lucene-stats] flush stats: snapshotCount=235, totalCount=
250246, periodSec=300, flushIntervalMillis=1278, snapshotNoDocs=21328, totalNoDocs=4518291, indexDirectory=/opt/atlassian/application-data/jira/caches/indexesV1/changes
, indexWriterId=com.atlassian.jira.index.MonitoringIndexWriter@7c947a16, indexDirectoryId=MMapDirectory@/opt/atlassian/application-data/jira/caches/indexesV1/changes lo
ckFactory=org.apache.lucene.store.NativeFSLockFactory@3fe9cf3c
2021-07-31 11:26:21,755+0430 NodeReindexServiceThread:thread-0 INFO [c.a.jira.index.MonitoringIndexWriter] [lucene-stats] flush stats: snapshotCount=489, totalCoun
t=309884, periodSec=302, flushIntervalMillis=618, snapshotNoDocs=0, totalNoDocs=0, indexDirectory=/opt/atlassian/application-data/jira/caches/indexesV1/issues, indexWri
terId=com.atlassian.jira.index.MonitoringIndexWriter@20dc88e7, indexDirectoryId=MMapDirectory@/opt/atlassian/application-data/jira/caches/indexesV1/issues lockFactory=o
rg.apache.lucene.store.NativeFSLockFactory@3fe9cf3c
2021-07-31 11:26:21,757+0430 NodeReindexServiceThread:thread-0 WARN [c.a.jira.index.MonitoringIndexWriter] Detected frequent flushes (every 618 millis) of lucene i
ndex which is below warning limit: jira.index.warn.flush.min.interval.millis=1000 millis. This may affect indexing performance. Please visit https://confluence.atlassia
n.com/x/w0VwOQ for more information.
2021-07-31 11:26:26,291+0430 Structure-Jobs4ae6e2ec Attribute-Thread#15240 WARN some_username 1145x13165457x1 1jfkcgt xx.xx.xx.xx,xx.xx.xx.xx/rest/structure/2.0/attribute
/subscription [c.a.j.structure.attribute.AttributeLoaderInfo] 41 warnings from expr:{"variables":{"issuekey":{"id":"key","format":"text"},"issueage":{"id":"sum","params":{"attribute":{"id":"expr","format":"any","params":{"formula":"if(and(issuekey,or(eq(status,\"Reject Request\"),eq(status,\"closed شده\"))),minus(latesttransdone,firsttransinprogress),and(issuekey,ne(statuscategory,\"to do\")),minus(now(),firsttransinprogress))","variables":{"firsttransinprogress":{"id":"transition-date","params":{"transition":"first","category":"indeterminate"},"format":"time"},"latesttransdone":{"id":"transition-date","params":{"transition":"latest","category":"done"},"format":"time"},"status":{"id":"status","format":"text"},"issuekey":{"id":"key","format":"text"},"statuscategory":{"id":"status-category","format":"text"}}}}},"format":"number"},"leaves":{"id":"count","params":{"leaves":true},"format":"number"}},"formula":"issueage"}:number were not shown
2021-07-31 11:26:26,291+0430 Structure-Jobs4ae6e2ec Attribute-Thread#15240 WARN some_username1145x13165457x1 1jfkcgt xx.xx.xx.xx,xx.xx.xx.xx/rest/structure/2.0/attribute/subscription [c.a.j.structure.attribute.AttributeLoaderInfo] expr:{"variables":{"issuekey":{"id":"key","format":"text"},"issueage":{"id":"sum","params":{"attribute":{"id":"expr","format":"any","params":{"formula":"if(and(issuekey,or(eq(status,\"Reject Request\"),eq(status,\"closed شده\"))),minus(latesttransdone,firsttransinprogress),and(issuekey,ne(statuscategory,\"to do\")),minus(now(),firsttransinprogress))","variables":{"firsttransinprogress":{"id":"transition-date","params":{"transition":"first","category":"indeterminate"},"format":"time"},"latesttransdone":{"id":"transition-date","params":{"transition":"latest","category":"done"},"format":"time"},"status":{"id":"status","format":"text"},"issuekey":{"id":"key","format":"text"},"statuscategory":{"id":"status-category","format":"text"}}}}},"format":"number"},"leaves":{"id":"count","params":{"leaves":true},"format":"number"}},"formula":"issueage"}:number loader does not declare context dependency CURRENT_TIME
2021-07-31 11:26:26,367+0430 Structure-Jobs4ae6e2ec Attribute-Thread#15240 WARN some_username1145x13165457x1 1jfkcgt xx.xx.xx.xx,xx.xx.xx.xx/rest/structure/2.0/attribute/subscription [c.a.j.structure.attribute.AttributeLoaderInfo] 25068 warnings from -non-unique-items:{"type":"leaves","attribute":{"id":"expr","format":"number","params":{"variables":{"issuekey":{"id":"key","format":"text"},"issueage":{"id":"sum","params":{"attribute":{"id":"expr","format":"any","params":{"formula":"if(and(issuekey,or(eq(status,\"Reject Request\"),eq(status,\"closed شده\"))),minus(latesttransdone,firsttransinprogress),and(issuekey,ne(statuscategory,\"to do\")),minus(now(),firsttransinprogress))","variables":{"firsttransinprogress":{"id":"transition-date","params":{"transition":"first","category":"indeterminate"},"format":"time"},"latesttransdone":{"id":"transition-date","params":{"transition":"latest","category":"done"},"format":"time"},"status":{"id":"status","format":"text"},"issuekey":{"id":"key","format":"text"},"statuscategory":{"id":"status-category","format":"text"}}}}},"format":"number"},"leaves":{"id":"count","params":{"leaves":true},"format":"number"}},"formula":"issueage"}
- We have frequently Error like below in the all nodes:
021-07-27 16:31:12,528+0430 localq-reader-20 ERROR[c.a.j.c.distribution.localq.LocalQCacheOpReader] [LOCALQ] [VIA-COPY] Abandoning sending: LocalQCacheOp{cacheName='com.atlassian.jira.cluster.dbr.DBR
Message', action=PUT, key=DBR, value == null ? false, replicatePutsViaCopy=true, creationTimeInMillis=1627387257441} from cache replication queue: [queueId=queue_Node1_9_400f9eeb84980be1750162a139bd36fc_put
, queuePath=/opt/atlassian/application-data/jira/localq/queue_Node1_9_400f9eeb84980be1750162a139bd36fc_put], failuresCount: 1/1. Removing from queue. Error: java.rmi.UnmarshalException: Error
2021-07-27 16:31:12,528+0430 localq-reader-20 ERROR[c.a.j.c.distribution.localq.LocalQCacheOpReader] [LOCALQ] [VIA-COPY] Abandoning sending: LocalQCacheOp{cacheName='com.atlassian.jira.cluster.dbr.DBR
Message', action=PUT, key=DBR, value == null ? false, replicatePutsViaCopy=true, creationTimeInMillis=1627387257441} from cache replication queue: [queueId=queue_Node1_9_400f9eeb84980be1750162a139bd36fc_put
, queuePath=/opt/atlassian/application-data/jira/localq/queue_Node1_9_400f9eeb84980be1750162a139bd36fc_put], failuresCount: 1/1. Removing from queue. Error: java.rmi.UnmarshalException: Error unmarshaling r
eturn header; nested exception is:
java.net.SocketTimeoutException: Read timed out
com.atlassian.jira.cluster.distribution.localq.LocalQCacheOpSender$UnrecoverableFailure: java.rmi.UnmarshalException: Error unmarshaling return header; nested exception is:
java.net.SocketTimeoutException: Read timed out
at com.atlassian.jira.cluster.distribution.localq.rmi.LocalQCacheOpRMISender.send(LocalQCacheOpRMISender.java:90)
at com.atlassian.jira.cluster.distribution.localq.LocalQCacheOpReader.run(LocalQCacheOpReader.java:96)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2021-07-27 17:23:31,026+0430 RMI TCP Connection(54913)-10.x.x.1xx ERROR[c.a.j.issue.index.DefaultIndexManager] Wait attempt timed out - waited 30000 milliseconds
com.atlassian.jira.issue.index.IndexException: Wait attempt timed out - waited 30000 milliseconds
at com.atlassian.jira.issue.index.DefaultIndexManager.obtain(DefaultIndexManager.java:872)
at com.atlassian.jira.issue.index.DefaultIndexManager.await(DefaultIndexManager.java:843)
(**) please attention to last description
- Before Jira fall into Full-GC until to become a slow and unusable Jira server, we have frequently Error same this:
2021-07-27 17:23:31,026+0430 RMI TCP Connection(54913)-1x.x.x.1 ERROR[c.a.j.issue.index.DefaultIndexManager] Wait attempt timed out - waited 30000 milliseconds
com.atlassian.jira.issue.index.IndexException: Wait attempt timed out - waited 30000 milliseconds
at com.atlassian.jira.issue.index.DefaultIndexManager.obtain(DefaultIndexManager.java:872)
at com.atlassian.jira.issue.index.DefaultIndexManager.await(DefaultIndexManager.java:843)
unlike increase timeout 3000 to 9000 was not applied
2021-07-22 00:48:59,599+0430 pool-39-thread-3 WARN [p.c.j.cpsa4j.lucene.AttachmentIndexManager] Wait attempt interrupted. [org.apache.lucene.store.LockObtainFailed
Exception: Lock held by this virtual machine: /opt/atlassian/application-data/jira/caches/indexesV1/attachments/write.lock] (RuntimeIOException).
com.atlassian.jira.util.RuntimeIOException: org.apache.lucene.store.LockObtainFailedException: Lock held by this virtual machine: /opt/atlassian/application-data/jira/c
aches/indexesV1/attachments/write.lock
at com.atlassian.jira.index.WriterWrapper$1.get(WriterWrapper.java:85)
at com.atlassian.jira.index.WriterWrapper$1.get(WriterWrapper.java:76)
at com.atlassian.jira.index.WriterWrapper.<init>(WriterWrapper.java:69)
at com.atlassian.jira.index.WriterWrapper.<init>(WriterWrapper.java:76)
at com.atlassian.jira.index.DefaultIndexEngine$DefaultWriterFactory.apply(DefaultIndexEngine.java:232)
at com.atlassian.jira.index.DefaultIndexEngine$DefaultWriterFactory.apply(DefaultIndexEngine.java:227)
at com.atlassian.jira.index.DefaultIndexEngine$WriterReference.doCreate(DefaultIndexEngine.java:212)
at com.atlassian.jira.index.DefaultIndexEngine$WriterReference.doCreate(DefaultIndexEngine.java:189)
at com.atlassian.jira.index.DefaultIndexEngine$ReferenceHolder$2.get(DefaultIndexEngine.java:272)
at com.atlassian.jira.concurrent.ResettableLazyReference.getOrCreateUnderLock(ResettableLazyReference.java:97)
at com.atlassian.jira.concurrent.ResettableLazyReference.getOrCreate(ResettableLazyReference.java:89)
at com.atlassian.jira.index.DefaultIndexEngine$ReferenceHolder.apply(DefaultIndexEngine.java:269)
at com.atlassian.jira.index.DefaultIndexEngine.write(DefaultIndexEngine.java:142)
at com.atlassian.jira.index.DefaultIndex.perform(DefaultIndex.java:28)
at com.atlassian.jira.index.QueueingIndex$Task.perform(QueueingIndex.java:132)
at com.atlassian.jira.index.QueueingIndex$Task.index(QueueingIndex.java:145)
at com.atlassian.jira.index.QueueingIndex$Task.run(QueueingIndex.java:111)
at java.lang.Thread.run(Thread.java:745)
Caused by: org.apache.lucene.store.LockObtainFailedException: Lock held by this virtual machine: /opt/atlassian/application-data/jira/caches/indexesV1/attachments/write
.lock
at org.apache.lucene.store.NativeFSLockFactory.obtainFSLock(NativeFSLockFactory.java:139)
at org.apache.lucene.store.FSLockFactory.obtainLock(FSLockFactory.java:41)
at org.apache.lucene.store.BaseDirectory.obtainLock(BaseDirectory.java:45)
at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:948)
at com.atlassian.jira.index.MonitoringIndexWriter.<init>(MonitoringIndexWriter.java:40)
at com.atlassian.jira.index.WriterWrapper$1.get(WriterWrapper.java:83)
2021-07-27 16:28:13,526+0430 ISSUE-indexQueue:thread-1 WARN administrator 160x25392x1 lztjsx xx.xx.xx.xx /secure/admin/IndexReIndex!reindex.jspa [c.a.jira.index.MonitoringIndexWriter] Detected frequent flushes (every 536 millis) of lucene index which is below warning limit: jira.index.warn.flush.min.interval.millis=1000 millis. This may affect indexing performance. Please visit https://confluence.atlassian.com/x/w0VwOQ for more information.
2021-07-27 16:28:23,369+0430 COMMENT-indexQueue:thread-1 INFO administrator 160x25392x1 lztjsx xx.xx.xx.xx /secure/admin/IndexReIndex!reindex.jspa [c.a.jira.index.MonitoringIndexWriter] [lucene-stats] flush stats: snapshotCount=2706, totalCount=93806, periodSec=300, flushIntervalMillis=110, snapshotNoDocs=0, totalNoDocs=0, indexDirectory=/opt/atlassian/application-
- Furthermore, every time we restart our service due failure. Jira notifies that it needs to re-index again. ( We recommend that you perform a re-index, as configuration changes were made to 'Plugins' at 2021/07/31 11:55 AM. Get help! . If you have other changes to make, complete them first so that you don't perform multiple re-indexes) But we know we have not changed our plugin.
- We have to mention for “Wait attempt timed out “we have increased time out from 3000 to 9000 but was not applied and have not affected. (**)
