1

我的应用程序在某个时候运行 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);

            }
        }

谢谢你。

4

2 回答 2

6

这似乎是 JVM 的完美健康行为。似乎您的代码进入了循环并不断创建必须进行 GC 处理的临时对象。

您可以尝试通过 jstack 获取一些堆栈跟踪，并尝试找出程序在哪里循环。

于 2013-09-20T12:30:50.473 回答
6

根据您的一个示例（更多示例会有所帮助），您似乎在这里创建了很多垃圾。

    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)

编译模式会创建很多对象，我建议尽可能少地这样做（如果有的话）

要获得更多信息，您确实需要使用内存分析器。试试 VisualVM，它内置在 JDK 中，或者如果你有 Java 7 更新 40+，则使用 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 秒，这意味着它只有 1.4% 的时间在 GC 中，因此 98.6% 的时间不是 GC。

于 2013-09-20T12:46:26.083 回答