Kevin
Reputation: 187
The JVM is doing minor garbage collections over and over again and never throws OutOfMemoryError
my app is running util at some point the JVM recursively does minor garbage collections over and over again and never stops. my java command line :
java -Xmx4G -Xms4G -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/home/root/gc.log -jar myApp.jar
The gc output:
4.238: [Full GC [PSYoungGen: 21968K->9997K(420864K)] [ParOldGen: 74537K->83814K(150144K)] 96505K->93811K(571008K) [PSPermGen: 10761K->10757K(21824K)], 0.3216090 secs] [Times: user=0.99 sys=0.01, real=0.32 secs]
8.660: [GC [PSYoungGen: 400333K->23552K(517568K)] 484147K->117422K(667712K), 0.0554510 secs] [Times: user=0.22 sys=0.00, real=0.06 secs]
8.979: [GC [PSYoungGen: 517504K->23488K(632384K)] 611374K->117358K(782528K), 0.0263860 secs] [Times: user=0.09 sys=0.01, real=0.03 secs]
9.333: [GC [PSYoungGen: 622208K->32K(637888K)] 716078K->117418K(788032K), 0.0249140 secs] [Times: user=0.09 sys=0.01, real=0.02 secs]
9.656: [GC [PSYoungGen: 603040K->32K(603072K)] 720426K->117418K(753216K), 0.0059430 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
9.960: [GC [PSYoungGen: 603040K->32K(638464K)] 720426K->117418K(788608K), 0.0051460 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
10.263: [GC [PSYoungGen: 602464K->32K(602496K)] 719850K->117418K(752640K), 0.0037990 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
10.575: [GC [PSYoungGen: 602464K->32K(638656K)] 719850K->117418K(788800K), 0.0037570 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
10.876: [GC [PSYoungGen: 603168K->32K(637952K)] 720554K->117418K(788096K), 0.0039310 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
11.180: [GC [PSYoungGen: 603168K->32K(638528K)] 720554K->117418K(788672K), 0.0039980 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
11.480: [GC [PSYoungGen: 605216K->64K(637952K)] 722602K->117450K(788096K), 0.0036720 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
11.786: [GC [PSYoungGen: 605248K->64K(640384K)] 722634K->117450K(790528K), 0.0049470 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
12.091: [GC [PSYoungGen: 609664K->32K(639872K)] 727050K->117418K(790016K), 0.0051130 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
12.395: [GC [PSYoungGen: 609632K->32K(642752K)] 727018K->117418K(792896K), 0.0042050 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
12.704: [GC [PSYoungGen: 614816K->32K(642304K)] 732202K->117418K(792448K), 0.0036980 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
13.012: [GC [PSYoungGen: 614816K->32K(645504K)] 732202K->117418K(795648K), 0.0040370 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Heap
PSYoungGen total 1397696K, used 1209524K [0x00000007aaab0000, 0x0000000800000000, 0x0000000800000000)
eden space 1397312K, 86% used [0x00000007aaab0000,0x00000007f47cd078,0x00000007fff40000)
from space 384K, 16% used [0x00000007fffa0000,0x00000007fffb0000,0x0000000800000000)
to space 384K, 0% used [0x00000007fff40000,0x00000007fff40000,0x00000007fffa0000)
ParOldGen total 2796224K, used 98577K [0x0000000700000000, 0x00000007aaab0000, 0x00000007aaab0000)
object space 2796224K, 3% used [0x0000000700000000,0x0000000706044600,0x00000007aaab0000)
PSPermGen total 21248K, used 11122K [0x00000006fae00000, 0x00000006fc2c0000, 0x0000000700000000)
object space 21248K, 52% used [0x00000006fae00000,0x00000006fb8dca60,0x00000006fc2c0000)
Jstack output when jvm is doing forever minor gcs:
"Service Thread" daemon prio=6 tid=0x0000000010e51000 nid=0x3c8c runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" daemon prio=10 tid=0x0000000010e50000 nid=0x449c waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" daemon prio=10 tid=0x0000000010e3d800 nid=0x46b8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Attach Listener" daemon prio=10 tid=0x0000000010e3c800 nid=0x37c8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Signal Dispatcher" daemon prio=10 tid=0x0000000010e35000 nid=0x4088 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" daemon prio=8 tid=0x0000000002186000 nid=0x3df8 in Object.wait() [0x000000001216f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000001fcd4d0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
- locked <0x0000000001fcd4d0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)
"Reference Handler" daemon prio=10 tid=0x000000000217f800 nid=0x1cfc in Object.wait() [0x0000000011f5f000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x0000000001fcf510> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:503)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
- locked <0x0000000001fcf510> (a java.lang.ref.Reference$Lock)
"main" prio=6 tid=0x000000000208d000 nid=0x4704 runnable [0x000000000244e000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern.atom(Pattern.java:2199)
at java.util.regex.Pattern.sequence(Pattern.java:2097)
at java.util.regex.Pattern.expr(Pattern.java:1964)
at java.util.regex.Pattern.compile(Pattern.java:1665)
at java.util.regex.Pattern.<init>(Pattern.java:1337)
at java.util.regex.Pattern.compile(Pattern.java:1022)
at java.util.regex.Pattern.matches(Pattern.java:1128)
at com.app.Search.search(Search.java:100)
"VM Thread" prio=10 tid=0x0000000010d92800 nid=0x4208 runnable
"GC task thread#0 (ParallelGC)" prio=6 tid=0x00000000020d4800 nid=0x4538 runnable
"GC task thread#1 (ParallelGC)" prio=6 tid=0x00000000020d6000 nid=0x4390 runnable
"GC task thread#2 (ParallelGC)" prio=6 tid=0x00000000020d7800 nid=0x4874 runnable
"GC task thread#3 (ParallelGC)" prio=6 tid=0x00000000020d9800 nid=0x4558 runnable
"VM Periodic Task Thread" prio=10 tid=0x0000000010e62000 nid=0x455c waiting on condition
JNI global references: 189
The Search.search() is searching strings that match the given regex, the code
Pattern pattern = Pattern.compile(regex);
final Set<String> result = new HashSet<>();
for (final String word : words) {
if (pattern.matcher(word).matches()) {
result.add(word);
}
}
Thank you.
Upvotes: 1
Views: 328
Answers (2)
Peter Lawrey
Reputation: 533492
Based on your one sample (more samples would be helpful) it appears that you are creating lots of garbage here.
at java.util.regex.Pattern.<init>(Pattern.java:1337)
at java.util.regex.Pattern.compile(Pattern.java:1022)
at java.util.regex.Pattern.matches(Pattern.java:1128)
at com.app.Search.search(Search.java:100)
Compiling a pattern creates lot of objects and I suggest doing this as rarely as possible (if at all)
For a more informated view, you really need to use a memory profiler. Try VisualVM, it is built-in to the JDK, or Java Mission Control if you have Java 7 update 40+
JVM recursively does minor garbage collections over and over again and never stops.
I suspect you meant repeatedly, not recursively.
That is what the GC is designed to to do. You are creating a large number of short live objects and the GC is cleaning the up pretty quickly.
What is suspicious is how cleanly the GC is running. Is this a simple program which just produces garbage? If anything real applications have much uglier logs.
You are producing about 2 GB per second of garbage. This is an upper limit for some older systems and newer systems can produce about 8 GB per second.
I suspect if you used a memory profiler you could eliminate most of the garbage you are creating and your program would run quite a bit faster.
jvm is doing forever minor gcs:
It is not, you can just add up the time spent in the GC in a 3 second period.
10.263: [GC [PSYoungGen: 602464K->32K(602496K)] 719850K->117418K(752640K), 0.0037990 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
10.575: [GC [PSYoungGen: 602464K->32K(638656K)] 719850K->117418K(788800K), 0.0037570 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
10.876: [GC [PSYoungGen: 603168K->32K(637952K)] 720554K->117418K(788096K), 0.0039310 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
11.180: [GC [PSYoungGen: 603168K->32K(638528K)] 720554K->117418K(788672K), 0.0039980 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
11.480: [GC [PSYoungGen: 605216K->64K(637952K)] 722602K->117450K(788096K), 0.0036720 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
11.786: [GC [PSYoungGen: 605248K->64K(640384K)] 722634K->117450K(790528K), 0.0049470 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
12.091: [GC [PSYoungGen: 609664K->32K(639872K)] 727050K->117418K(790016K), 0.0051130 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
12.395: [GC [PSYoungGen: 609632K->32K(642752K)] 727018K->117418K(792896K), 0.0042050 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
12.704: [GC [PSYoungGen: 614816K->32K(642304K)] 732202K->117418K(792448K), 0.0036980 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
13.012: [GC [PSYoungGen: 614816K->32K(645504K)] 732202K->117418K(795648K), 0.0040370 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
The total time spent in GC in 2.749 seconds is 0.037 seconds which means it is only in GC 1.4% of the time, so 98.6% of the time it is not GCing.
Upvotes: 6
piet.t
Reputation: 11911
This seems like perfectly healthy behaviour of a JVM. Seems your code got into a loop and keeps creating temporary objects which have to be GCed.
You could try geting some stacktraces via jstack and try to find out where the program is looping.
Upvotes: 6
Related Questions
- JRE insufficient memory issue even though with enough memory?
- JVM enough memory but frequency full gc
- Garbage collection before OutOfMemoryError
- Is it possible to get OutOfMemoryError because garbage collection too slow?
- Java Process did not die after OutOfMemoryException
- memory full but not garbage collection
- Strange java jvm outofmemory
- When exactly is the JVM throwing an OutOfMemoryError
- JVM throws OutOfMemory during gc though there are plenty memory left
- JVM Memory Problems