JDK-7087969 : GarbageCollectorMXBean notification contains ticks vs millis
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc
  • Affected Version: 7
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: linux
  • CPU: x86
  • Submitted: 2011-09-07
  • Updated: 2013-06-26
  • Resolved: 2012-04-19
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 7 JDK 8 Other
7u40Fixed 8Fixed hs24Fixed
Description
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)


FULL OS VERSION :
ALL (OS independent issue).

A DESCRIPTION OF THE PROBLEM :
When grabbing GarbageCollectorMXBean from the ManagementFactory, it is NOW possible (in Java 7) to cast the underlying bean implementation into a NotificationBroadcaster and add a NotificationListener.  Doing this causes the JVM to report on GC events after they're done.  In the JVM, GCNotifier::pushNotification puts the "raw" GCStatInfo data (containing start/end ticks) onto the request queue.  GCNotifier::sendNotification constructs GcInfo from this data WITHOUT converting the ticks to millis.  When the listener gets access to the GcInfo object, a call to getDuration() returns elapsed ticks vs. elapsed millis (contrary to comments in the source code).

This all constrasts the notion of calling GarbageCollectorMXBean.getLastGcInfo, which under the covers DOES convert the ticks to millis prior to returning the object.


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 :
Use the provided source code.

EXPECTED VERSUS ACTUAL BEHAVIOR :
Actual results:

PS Scavenge : 7093839093246673821
PS Scavenge : 4309
PS Scavenge : 4305
PS Scavenge : 4304
PS Scavenge : 3037
PS Scavenge : 3226
PS Scavenge : 2991
PS Scavenge : 4432
PS Scavenge : 1643
PS Scavenge : 1797
PS Scavenge : 973
PS Scavenge : 863
PS Scavenge : 738
PS Scavenge : 993
PS Scavenge : 765
...


REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
    public static void main(String[] args)
    {
        NotificationListener nl = new NotificationListener()
        {
            @Override
            public void handleNotification(Notification notification, Object name)
            {
                CompositeData cd = (CompositeData) notification.getUserData();
                cd = (CompositeData) cd.get("gcInfo");
                GcInfo gcInfo = GcInfo.from(cd);
                long ticksNotMillis = gcInfo.getDuration();
                System.out.append(String.valueOf(name)).append(" : ");
                System.out.append(Long.toString(ticksNotMillis)).append("\n");
            }
        };

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

        for (GarbageCollectorMXBean bean : list)
            ((NotificationBroadcaster) bean).addNotificationListener(nl, null, bean.getName());

        // Force garbage collection

        long start = System.currentTimeMillis();

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

            if (now - start > 5000)
                break;

            byte[] bytes = new byte[1048576];
        }
    }

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

Comments
EVALUATION http://hg.openjdk.java.net/hsx/hotspot-main/hotspot/rev/9a5bef0481c8
04-04-2012

EVALUATION http://hg.openjdk.java.net/hsx/hotspot-rt/hotspot/rev/9a5bef0481c8
29-03-2012