JDK-6800586 : -XX:+PrintGCDateStamps is using mt-unsafe localtime function
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 6u12-rev
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • OS: solaris_8
  • CPU: generic
  • Submitted: 2009-02-03
  • Updated: 2012-10-08
  • Resolved: 2009-02-27
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 6 JDK 7 Other
6u13-revFixed 7Fixed hs11.3Fixed
Related Reports
Relates :  
JDK-6803736 - Windows: iso8601_time() uses localtime() which might be MT-unsafe on some versions of Windows
Relates :  
JDK-6517301 - There should be a -XX:+PrintGCDateStamps
Description
The os::iso8601_time function called from the CMS collector is using the mt-unsafe localtime system function on the Solaris/Sparc platform.

The localtime call is conflicting with mt-safe localtime_r calls invoked from other JNI threads. The JNI threads are running independently from the CMS processing.

Within the attached stack trace the lwp#6 thread tries to deallocate 
same memory as the the lwp#21 thread (ff38425c).

-----------------  lwp# 6 / thread# 6  --------------------
ff29f2dc _lwp_kill (6, 0, 0, ffffffff, ff2c03c4, 1) + 8
ff235984 abort    (ff2bc008, 6f, 0, ff2aac27, 0, 3d) + 100
ff370db4 free     (ff38425c, 40, ff384000, a7e6448, 40, 0) + 1f8
ff2537c4 tzcpy    (a7e6600, ff2c2940, 4, 4, ff2bc008, cfae8) + 74
ff253504 _ltzset_u (0, c09e8, ff2bf560, ff2bf55c, ff2bf558, ff2bf538) + 344
ff2523f4 localtime_u (91f7f754, ff2c2948, ff0ea000, 9c39b, ff2bc008, fee6a9c0) + 14
fee6a9c0 char*os::iso8601_time(char*,unsigned) (91f7f7b8, 20, 91f7f7b8, 7efefeff, ff0ea000, 0) + 9c
fee75c00 void outputStream::date_stamp(bool,const char*,const char*) (bc4b8, 1, ff014cf0, ff014cf1, ff0ea000, ff121fec) + 48
fec3b9bc void GenCollectedHeap::do_collection(bool,bool,unsigned,bool,int) (13abc0, ff014cd1, 0, 14, 1, 1) + 214
febc8c98 HeapWord*GenCollectorPolicy::satisfy_failed_allocation(unsigned,bool) (bdf70, 14, 13abc0, fe740d92, 0, a) + 15c
fef6804c void VM_GenCollectForAllocation::doit() (8d27ea24, 13abc0, 9, 8, bdfb8, be000) + 78
fe9c5384 void VM_Operation::evaluate() (8d27ea24, cf638, ff0ea000, ff2, 7f9785, 36c00) + 80
fef6a5ec void VMThread::evaluate_operation(VM_Operation*) (cf638, 8d27ea24, 10a108, 7f9785, 10a110, ff0ea000) + cc
fef6ab84 void VMThread::loop() (0, fead7248, 2c954, 0, 44800, e5538) + 45c
fea4fc00 void VMThread::run() (14ec00, 36000, ff120360, ff0ea000, 36360, 36000) + 98
fee6d148 java_start (14ec00, 4, ced7, ff0ea000, ff05d875, ff121914) + 168
ff354c3c _lwp_start (0, 0, 0, 0, 0, 0)

-----------------  lwp# 21 / thread# 21  --------------------
ff354d80 __lwp_park (ff2f2800, ff366b44, a7e6410, ff366000, 1, a7e641c) + 14
ff351414 slow_lock (a7e6410, ff2f2800, a7e6410, ff2aac27, 0, 3d) + 54
ff370d48 free     (ff38425c, 80, ff384000, a7e6448, 80, 0) + 18c
ff2537c4 tzcpy    (a7e65e8, ff2c2940, 4, 4, ff2bc008, cfae8) + 74
ff253504 _ltzset_u (18, c09e8, ff2bf560, ff2bf55c, ff2bf558, ff2bf538) + 344
ff2523f4 localtime_u (8e1fb180, 8e1fb114, 0, ff2bc008, ff2bc008, 682ac38) + 14
ff2525fc localtime_r (8e1fb180, 8e1fb114, 8e1fb180, 682ac40, 682ac38, 682ada8) + 28
8ede9758 void cbxmp::AbstractBasketRecord::formatDate(std::string &,const long) (682aa30, 497a05aa, 682aa24, 2, a, 8ee9e2b4) + c
8edf28c0 void cbxmp::BasketUpdater::updateSnaps(const std::vector<cbxmp::BasketSnap>&) (682a798, e41d06c, 497a05aa, 682aa18, 2, 682a8a0) + 60
8edeb8e4 void cbxmp::BasketRecord::calculateAndRefresh_i(bool&,bool,cbxmp::BasketUpdater&) (e41cf20, 8e1fbccf, 8ee80c73, 682a798, 682a7a4, fff4c95c) + cac
8edeabac void cbxmp::BasketRecord::calculateAndRefresh(bool) (e41cf20, 1, 1, 8ee9e2b4, 22c, 0) + 7c
8edea88c void cbxmp::BasketRecord::enable() (e41cf20, 8e1fbdac, e41cf20, e41d078, 8e1fbd34, 0) + 88
8ede6450 void cbxmp::BasketPricer::processPriceCommand(const cbxmp::Basket*) (f5330, 145873c0, 0, 44d9f88, 40, e41cf20) + 118
8ede61b0 void cbxmp::BasketPricer::BasketQueue::runQueue(void*) (f53e0, 44da148, 8e1fbeb0, 8ee9e2b4, 0, 44ec790) + 40
fc1d1fac void ost::ThreadQueue::run() (f53e0, 1, 8e1fbf40, 8e1fbf1c, 0, 0) + 8c
fc1ac018 void ost::ThreadImpl::ThreadExecHandler(ost::Thread*) (f5400, 0, 0, 0, 0, 0) + 148
fc1aa52c ccxx_exec_handler (f5400, ff2f2800, 0, 0, 0, 0) + c

