Long safepoint pause directly after GC log file rotation in 1.7.0_80

[Rainer Jung]

Hi,

after upgrading from 1.7.0_76 to 1.7.0_80 we experience long pauses 
directly after a GC log rotation.

The pause duration varies due to application and load but is in the 
range of 6 seconds to 60 seconds. There is no GC involved, i.e. no GC 
output is written related to these pauses.

Example:

Previous file ends with:

2015-11-09T01:28:36.832+0100: 38461,486: Application time: 5,2840810 seconds
{Heap before GC invocations=7366 (full 8):
par new generation   total 458752K, used 442678K [0xfffffffe00400000, 
0xfffffffe20400000, 0xfffffffe20400000)
   eden space 393216K, 100% used [0xfffffffe00400000, 
0xfffffffe18400000, 0xfffffffe18400000)
   from space 65536K,  75% used [0xfffffffe18400000, 0xfffffffe1b44d998, 
0xfffffffe1c400000)
   to   space 65536K,   0% used [0xfffffffe1c400000, 0xfffffffe1c400000, 
0xfffffffe20400000)
concurrent mark-sweep generation total 3670016K, used 1887085K 
[0xfffffffe20400000, 0xffffffff00400000, 0xffffffff00400000)
concurrent-mark-sweep perm gen total 524288K, used 453862K 
[0xffffffff00400000, 0xffffffff20400000, 0xffffffff20400000)
2015-11-09T01:28:36.839+0100: 38461,493: 
[GC2015-11-09T01:28:36.840+0100: 38461,493: [ParNew
Desired survivor size 33554432 bytes, new threshold 16 (max 31)
- age   1:    2964800 bytes,    2964800 total
- age   2:    2628048 bytes,    5592848 total
- age   3:    1415792 bytes,    7008640 total
- age   4:    1354008 bytes,    8362648 total
- age   5:    1132056 bytes,    9494704 total
- age   6:    1334072 bytes,   10828776 total
- age   7:    1407336 bytes,   12236112 total
- age   8:    3321304 bytes,   15557416 total
- age   9:    1531064 bytes,   17088480 total
- age  10:    2453024 bytes,   19541504 total
- age  11:    2797616 bytes,   22339120 total
- age  12:    1698584 bytes,   24037704 total
- age  13:    1870064 bytes,   25907768 total
- age  14:    2211528 bytes,   28119296 total
- age  15:    3626888 bytes,   31746184 total
: 442678K->37742K(458752K), 0,0802687 secs] 
2329763K->1924827K(4128768K), 0,0812120 secs] [Times: user=0,90 
sys=0,03, real=0,08 secs]
Heap after GC invocations=7367 (full 8):
par new generation   total 458752K, used 37742K [0xfffffffe00400000, 
0xfffffffe20400000, 0xfffffffe20400000)
   eden space 393216K,   0% used [0xfffffffe00400000, 
0xfffffffe00400000, 0xfffffffe18400000)
   from space 65536K,  57% used [0xfffffffe1c400000, 0xfffffffe1e8db9a0, 
0xfffffffe20400000)
   to   space 65536K,   0% used [0xfffffffe18400000, 0xfffffffe18400000, 
0xfffffffe1c400000)
concurrent mark-sweep generation total 3670016K, used 1887085K 
[0xfffffffe20400000, 0xffffffff00400000, 0xffffffff00400000)
concurrent-mark-sweep perm gen total 524288K, used 453862K 
[0xffffffff00400000, 0xffffffff20400000, 0xffffffff20400000)
}
....
2015-11-09T01:28:36.921+0100: 38461,575: Total time for which 
application threads were stopped: 0,0888232 seconds, Stopping threads 
took: 0,0005420 seconds
2015-11-09T01:28:59.821+0100: 38484,474: Application time: 0,0002954 seconds
2015-11-09T01:28:59.823+0100: 38484,477: Total time for which 
application threads were stopped: 0,0026081 seconds, Stopping threads 
took: 0,0004146 seconds
2015-11-09T01:28:59.824+0100: 38484,477: Application time: 0,0003073 seconds
2015-11-09T01:28:59.826+0100: 38484,480: Total time for which 
application threads were stopped: 0,0025411 seconds, Stopping threads 
took: 0,0004064 seconds
2015-11-09T01:28:59.827+0100: 38484,480: Application time: 0,0002885 seconds
2015-11-09 01:28:59 GC log file has reached the maximum size. Saved as 
./application/logs-a/mkb_gc.log.2

This output looks normal. Last timestamp is 2015-11-09T01:28:59.827

Now the next file begins:

2015-11-09 01:28:59 GC log file created ./application/logs-a/mkb_gc.log.3
Java HotSpot(TM) 64-Bit Server VM (24.80-b11) for solaris-sparc JRE 
(1.7.0_80-b15), built on Apr 10 2015 18:47:18 by "" with Sun Studio 12u1
Memory: 8k page, physical 133693440k(14956840k free)
CommandLine flags: -XX:AllocateInstancePrefetchLines=2 
-XX:AllocatePrefetchInstr=1 -XX:AllocatePrefetchLines=6 
-XX:AllocatePrefetchStyle=3 -XX:+CMSClassUnloadingEnabled 
-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses 
-XX:GCLogFileSize=10485760 -XX:InitialHeapSize=4294967296 
-XX:MaxHeapSize=4294967296 -XX:MaxNewSize=536870912 
-XX:MaxPermSize=536870912 -XX:MaxTenuringThreshold=31 
-XX:NewSize=536870912 -XX:NumberOfGCLogFiles=10 -XX:OldPLABSize=16 
-XX:ParallelGCThreads=16 -XX:PermSize=536870912 -XX:+PrintGC 
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps 
-XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:SurvivorRatio=6 
-XX:-UseAdaptiveSizePolicy -XX:+UseCompressedOops 
-XX:+UseConcMarkSweepGC -XX:+UseGCLogFileRotation -XX:+UseParNewGC
2015-11-09T01:29:55.640+0100: 38540,292: Total time for which 
application threads were stopped: 55,8119519 seconds, Stopping threads 
took: 0,0003857 seconds
2015-11-09T01:29:55.648+0100: 38540,299: Application time: 0,0076173 seconds

Note the 55.8 seconds pause directly after printing the flags and the 
consistent timestamp jump from 01:28:59 to 01:29:55. There's no GC 
output, although verbose GC is active and works. For some other reason 
there is a very long safepoint. Note also, that the time is not due to 
waiting until the safepoint is reached. At least the log claims that 
reaching the safepoint only took 0.008 seconds. Also at that timeof day 
the servers are not very busy.

Is there any idea, what happens here? Anything that rings a bell between 
1.7.0_76 and 1.7.0_80? Why should there be a long safepoint directly 
after GC rotation opened a new file?

I searched the bug parade, but didn't find a good hit. There was also 
nothing in the change for JDK-7164841 that seemed immediately 
responsible for a long pause.

Unfortunately this happens on a production system and the first thing 
was to roll back to the old Java version.Not sure, how good this will be 
reproducible on a test system (will check tomorrow).

Thanks for any hint,

Rainer