I observe extremely long application pauses in GC logs that are apparently not related to garbage collection. The application is in a 16 gigabyte heap, and the allocated memory bandwidth is quite large. I understand that there will be pauses in the GC logs that are not necessarily related to the GC, and this seems to be the case here.
In addition, during these pauses, the processor reaches 100%, there is no I / O on disk or memory, and there is no logging activity (due to stopping all applications).
Any ideas on what might cause these long pauses, or any suggestions on how I can track the root cause?
Here is the corresponding passage from the logs (note the pause of 151 seconds):
2015-04-21T06:30:04.834-0500: 217179.483: [GC (Allocation Failure)2015-04-21T06:30:04.849-0500: 217179.483: [ParNew
Desired survivor size 43614208 bytes, new threshold 6 (max 6)
- age 1: 19876896 bytes, 19876896 total
- age 2: 15903904 bytes, 35780800 total
- age 3: 617120 bytes, 36397920 total
- age 4: 34096 bytes, 36432016 total
- age 5: 399896 bytes, 36831912 total
- age 6: 71112 bytes, 36903024 total
: 706301K->45145K(766784K), 0.0681632 secs] 19029029K->18368371K(25080640K), 0.0684183 secs] [Times: user=0.44 sys=0.00, real=0.08 secs]
2015-04-21T06:30:05.816-0500: 217180.453: Total time for which application threads were stopped: 1.8507910 seconds
2015-04-21T06:30:09.171-0500: 217183.812: [GC (Allocation Failure)2015-04-21T06:30:09.171-0500: 217183.812: [ParNew
Desired survivor size 43614208 bytes, new threshold 6 (max 6)
- age 1: 14812976 bytes, 14812976 total
- age 2: 3411968 bytes, 18224944 total
- age 3: 14952032 bytes, 33176976 total
- age 4: 430048 bytes, 33607024 total
- age 5: 32864 bytes, 33639888 total
- age 6: 374880 bytes, 34014768 total
: 726745K->43352K(766784K), 0.0673428 secs] 19049971K->18366645K(25080640K), 0.0675792 secs] [Times: user=0.48 sys=0.00, real=0.06 secs]
2015-04-21T06:30:09.249-0500: 217183.886: Total time for which application threads were stopped: 0.0763406 seconds
2015-04-21T06:32:43.960-0500: 217338.603: Total time for which application threads were stopped: 151.1866188 seconds
2015-04-21T06:32:43.975-0500: 217338.607: [GC (GCLocker Initiated GC)2015-04-21T06:32:43.975-0500: 217338.607: [ParNew
Desired survivor size 43614208 bytes, new threshold 4 (max 6)
- age 1: 18173880 bytes, 18173880 total
- age 2: 9659800 bytes, 27833680 total
- age 3: 3400176 bytes, 31233856 total
- age 4: 14928944 bytes, 46162800 total
- age 5: 375056 bytes, 46537856 total
- age 6: 31880 bytes, 46569736 total
: 727682K->56678K(766784K), 0.0759093 secs] 19050975K->18380341K(25080640K), 0.0760795 secs] [Times: user=0.58 sys=0.00, real=0.08 secs]
2015-04-21T06:32:44.053-0500: 217338.684: Total time for which application threads were stopped: 0.0769955 seconds
JVM :
-Xmx16g
-XX:MaxPermSize=256m
-Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.authenticate=true
-Dcom.sun.management.jmxremote.login.config=JmxFileLoginModule
-Dcom.sun.management.jmxremote.port=8082
-Dcom.sun.management.jmxremote.ssl=false
-Dfile.encoding=UTF8
-Djava.awt.headless=true
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Xloggc:{fileLoc}
-XX:+DisableExplicitGC
-XX:+PrintAdaptiveSizePolicy
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCCause
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintTenuringDistribution
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:GCLogFileSize=50M
-XX:NumberOfGCLogFiles=10
-XX:ReservedCodeCacheSize=256M
-XX:-UseGCLogFileRotation
-XX:+PrintSafepointStatistics
-XX:+SafepointTimeout
-XX:SafepointTimeoutDelay=4000
-XX:+PrintSafepointStatistics
UPDATE:
safepoint . , safepoint 151- , :
217338.603: [sweeping nmethods, 0.0000036 secs]
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
217187.422: GenCollectForAllocation [ 140 46 1 ] [ 1 0151184 2 0 ] 0
0, , 151184.
GC safepoint :
107100.562: [sweeping nmethods, 0.0000015 secs]
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
107100.563: GenCollectForAllocation [ 117 0 0 ] [ 0 0 0 0 38238 ] 0
, GC vmop, GC . , .