FULL PRODUCT VERSION :
java version "1.7.0"
Java(TM) SE Runtime Environment (build 1.7.0-b147)
Java HotSpot(TM) 64-Bit Server VM (build 21.0-b17, mixed mode)

ADDITIONAL OS VERSION INFORMATION :
Linux 2.6.32-5-amd64 #1 SMP Mon Oct 3 03:59:20 UTC 2011 x86_64 GNU/Linux

EXTRA RELEVANT SYSTEM CONFIGURATION :
Must run with JDK params: -XX:+UseConcMarkSweepGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc-events


A DESCRIPTION OF THE PROBLEM :
The GarbageCollectorMXBean can be periodically accessed to retrieve (1) the number of garbage collections that have been run by a particular garbage collector, and also (2) the number of millis that have been spent doing same.

So, run on minute boundaries, this may return:
minute1: 1 collection, 500 millis,
minute2: 2 collections, 1000 millis.

Keeping track of the last values seen, it can be concluded that in the second minute, 1 gc was done, taking 500 millis.

The 1 supposed gc/500 ms time can be confirmed looking at the gc-events file.

Up to version JDK 1.6.0_22, this process worked for all tested garbage collectors, including the G1/tenured collector.

Current versions of the JVM now return times much lower (example, 0 or 2ms) that do not correspond to values found in the gc-events file for tenured Concurrent Mark and Sweep times.


REGRESSION. Last worked in version 6u29

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
java -Xms4M -Xmx32M -XX:+UseConcMarkSweepGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc-events GCTest


REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------

import java.util.Iterator;
import java.util.List;
import java.util.Map;
import java.util.HashMap;
import java.lang.management.GarbageCollectorMXBean;

/**
 * GCTest.java
 * Testing garbage collection behavior. Suggested JVM options: -Xms4m -Xmx32m
 */

