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

(I verified that this is still a problem in: http://hg.openjdk.java.net/jdk7u/jdk7u/)


FULL OS VERSION :
This is a problem on ALL OS's.

A DESCRIPTION OF THE PROBLEM :
Consider the following in hotspot/src/share/vm/services:

When a garbage collection is complete, GCMemoryManager::gc_end gets called (in memoryManager.cpp).  This method completes the stats within the _current_gc_stat object.  As the method proceeds, it makes a call to GCNotifier::pushNotification (in gcNotifier.cpp) BEFORE it moves _current_gc_stat into _last_gc_stat.

The problem with this is that GCNotifier::pushNotification makes a call to GCMemoryManager::get_last_gc_stat, which always has the LAST set of stats (and bogus data if it's the first call).

Any java app that subscribes for GC notifications consistently gets stats that is 1 collection old (with the 1st set of stats bogus).


THE PROBLEM WAS REPRODUCIBLE WITH -Xint FLAG: Did not try

THE PROBLEM WAS REPRODUCIBLE WITH -server FLAG: Did not try

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Run the provided source code:

java -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+TraceGen0Time -XX:+TraceGen1Time GCTest



EXPECTED VERSUS ACTUAL BEHAVIOR :
Notice in the following output that the id and secs consistently apply to the PREVIOUS collection, with the very 1st collection pointing to bogus data:

13:24:38.797
13:24:39.000
0.266: [GC 2457K->203K(15872K), 0.0011547 secs]
13:24:39.000 [ name:Copy, action:end of minor GC, cause:Allocation Failure, id:3932536, secs:0.000000 ]
13:24:40.000
13:24:41.000
2.266: [GC 4615K->269K(15872K), 0.0010946 secs]
13:24:41.000 [ name:Copy, action:end of minor GC, cause:Allocation Failure, id:1, secs:0.001194 ]
13:24:42.000
13:24:43.000
4.266: [GC 4444K->271K(15872K), 0.0009936 secs]
13:24:43.000 [ name:Copy, action:end of minor GC, cause:Allocation Failure, id:2, secs:0.001124 ]
13:24:44.000
13:24:45.000
6.266: [GC 4419K->272K(15872K), 0.0006629 secs]
13:24:45.000 [ name:Copy, action:end of minor GC, cause:Allocation Failure, id:3, secs:0.001024 ]
13:24:46.000
13:24:47.000
8.266: [GC 4422K->274K(15872K), 0.0004875 secs]
13:24:47.000 [ name:Copy, action:end of minor GC, cause:Allocation Failure, id:4, secs:0.000692 ]
13:24:48.000
[Accumulated GC generation 0 time 0.0045320 secs, 5 GC's, avg GC time 0.0009064]
[Accumulated GC generation 1 time 0.0000000 secs, 0 GC's, avg GC time 0.0000000]


REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
import java.lang.management.GarbageCollectorMXBean;
import java.lang.management.ManagementFactory;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.List;

import javax.management.Notification;
import javax.management.NotificationBroadcaster;
import javax.management.NotificationListener;
import javax.management.openmbean.CompositeData;

import sun.misc.Perf;

public class GcTest
{
    private static final long FREQ = Perf.getPerf().highResFrequency();

    private static void handleGcNotification(Notification notification)
    {
        if (notification == null)
            return;

        Object data = notification.getUserData();

        if (!(data instanceof CompositeData))
            return;

        long curTimeMs = System.currentTimeMillis();
        SimpleDateFormat sdf = new SimpleDateFormat("HH:mm:ss.SSS");

        StringBuilder sb = new StringBuilder();
        sb.append(sdf.format(new Date(curTimeMs)));

        CompositeData cd = (CompositeData) data;
        sb.append(" [ name:");
        sb.append(String.valueOf(cd.get("gcName")));
        sb.append(", action:");
        sb.append(String.valueOf(cd.get("gcAction")));
        sb.append(", cause:");
        sb.append(String.valueOf(cd.get("gcCause")));

        Object gcInfo = cd.get("gcInfo");

        if (gcInfo instanceof CompositeData)
        {
            cd = (CompositeData) gcInfo;
            sb.append(", id:");
            sb.append(String.valueOf(cd.get("id")));

            // NOTE: duration is in ticks, NOT millis.  Bug: 7087969

            Object duration = cd.get("duration");
            double ticks = (duration instanceof Number) ? ((Number) duration).doubleValue() : -1;
            double secs = ticks > -1 ? ticks / FREQ : -1;
            sb.append(", secs:");
            sb.append(String.format("%.6f", Double.valueOf(secs)));
        }

        sb.append(" ]");
        System.out.println(sb);
    }

    public static void main(String[] args)
    {
        NotificationListener nl = new NotificationListener()
        {
            @Override
            public void handleNotification(Notification notification, Object handback)
            {
                handleGcNotification(notification);
            }
        };

        List<GarbageCollectorMXBean> list = ManagementFactory.getGarbageCollectorMXBeans();

        for (GarbageCollectorMXBean bean : list)
        {
            if (bean instanceof NotificationBroadcaster)
                ((NotificationBroadcaster) bean).addNotificationListener(nl, null, null);
        }

        int runtimeSecs = 10;
        int bytesSize = 1024 * 1024 * 2;

        SimpleDateFormat sdf = new SimpleDateFormat("HH:mm:ss.SSS");
        long startMs = System.currentTimeMillis();
        long lastSec = 0;

        for (;;)
        {
            long curTimeMs = System.currentTimeMillis();

            if (curTimeMs - startMs >= runtimeSecs * 1000)
                break;

            if (lastSec != curTimeMs / 1000)
            {
                System.out.println(sdf.format(new Date(curTimeMs)));
                lastSec = curTimeMs / 1000;
                byte[] bytes = new byte[bytesSize];
            }
        }
    }
}

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