Why do some lines in my GC log show only one value for the heap size?

Question

Most lines in my GC log look like this:

203.558: [GC 326391K->324672K(4192192K), 0.0452610 secs]

The size in parentheses is the "commited heap", or (approximately) the size of the process as seen by the OS. The two numbers before that ("a->b") show heap usage before and after GC.

Now, regularly, I get lines like this:

42381.926: [GC 10996274K(12565888K), 0.0651560 secs]

Do those mean that the heap usage was not changed by GC, or is this a different message? I looked at Oracle's GC tuning tutorial and another page specifically about GC output, but couldn't find this type of message explained.

I'm using the Sun JVM (1.6.0.25), the Concurrent Collector (-XX:+UseConcMarkSweepGC) and the only output related startup option is -Xloggc:gc.log.

I don't know. But if you really wanted to find out, you could examine the latest OpenJDK source code to find out what is producing the message. — Stephen C, Nov 01 '11 at 11:17

G_H · Answer 1 · 2011-11-01T12:10:56.297

I've searched for "secs" in the source code of JDK 1.6 update 23 (most recent 1.6 version I could find it for) and for regex "[^"]*->[^"]*" through the GC code folders in hope of finding a lead. I've also searched through the OpenJDK 1.7 code. Then I tried searching the entire HotSpot folder for "[^"]*->[^"]*"?.*secs. Yet, the only line of GC logging I've found that seems remotely related to what you're seeing is

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

That's in concurrentMarkSweepGeneration.cpp. It doesn't look even close to the format you've seen. Either I'm not searching very well, or something changed in between update 23 and update 25 regarding GC logging.

If anyone has a clearer idea of where to look or what to search on, I'll be glad to oblige.

EDIT: wait, found something starting at line 827 of concurrentMarkSweepGeneration.cpp:

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);
  }
}

And that function's being called only here:

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");
  }
}

It sure looks like what you're getting. I'm not so good at interpreting this code, but I'd say what you're seeing is simply a log line showing the current heap use followed by the committed heap size in parentheses, nothing more. Basically the same info but without the use before garbage collection.

I think you'll find that format is from a call to `TraceTime::TraceTime` in vm/runtime/timer.cpp — Matt, Nov 01 '11 at 12:01
@Matt I didn't find any link to TraceTime (not a C++ programmer, so I'm not too good at reading this stuff), but like you I've found the `printOccupancy` function to be called from `do_CMS_operation`. — G_H, Nov 01 '11 at 12:48

score 0 · Answer 2 · edited May 23 '17 at 12:03

0

Can you list all gc-looging relevant jvm parameters?

Looking at your output I don't think you are using

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

Also please check

Explanation of Tomcat GC log statements

Java Garbage Collection Log messages

edited May 23 '17 at 12:03

Community

1
1

answered Nov 01 '11 at 11:55

moodywoody

2,149
1
17
21

score 0 · Answer 3 · answered Nov 01 '11 at 12:25

I think this line is initiated by TraceTime in timer.cpp which is called from CMS (concurrentMarkSweepGeneration.cpp do_CMS_operation) and ParNew (parNewGeneration.cpp collect). This code seems the source

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);
    }
}

Therefore this is a statement of the total occupancy of the heap (sum of all generations) along with the time elapsed during the current GC operation. The time printed appears to be wall time as the timer (os::elapsed_counter so this is gettimeofday on linux for example) is started when the TraceTime is instantiated and stopped/printed when it is destroyed.

I recommend you add verbose:gc to get more information if you want it.

Why do some lines in my GC log show only one value for the heap size?

3 Answers3