JVM一遍又一遍地进行小型垃圾收集,并且永远不会抛出OutOfMemoryError

Question

我的应用程序在某些时候运行util,JVM递归地反复执行次要的垃圾收集并且永远不会停止.我的java命令行:

java -Xmx4G -Xms4G -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/home/root/gc.log -jar myApp.jar

gc输出:

 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)

当jvm永远执行次要gcs时的Jstack输出:

"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

Search.search()正在搜索与给定正则表达式匹配的字符串

Pattern pattern = Pattern.compile(regex);
        final Set<String> result = new HashSet<>();
        for (final String word : words) {


            if (pattern.matcher(word).matches()) {

                result.add(word);

            }
        }

谢谢.

Answer 1

这似乎是JVM完全健康的行为.似乎你的代码进入循环并不断创建必须进行GCed的临时对象.

您可以尝试通过jstack进行一些堆栈跟踪,并尝试找出程序循环的位置.

Answer 2

基于您的一个样本(更多样本会有所帮助),您似乎在这里创建了大量垃圾.

    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)

编译模式会创建很多对象,我建议尽可能少地做这个(如果有的话)

有关更详细的视图,您确实需要使用内存分析器.如果您有Java 7更新40+,请尝试使用VisualVM,它内置于JDK或Java Mission Control

JVM递归地反复执行次要的垃圾收集,并且永远不会停止.

我怀疑你的意思是反复,而不是递归.

这就是GC的目的.您正在创建大量短期对象,GC正在快速清理.

可疑的是GC运行的干净程度.这是一个只产生垃圾的简单程序吗？如果有任何真正的应用程序有更多丑陋的日志.

你每秒产生大约2 GB的垃圾.这是某些旧系统的上限,而较新的系统每秒可产生约8 GB的系统.

我怀疑如果你使用内存分析器,你可以消除你正在创建的大部分垃圾,你的程序运行速度会快得多.

jvm正在做永远的小gcs:

事实并非如此,您可以在3秒钟内将GC花费的时间加起来.

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]

在2.749秒内在GC中花费的总时间为0.037秒,这意味着它仅在GC的1.4%时间内,因此98.6%的时间不是GCing.