JRockit JVM crashes with OOM on Lucene IndexWriter merge
We recently upgraded to Lucene 3.6 and JRockit JVM is crashing with OOM
exception for large dataset. Following is the JRockit dump:
2013-08-22 18:37:43,524 INFO [STDOUT] (indexer:46030) ===== BEGIN DUMP
============================================================= 2013-08-22
18:37:43,524 INFO [STDOUT] (indexer:46030) JRockit dump produced after 0
days, 05:03:42 on Thu Aug 22 18:37:36 2013
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Error Message:
Illegal memory access. [54]
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Exception Rec:
EXCEPTION_ACCESS_VIOLATION (00000000c0000005) at 0x0000000180137D32 -
memory at 0x0000000000000080 could not be read.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Version : Oracle
JRockit(R) R28.2.3-13-149708-1.6.0_31-20120327-1523-windows-x86_64
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) CPU : Intel
Nehalem-EX (HT) SSE SSE2 SSE3 SSSE3 SSE4.1 SSE4.2 Core Intel64
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Number CPUs : 48
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Tot Phys Mem :
137425145856 (131058 MB)
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) OS version :
Microsoft Windows 2008 R2 version 6.1 (Build 7600) (64-bit)
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Thread System:
Windows Threads
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Java locking : Lazy
unlocking enabled (class banning) (transfer banning)
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) State : JVM is
running (Main thread has finished)
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Command Line :
-Xms11059m -Xmx11059m -XgcPrio:pausetime -XXgcTrigger:25
-XpauseTarget:200ms -XXcompressedRefs:enable=false
-XXtlasize:min=16k,preferred=512k -Xverbose:gcreport -Xns:3072m -server
-Xrs -Dsun.rmi.transport.tcp.handshakeTimeout=0
-Desa.common.rootlogger.client=esa.common.rootlogger.indexer
-Druntime.tmpdir=D:\CW\V714\scratch\temp\component\225pst round
2-indexer@46030-20130822133352-0
-Desa.common.rootlogger.roodir=D:/CW/V714/data/esadb/case-logs/225pst
round 2/225pst round 2-indexer@46030-20130822133352-0.log
-Dsun.java.command=com.teneo.esa.admin.service.shell.Shell 46030 normal
-Dsun.java.launcher=SUN_STANDARD com.teneo.esa.admin.service.shell.Shell
46030 normal
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) java.home :
c:\jrockit-jdk1.6.0_31-R28.2.3-4.1.0-x64\jre
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) StackOverFlow: 0
StackOverFlowErrors have occured
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) OutOfMemory : 0
OutOfMemoryErrors have occured
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) C Heap : Good; no
memory allocations have failed
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) GC Strategy : Mode:
pausetime, with strategy: genconcon (basic strategy: genconcon)
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) GC Status : OC is
not running. Last finished OC was OC#471.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) : YC is currently
running. This is YC#6512.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) YC Promotion : This
YC has been able to promote all found objects so far
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) YC History : Ran 0
YCs before OC#467.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) : Ran 6 YCs before
OC#468.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) : Ran 20 YCs before
OC#469.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) : Ran 15 YCs before
OC#470.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) : Ran 1 YCs before
OC#471.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) : Started 25 YCs
since last OC.
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Heap :
0x0000000180410000 - 0x0000000433710000 (Size: 11059 MB)
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Compaction : (no
compaction area)
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) Allocation :
TLA-min: 16384, TLA-preferred: 524288 TLA-waste limit: 16384
2013-08-22 18:37:43,539 INFO [STDOUT] (indexer:46030) CompRefs :
References are uncompressed 64-bit.
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) Thread:
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) "Lucene Merge Thread
#0" id=445057 idx=0x690 tid=23496 lastJavaFrame=0x0000000073E9DF50
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) Stack 0:
start=0x0000000073E60000, end=0x0000000073EA0000,
guards=0x0000000073E64000 (ok), forbidden=0x0000000073E61000
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) Thread Stack Trace:
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
findNext+306(refiter.c:280+28)@0x0000000180137D32
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
findNextToReturn+40(refiter.c:303+0)@0x0000000180137DD8
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
trProcessLocksForThread+99(roots.c:620+19)@0x0000000180138D74
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
javaLockConvertLazyToThin+197(javalock.c:1760+99)@0x0000000180130746
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
javalock_lazy_possibleToUnlock+162(javalock.c:2032+15)@0x0000000180130D33
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
RJNI_jrockit_vm_Locks_checkAndTransferLazyLocked+297(javalock.c:2175+16)@0x0000000180130EBA
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) -- Java stack --
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
jrockit/vm/Locks.checkAndTransferLazyLocked(Ljava/lang/Object;)I(Native
Method)
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:971)[optimized]
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
jrockit/vm/Locks.monitorEnter(Locks.java:2179)[optimized]
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
org/apache/lucene/index/MergePolicy$OneMerge.checkAborted(MergePolicy.java:144)
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
org/apache/lucene/index/IndexWriter.mergeMiddle(IndexWriter.java:4251)[optimized]
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
org/apache/lucene/index/IndexWriter.merge(IndexWriter.java:3952)[optimized]
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
org/apache/lucene/index/ConcurrentMergeScheduler.doMerge(ConcurrentMergeScheduler.java:388)[inlined]
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
org/apache/lucene/index/ConcurrentMergeScheduler$MergeThread.run(ConcurrentMergeScheduler.java:456)[optimized]
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) at
jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) -- end of trace
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) Memory usage report:
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) Could not mark
thread stacks regions properly.
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) Total mapped
14738456KB (reserved=1774596KB)
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - Java heap
11324416KB (reserved=0KB)
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - GC tables 378784KB
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - Thread stacks 0KB
(#threads=0)
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - Compiled code
1048576KB (used=19557KB)
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - Internal 904KB
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - OS 78384KB
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - Other 1817472KB
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - Classblocks 4608KB
(malloced=4486KB #13282)
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - Java class data
83200KB (malloced=82754KB #62498 in 13282 classes)
Not tracing sites.
2013-08-22 18:37:43,586 INFO [STDOUT] (indexer:46030) - Native memory
tracking 4224KB (malloced=2077KB #10)
No comments:
Post a Comment