United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-7176220 'Full GC' events miss date stamp information occasionally
JDK-7176220 : 'Full GC' events miss date stamp information occasionally

Details
Type:
Bug
Submit Date:
2012-06-12
Status:
Resolved
Updated Date:
2013-06-22
Project Name:
JDK
Resolved Date:
2013-05-20
Component:
hotspot
OS:
solaris_10
Sub-Component:
gc
CPU:
sparc
Priority:
P4
Resolution:
Fixed
Affected Versions:
6u31
Fixed Versions:
hs24 (b46)

Related Reports
Backport:
Backport:
Backport:
Relates:
Relates:

Sub Tasks

Description
'Full GC' events miss date and time stamp information occasionally.

Example:
% grep Full * | more
97615.938: [Full GC 1948395K->1737658K(2259136K), 16.4664960 secs]
98012.870: [Full GC 2340711K->1727536K(2528000K), 14.2683270 secs]
98107.575: [Full GC 2136505K->1748729K(2528000K), 13.6718630 secs]
98924.642: [Full GC 2506695K->1970965K(2528000K), 15.2351710 secs]
99339.771: [Full GC 2392788K->2095746K(2528000K), 15.1428000 secs]
2012-02-15T11:10:37.574+0100: 99360.096: [Full GC 2480403K->2137904K(2528000K), 15.5759880 secs]
2012-02-15T11:10:57.657+0100: 99381.371: [Full GC 2460514K->2155095K(2528000K), 15.8424040 secs]
2012-02-15T11:11:18.523+0100: 99402.416: [Full GC 2494126K->2205046K(2528000K), 16.0608940 secs]
99420.437: [Full GC 2524249K->2225820K(2528000K), 15.9992900 secs]
2012-02-15T11:11:55.189+0100: 99438.003: [Full GC 2481820K->2211826K(2528000K), 16.2163920 secs]
99456.979: [Full GC 2524492K->2240067K(2528000K), 16.1425710 secs]
[ ...]

                                    

Comments
SUGGESTED FIX

diff --git a/src/share/vm/memory/genCollectedHeap.cpp b/src/share/vm/memory/genCollectedHeap.cpp                                                                 
--- a/src/share/vm/memory/genCollectedHeap.cpp                                   
+++ b/src/share/vm/memory/genCollectedHeap.cpp                                   
@@ -518,6 +518,7 @@
             increment_total_full_collections();                                 
           }                                                                     
           pre_full_gc_dump();    // do any pre full gc dumps                    
+          gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);               
         }                                                                       
         // Timer for individual generations. Last argument is false: no CR      
         TraceTime t1(_gens[i]->short_name(), PrintGCDetails, false, gclog_or_tty);
                                     
2012-06-12
EVALUATION

Missing a call to date_stamp() in GenCollectedHeap::do_collection.  Bug has existed since -XX:+PrintGCDateStamps was added in hs10/jdk6u4.
                                     
2012-06-12
Adding another date_stamp call was not enough.
New approach is to add the date-stamp call to a newly created subclass of TraceTime, 'GCTraceTime', and then removing the standalone calls to date-stamp.
The time-stamp part of the logging is already present in the TraceTime class, this will be moved to GCTraceTime.
This will avoid problems such as the flag PrintGCTimeStamp affecting other parts of HotSpot that are using TraceTime.
                                     
2012-10-30
Waiting for go-ahead from GC team to merge fix.
                                     
2013-04-05
URL:   http://hg.openjdk.java.net/hsx/hsx24/hotspot/rev/aa01d1f5fcd9
User:  brutisso
Date:  2013-05-20 10:11:28 +0000

                                     
2013-05-20



Hardware and Software, Engineered to Work Together