class GCTest {
    static MyList objList = null;
    static int wait = 500; // milliseconds
    static int initSteps = 16; // 2 MB
    static int testSteps = 1;
    static int objSize = 128; // 1/8 MB
    public static void main(String[] arg) {
        if (arg.length>0) initSteps = Integer.parseInt(arg[0]);
        if (arg.length>1) testSteps = Integer.parseInt(arg[1]);
        objList = new MyList();
        Monitor m = new Monitor();
        m.setDaemon(true);
        m.start();
        myTest();
    }
    public static void myTest() {
        for (int m=0; m<initSteps; m++) {
            mySleep(wait);
            objList.add(new MyObject());
        }
        for (int n=0; n<10*8*8/testSteps; n++) {
            for (int m=0; m<testSteps; m++) {
                mySleep(wait);
                objList.add(new MyObject());
            }
            for (int m=0; m<testSteps; m++) {
                mySleep(wait);
                objList.removeTail();
                // objList.removeHead();
            }
        }
    }
    static void mySleep(int t) {
        try {
            Thread.sleep(t);
        } catch (InterruptedException e) {
            System.out.println("Interreupted...");
        }
    }
    static class MyObject {
        private static long count = 0;
        private long[] obj = null;
        public MyObject next = null;
        public MyObject prev = null;
        public MyObject() {
            count++;
            obj = new long[objSize*192];
        }
        protected final void finalize() {
            count--;
        }
        static long getCount() {
            return count;
        }
    }
    static class MyList {
        static long count = 0;
        MyObject head = null;
        MyObject tail = null;
        static long getCount() {
            return count;
        }
        void add(MyObject o) {
            // add the new object to the head;
            if (head==null) {
                head = o;
                tail = o;
            } else {
                o.prev = head;
                head.next = o;
                head = o;
            }
            count++;
        }
        void removeTail() {
            if (tail!=null) {
                if (tail.next==null) {
                    tail = null;
                    head = null;
                } else {
                    tail = tail.next;
                    tail.prev = null;
                }
                count--;
            }
        }
        void removeHead() {
            if (head!=null) {
                if (head.prev==null) {
                    tail = null;
                    head = null;
                } else {
                    head = head.prev;
                    head.next = null;
                }
                count--;
            }
        }
    }
    static class Monitor extends Thread {
        public void run() {
            Runtime rt = Runtime.getRuntime();
            System.out.println(
                               "Time Total Free Free Total Act. Dead Over");
            System.out.println(
                               "sec. Mem. Mem. Per. Obj. Obj. Obj. Head");
            long dt0 = System.currentTimeMillis()/1000;
            StringBuffer reportLine;
            String lastReportLine = "";
            Map<String,GCHistory> gcHistory = new HashMap<String,GCHistory>();
            while (true) {
                long tm = rt.totalMemory()/1024;
                long fm = rt.freeMemory()/1024;
                long ratio = (100*fm)/tm;
                long dt = System.currentTimeMillis()/1000 - dt0;
                long to = MyObject.getCount()*objSize;
                long ao = MyList.getCount()*objSize;
                System.out.println(dt
                                   + " " + tm + " " + fm + " " + ratio +"%"
                                   + " " + to + " " + ao + " " + (to-ao)
                                   + " " + (tm-fm-to));
                reportLine = new StringBuffer();
                List<GarbageCollectorMXBean> garbageCollectors;
                garbageCollectors = java.lang.management.ManagementFactory.getGarbageCollectorMXBeans();
                for ( GarbageCollectorMXBean collector : garbageCollectors) {
                    long gcCollectionCount = collector.getCollectionCount();
                    long gcCollectionTime = collector.getCollectionTime();
                    String name = collector.getName();
                    name = name.replace( " ", "_");
                    GCHistory history = gcHistory.get( name);
                    if ( null == history) {
                        history = new GCHistory( name);
                        gcHistory.put( name, history);
                    }
                    history.updateHistory( gcCollectionTime, gcCollectionCount);
                    if (( gcCollectionCount > 0) || ( gcCollectionTime > 0)) {
                        reportLine.append( history.report());
                    }
                }
                if (( ! "".equals( reportLine.toString())) && ( ! lastReportLine.equals( reportLine.toString()))) {
                    // To make it easier to synch up these report lines with the gc-events file, print the seconds-since-jvm-start,
                    double secondsSinceJvmStart = (double)
                        (( System.currentTimeMillis()-
                           java.lang.management.ManagementFactory.getRuntimeMXBean().getStartTime()) / 1000.0);
                
                    System.out.println("\tGarbageCollection: " + secondsSinceJvmStart + " - " + reportLine.toString());
                    lastReportLine = reportLine.toString();
                }
                mySleep(wait);
            }
        }
        public class GCHistory {
            String name;
            long accumCollectionCount = 0;
            long accumCollectionTime = 0;
            long periodCollectionCount = 0;
            long periodCollectionTime = 0;

            public GCHistory( String name) {
                this.name = name;
            }

            public void updateHistory( long time, long collections) {
                periodCollectionCount = collections - accumCollectionCount;
                accumCollectionCount = collections;
                periodCollectionTime = time - accumCollectionTime;
                accumCollectionTime = time;
            }

            public String toString() {
                StringBuffer sb = new StringBuffer();
                sb.append( "GarbageCollector Performance :: " + name);
                sb.append( "\t");
                sb.append( periodCollectionCount + " collections / " );
                sb.append( periodCollectionTime + " ms.");
                return sb.toString();
            }

            public String report() {
                StringBuffer sb = new StringBuffer();
                if (( periodCollectionCount != 0) || ( periodCollectionTime != 0)) {
                    sb.append( "name " + name);
                    sb.append( " ");
                    sb.append( periodCollectionCount);
                    sb.append( " / ");
                    sb.append( periodCollectionTime + " ms. ");
                }
                return sb.toString();
            }
        
        }
    }

}


---------- END SOURCE ----------