United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-6800586 -XX:+PrintGCDateStamps is using mt-unsafe localtime function
JDK-6800586 : -XX:+PrintGCDateStamps is using mt-unsafe localtime function

Details
Type:
Bug
Submit Date:
2009-02-03
Status:
Closed
Updated Date:
2012-10-08
Project Name:
JDK
Resolved Date:
2009-02-27
Component:
hotspot
OS:
solaris_8
Sub-Component:
runtime
CPU:
generic
Priority:
P3
Resolution:
Fixed
Affected Versions:
6u12-rev
Fixed Versions:
hs15 (b02)

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

Sub Tasks

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
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.
                                     
2009-02-03
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.
                                     
2009-02-08
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 = '+';
                                     
2009-02-08
SUGGESTED FIX

Here's the current webrev:-

 http://analemma.sfbay.sun.com/net/neeraja/export/ysr/localtime/webrev
                                     
2009-02-09
EVALUATION

http://hg.openjdk.java.net/jdk7/hotspot-gc/hotspot/rev/773234c55e8c
                                     
2009-02-09
EVALUATION

http://hg.openjdk.java.net/jdk7/hotspot/hotspot/rev/773234c55e8c
                                     
2009-02-12



Hardware and Software, Engineered to Work Together