(See also Java Developer Bug Report #1449833 "Solaris/Sparc hotspot is using unsafe localtime function within CMS collector" which has been created directly by the customer: ###@###.###)


FULL PRODUCT VERSION :
java version "1.6.0_07"
Java(TM) SE Runtime Environment (build 1.6.0_07-b06)
Java HotSpot(TM) Server VM (build 10.0-b23, mixed mode)

FULL OS VERSION :
SunOS sv054869 5.8 Generic_117350-16 sun4u sparc SUNW,Netra-T12 Solaris

EXTRA RELEVANT SYSTEM CONFIGURATION :
CMS parameters
-d32 -server -XX:-OmitStackTraceInFastThrow -XX:+PrintGCDetails 
-XX:+PrintGCDateStamps -XX:+TraceClassUnloading -XX:+PrintHeapAtGC 
-XX:PrintCMSStatistics=1 -XX:+PrintTenuringDistribution -Xmx1512m 
-Xms512m -XX:NewSize=128m -XX:MaxNewSize=128m -XX:PermSize=128m 
-XX:SurvivorRatio=5 -XX:MaxTenuringThreshold=8 -XX:CMSMarkStackSize=8M 
-XX:CMSMarkStackSizeMax=32M -XX:+UseConcMarkSweepGC 
-XX:+CMSClassUnloadingEnabled -XX:+CMSIncrementalMode 
-XX:CMSIncrementalDutyCycleMin=5 -XX:+CMSIncrementalPacing 
-XX:+UseParNewGC -XX:-ParallelRefProcEnabled -XX:ParallelGCThreads=2 
-XX:ParallelCMSThreads=1 -Xloggc:/tmp/gc20090202.log 

REPRODUCIBILITY :
This bug can be reproduced often.
Comments
EVALUATION http://hg.openjdk.java.net/jdk7/hotspot/hotspot/rev/773234c55e8c
12-02-2009
EVALUATION http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/773234c55e8c
09-02-2009
SUGGESTED FIX Here's the current webrev:- http://analemma.sfbay.sun.com/net/neeraja/export/ysr/localtime/webrev
09-02-2009
EVALUATION Change localtime -> localtime_r on Solaris & Linux. (Windows doesn't appear to have a correspomding method; perhaps localtime provides thread local storage that is reused and is not subject to the mt-unsafeness observed by customer on Solaris 8?) Handing off to sustaining for backport to jdk6/pool/rev for verification at the customer. Once the customer has verified the fix and the code has been reviewed locally, we will push the fixes into the hs15 repo. Then, if customer wants fix backported to jdk6/rev/pool, submitter can open a subCR for suitable previous release and escalate it as necessary.
08-02-2009
SUGGESTED FIX I made the obvious change on Solaris/Linux. Windows appears not to have the localtime_r() function, so I will defer to the runtime team for vetting the following changes, which will be sent to the customer for verification by Sustaining Eng, to whom I will now hand-off the bug; see suggested diffs below, wrt a recent hs15/JDK7 workspace which should backport in the obvious way to the jdk6/rev-pool workspaces:- diff -r 58054a18d735 src/share/vm/runtime/os.cpp --- a/src/share/vm/runtime/os.cpp Fri Feb 06 01:38:50 2009 +0300 +++ b/src/share/vm/runtime/os.cpp Sun Feb 08 12:43:29 2009 -0800 @@ -74,13 +74,20 @@ char* os::iso8601_time(char* buffer, siz const int milliseconds_after_second = milliseconds_since_19700101 % milliseconds_per_microsecond; // Convert the time value to a tm and timezone variable - const struct tm *time_struct_temp = localtime(&seconds_since_19700101); - if (time_struct_temp == NULL) { + struct tm time_struct; +#ifndef _WINDOWS // Solaris and Linux + if (localtime_r(&seconds_since_19700101, &time_struct) == NULL) { + assert(false, "Failed localtime_r"); + return NULL; + } +#else // _WINDOWS + const struct tm* time_struct_ptr = localtime(&seconds_since_19700101); + if (time_struct_ptr == NULL) { assert(false, "Failed localtime"); return NULL; } - // Save the results of localtime - const struct tm time_struct = *time_struct_temp; + time_struct = *time_struct_ptr; +#endif // _WINDOWS const time_t zone = timezone; // If daylight savings time is in effect, @@ -93,10 +100,10 @@ char* os::iso8601_time(char* buffer, siz UTC_to_local = UTC_to_local - seconds_per_hour; } // Compute the time zone offset. - // localtime(3C) sets timezone to the difference (in seconds) + // localtime_r(3C) sets timezone to the difference (in seconds) // between UTC and and local time. // ISO 8601 says we need the difference between local time and UTC, - // we change the sign of the localtime(3C) result. + // we change the sign of the localtime_r(3C) result. const time_t local_to_UTC = -(UTC_to_local); // Then we have to figure out if if we are ahead (+) or behind (-) UTC. char sign_local_to_UTC = '+';
08-02-2009
WORK AROUND Use -XX:+PrintGCTimeStamps instead of -XX:+PrintGCDateStamps and store absolute local timestamp into a file immediately before JVM is started - this will at least allow calculating absolute time of events from absolute JVM start time and relative time as shown in GC log.
03-02-2009