3

我的 GC 日志中的大多数行如下所示：

203.558：[GC 326391K->324672K(4192192K)，0.0452610 秒]

括号中的大小是“提交的堆”，或（大约）操作系统看到的进程大小。前面的两个数字（“a->b”）显示了 GC 前后的堆使用情况。

现在，我经常收到这样的行：

42381.926：[GC 10996274K(12565888K)，0.0651560 秒]

这些是否意味着堆使用没有被 GC 改变，或者这是一个不同的消息？我查看了Oracle 的 GC 调优教程和另一个专门关于 GC 输出的页面，但找不到此类消息的解释。

我正在使用 Sun JVM (1.6.0.25)、并发收集器 ( -XX:+UseConcMarkSweepGC)，唯一与输出相关的启动选项是-Xloggc:gc.log.

4

3 回答 3

1

我在 JDK 1.6 update 23（我可以找到的最新 1.6 版本）的源代码中搜索了“secs”，并通过 GC 代码文件夹搜索了正则表达式“[^”]*->[^“]*”希望找到线索。我还搜索了 OpenJDK 1.7 代码。然后我尝试在整个 HotSpot 文件夹中搜索 "[^"]*->[^"]*"?.*secs. 然而，我发现的唯一一条 GC 日志记录似乎与您所看到的内容远程相关的是

gclog_or_tty->print("[%s-concurrent-%s: %3.3f/%3.3f secs]",
             _collector->cmsGen()->short_name(),
             _phase, _collector->timerValue(), _wallclock.seconds());

在 concurrentMarkSweepGeneration.cpp 中。它看起来甚至与您看到的格式不一样。要么我没有很好地搜索，要么在更新 23 和更新 25 之间关于 GC 日志记录发生了一些变化。

如果有人对在哪里寻找或搜索什么有更清晰的想法，我将很乐意提供帮助。

编辑：等等，从 concurrentMarkSweepGeneration.cpp 的第 827 行开始找到一些东西：

void ConcurrentMarkSweepGeneration::printOccupancy(const char *s) {
  GenCollectedHeap* gch = GenCollectedHeap::heap();
  if (PrintGCDetails) {
    if (Verbose) {
      gclog_or_tty->print(" [%d %s-%s: "SIZE_FORMAT"("SIZE_FORMAT")]",
        level(), short_name(), s, used(), capacity());
    } else {
      gclog_or_tty->print(" [%d %s-%s: "SIZE_FORMAT"K("SIZE_FORMAT"K)]",
        level(), short_name(), s, used() / K, capacity() / K);
    }
  }
  if (Verbose) {
    gclog_or_tty->print(" "SIZE_FORMAT"("SIZE_FORMAT")",
              gch->used(), gch->capacity());
  } else {
    gclog_or_tty->print(" "SIZE_FORMAT"K("SIZE_FORMAT"K)",
              gch->used() / K, gch->capacity() / K);
  }
}

并且该函数仅在此处被调用：

void CMSCollector::do_CMS_operation(CMS_op_type op) {
  gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
  TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
  TraceTime t("GC", PrintGC, !PrintGCDetails, gclog_or_tty);
  TraceCollectorStats tcs(counters());

  switch (op) {
    case CMS_op_checkpointRootsInitial: {
      checkpointRootsInitial(true);       // asynch
      if (PrintGC) {
        _cmsGen->printOccupancy("initial-mark");
      }
      break;
    }
    case CMS_op_checkpointRootsFinal: {
      checkpointRootsFinal(true,    // asynch
                           false,   // !clear_all_soft_refs
                           false);  // !init_mark_was_synchronous
      if (PrintGC) {
        _cmsGen->printOccupancy("remark");
      }
      break;
    }
    default:
      fatal("No such CMS_op");
  }
}

它确实看起来像你得到的。我不太擅长解释这段代码，但我想说你所看到的只是一个日志行，显示当前堆使用情况，后跟括号中的提交堆大小，仅此而已。基本相同的信息，但在垃圾收集之前没有使用。

于 2011-11-01T11:50:50.760 回答
0

我认为这条线是由从 CMS ( ) 和 ParNew ( )TraceTime调用的 timer.cpp 中启动的。这段代码似乎是来源concurrentMarkSweepGeneration.cpp do_CMS_operationparNewGeneration.cpp collect

void ConcurrentMarkSweepGeneration::printOccupancy(const char *s) {
    GenCollectedHeap* gch = GenCollectedHeap::heap();
    if (PrintGCDetails) {
      if (Verbose) {
        gclog_or_tty->print(" [%d %s-%s: "SIZE_FORMAT"("SIZE_FORMAT")]",
          level(), short_name(), s, used(), capacity());
    } else {
        gclog_or_tty->print(" [%d %s-%s: "SIZE_FORMAT"K("SIZE_FORMAT"K)]",
          level(), short_name(), s, used() / K, capacity() / K);
      }
    }
    if (Verbose) {
      gclog_or_tty->print(" "SIZE_FORMAT"("SIZE_FORMAT")",
                gch->used(), gch->capacity());
    } else {
      gclog_or_tty->print(" "SIZE_FORMAT"K("SIZE_FORMAT"K)",
              gch->used() / K, gch->capacity() / K);
    }
}

因此，这是堆的总占用率（所有代的总和）以及当前 GC 操作期间经过的时间的声明。打印的时间似乎是挂钟时间，因为计时器（例如os::elapsed_counter，这是gettimeofday在 linux 上）在TraceTime实例化时启动并在销毁时停止/打印。

verbose:gc如果需要，我建议您添加以获取更多信息。

于 2011-11-01T12:25:51.467 回答
0

你能列出所有 gc-looging 相关的 jvm 参数吗？

查看您的输出，我认为您没有使用

-verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails

也请检查

Tomcat GC日志语句说明

Java 垃圾收集日志消息

于 2011-11-01T11:55:35.457 回答