The JVM is doing minor garbage collections over and over again and never throws OutOfMemoryError

Question

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.

see http://www.oracle.com/technetwork/java/javase/gc-tuning-6-140523.html#cms.oom — Łukasz Rzeszotarski, Sep 20 '13 at 12:37
Are you producing "garbage objects" by purpose? A full GC is never run. Only regular little GC, none taking long, which is ok. Try this to analyze quickly the GC logs. http://garbagecat.eclipselabs.org.codespot.com/files/garbagecat-1.0.0.jar — blackbird014, Sep 20 '13 at 12:54
Can you explain what the problem actually is because I can't find one? — Peter Lawrey, Sep 20 '13 at 13:19

score 6 · Answer 1 · answered Sep 20 '13 at 12:30

6

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.

answered Sep 20 '13 at 12:30

piet.t

11,718
21
43
52

Peter Lawrey · Accepted Answer · 2013-09-20T13:18:32.217

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.

The only thing to add is that there is no real indication of *recursion* here. — Stephen C, Sep 20 '13 at 12:54
You are right Peter, I should have meant "repeatly". When GCs are running in such a high frequency, JProfiler showed java.util.regex.Matcher was using 500M+ memory. The reason was It was searching words from 6345 distinct words against a regex. — Kevin, Sep 20 '13 at 13:34
The Matcher is not used very well there. You should use the Matcher.reset method so it would avoid that much of objects , see more in http://stackoverflow.com/questions/11391337/java-pattern-matcher-create-new-or-reset — lcestari, Sep 20 '13 at 13:39

The JVM is doing minor garbage collections over and over again and never throws OutOfMemoryError

2 Answers2