GC日志让我很困惑

Question

 -server -Xms32g -Xmx32g \
 -XX:NewSize=10g -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly \
 -XX:+CMSParallelRemarkEnabled -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 \
 -XX:+PrintGCDateStamps -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime \
 -XX:+PrintGCCause -Xloggc:/var/log/flume-ng/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=10M

2016-01-09T18:37:14.193+0800: 18879.031: Application time: 0.0071232 seconds
2016-01-09T18:37:14.193+0800: 18879.032: Total time for which application threads were stopped: 0.0003769 seconds, Stopping threads took: 0.0000800 seconds
2016-01-09T18:37:21.704+0800: 18886.542: Application time: 7.5105681 seconds
2016-01-09T18:37:21.705+0800: 18886.543: [GC (Allocation Failure) 2016-01-09T18:37:21.705+0800: 18886.543: [ParNew: 8412583K->36040K(9437184K), 0.0159936 secs] 21350038K->12973495K(32505856K), 0.0162151 secs] [Times: user=0.34 sys=0.00, real=0.02 secs] 
2016-01-09T18:37:21.721+0800: 18886.559: Total time for which application threads were stopped: 0.0172971 seconds, Stopping threads took: 0.0001286 seconds
2016-01-09T18:37:37.830+0800: 18902.668: Application time: 16.1087180 seconds
2016-01-09T18:42:43.301+0800: 19208.140: Total time for which application threads were stopped:

下面是下一个gc日志（第一行305.4698351秒是我执行JStack命令的时间减去应用程序停止工作的时间）。

2016-01-09T18:42:43.301+0800: 19208.140: Total time for which application threads were stopped: 305.4715152 seconds, Stopping threads took: 305.4698351 seconds

skip some Application time log


2016-01-09T18:42:44.340+0800: 19209.179: [GC (Allocation Failure) 2016-01-09T18:42:44.340+0800: 19209.179: [ParNew: 8424650K->127192K(9437184K), 0.0331325 secs] 21362105K->13064648K(32505856K), 0.0333109 secs] [Times: user=0.72 sys=0.00, real=0.03 secs] 
2016-01-09T18:42:44.374+0800: 19209.212: Total time for which application threads were stopped: 0.0338915 seconds, Stopping threads took: 0.0000998 seconds
2016-01-09T18:42:44.374+0800: 19209.212: Application time: 0.0001254 seconds
2016-01-09T18:42:44.375+0800: 19209.213: [GC (GCLocker Initiated GC) 2016-01-09T18:42:44.375+0800: 19209.213: [ParNew: 133268K->152503K(9437184K), 0.0335528 secs] 13070724K->13089959K(32505856K), 0.0336755 secs] [Times: user=0.69 sys=0.00, real=0.04 secs] 
2016-01-09T18:42:44.408+0800: 19209.247: Total time for which application threads were stopped: 0.0345724 seconds, Stopping threads took: 0.0001147 seconds
2016-01-09T18:42:46.920+0800: 19211.759: Application time: 0.8197406 seconds
2016-01-09T18:42:46.921+0800: 19211.760: [GC (Allocation Failure) 2016-01-09T18:42:46.921+0800: 19211.760: [ParNew: 8541111K->441557K(9437184K), 0.0993869 secs] 21478567K->13379018K(32505856K), 0.0995702 secs] [Times: user=2.25 sys=0.00, real=0.10 secs] 
2016-01-09T18:42:49.571+0800: 19214.409: Application time: 0.6178457 seconds
2016-01-09T18:42:49.572+0800: 19214.410: [GC (Allocation Failure) 2016-01-09T18:42:49.572+0800: 19214.410: [ParNew: 8830165K->812963K(9437184K), 0.1568946 secs] 21767626K->13750433K(32505856K), 0.1571136 secs] [Times: user=3.58 sys=0.00, real=0.16 secs] 
2016-01-09T18:42:49.729+0800: 19214.568: Total time for which application threads were stopped: 0.1581075 seconds, Stopping threads took: 0.0001236 seconds

2016-01-09T18:42:52.286+0800: 19217.125: [GC (GCLocker Initiated GC) 2016-01-09T18:42:52.286+0800: 19217.125: [ParNew: 9201571K->973385K(9437184K), 0.3264006 secs] 22139041K->14095607K(32505856K), 0.3265784 secs] [Times: user=4.46 sys=0.00, real=0.33 secs] 

2016-01-09T18:42:55.279+0800: 19220.117: [GC (Allocation Failure) 2016-01-09T18:42:55.279+0800: 19220.117: [ParNew: 9361993K->1048576K(9437184K), 0.3140569 secs] 22484215K->14506810K(32505856K), 0.3142791 secs] [Times: user=5.36 sys=0.00, real=0.31 secs] 

2016-01-09T18:42:58.222+0800: 19223.061: Application time: 0.0000301 seconds
2016-01-09T18:42:58.223+0800: 19223.061: [GC (GCLocker Initiated GC) 2016-01-09T18:42:58.223+0800: 19223.061: [ParNew: 9437184K->1048576K(9437184K), 0.3384320 secs] 22895418K->14892045K(32505856K), 0.3386214 secs] [Times: user=5.71 sys=0.00, real=0.34 secs] 

2016-01-09T18:43:01.166+0800: 19226.005: [GC (GCLocker Initiated GC) 2016-01-09T18:43:01.166+0800: 19226.005: [ParNew: 9437184K->1048576K(9437184K), 0.3425942 secs] 23280717K->15266436K(32505856K), 0.3427797 secs] [Times: user=5.89 sys=0.00, real=0.35 secs] 

2016-01-09T18:43:04.112+0800: 19228.950: Application time: 0.6938848 seconds

在2016-01-09 18:43时，该应用程序再次停止工作。

然后我再次使用jstack-m命令，应用程序再次返回ok。

2016-01-09T18:46:18.871+0800: 19423.709: [GC (Allocation Failure) 2016-01-09T18:46:18.871+0800: 19423.710: [ParNew: 9437184K->1048576K(9437184K), 0.3188298 secs] 23655044K->15632857K(32505856K), 0.3191140 secs] [Times: user=5.55 sys=0.00, real=0.32 secs] 
2016-01-09T18:46:19.190+0800: 19424.029: Total time for which application threads were stopped: 195.0782503 seconds, Stopping threads took: 194.7573545 seconds


2016-01-09T18:46:22.197+0800: 19427.035: [GC (Allocation Failure) 2016-01-09T18:46:22.197+0800: 19427.036: [ParNew: 9437184K->1048576K(9437184K), 0.3175688 secs] 24021465K->16017865K(32505856K), 0.3177865 secs] [Times: user=5.85 sys=0.00, real=0.32 secs] 

2016-01-09T18:46:25.111+0800: 19429.950: [GC (Allocation Failure) 2016-01-09T18:46:25.112+0800: 19429.950: [ParNew: 9437184K->1048576K(9437184K), 0.2808750 secs] 24406473K->16384589K(32505856K), 0.2810767 secs] [Times: user=5.04 sys=0.00, real=0.28 secs] 

2016-01-09T18:46:27.974+0800: 19432.813: [GC (Allocation Failure) 2016-01-09T18:46:27.975+0800: 19432.813: [ParNew: 9437184K->1048576K(9437184K), 0.3201238 secs] 24773197K->16833663K(32505856K), 0.3203207 secs] [Times: user=5.53 sys=0.00, real=0.32 secs] 
.........
2016-01-09T18:55:25.249+0800: 19970.088: [GC (Allocation Failure) 2016-01-09T18:55:25.249+0800: 19970.088: [ParNew: 8419546K->31852K(9437184K), 0.0155374 secs] 13769434K->5382550K(32505856K), 0.0157411 secs] [Times: user=0.33 sys=0.00, real=0.02 secs] 

下面是jstack-f结果文件中的一个特殊线程。除了in_vm之外，所有线程的状态都被阻塞。

Attaching to process ID 23694, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.66-b17
Deadlock Detection:

No deadlocks found.

Thread 143283: (state = IN_VM)
 - sun.misc.Unsafe.freeMemory(long) @bci=0 (Compiled frame; information may be imprecise)
 - java.nio.DirectByteBuffer$Deallocator.run() @bci=17, line=94 (Compiled frame)
 - sun.misc.Cleaner.clean() @bci=12, line=143 (Compiled frame)
 - io.netty.util.internal.Cleaner0.freeDirectBuffer(java.nio.ByteBuffer) @bci=34, line=66 (Compiled frame)
 - io.netty.util.internal.PlatformDependent0.freeDirectBuffer(java.nio.ByteBuffer) @bci=1, line=147 (Compiled frame)
 - io.netty.util.internal.PlatformDependent.freeDirectBuffer(java.nio.ByteBuffer) @bci=13, line=281 (Compiled frame)
 - io.netty.buffer.UnpooledUnsafeDirectByteBuf.freeDirect(java.nio.ByteBuffer) @bci=1, line=115 (Compiled frame)
 - io.netty.buffer.UnpooledUnsafeDirectByteBuf.deallocate() @bci=24, line=508 (Compiled frame)
 - io.netty.buffer.AbstractReferenceCountedByteBuf.release() @bci=39, line=106 (Compiled frame)
 - io.netty.util.ReferenceCountUtil.release(java.lang.Object) @bci=11, line=59 (Compiled frame)
 - io.netty.util.ReferenceCountUtil.safeRelease(java.lang.Object) @bci=1, line=84 (Compiled frame)
 - io.netty.channel.ChannelOutboundBuffer.remove() @bci=40, line=258 (Compiled frame)
 - io.netty.channel.ChannelOutboundBuffer.removeBytes(long) @bci=83, line=334 (Compiled frame)
 - io.netty.channel.socket.nio.NioSocketChannel.doWrite(io.netty.channel.ChannelOutboundBuffer) @bci=238, line=317 (Compiled frame)
 - io.netty.channel.AbstractChannel$AbstractUnsafe.flush0() @bci=89, line=750 (Compiled frame)
 - io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0() @bci=9, line=303 (Compiled frame)
 - io.netty.channel.AbstractChannel$AbstractUnsafe.flush() @bci=15, line=719 (Compiled frame)
 - io.netty.channel.DefaultChannelPipeline$HeadContext.flush(io.netty.channel.ChannelHandlerContext) @bci=4, line=1119 (Compiled frame)
 - io.netty.channel.AbstractChannelHandlerContext.invokeFlush() @bci=8, line=735 (Compiled frame)
 - io.netty.channel.AbstractChannelHandlerContext.access$1500(io.netty.channel.AbstractChannelHandlerContext) @bci=1, line=32 (Compiled frame)
 - io.netty.channel.AbstractChannelHandlerContext$16.run() @bci=4, line=723 (Compiled frame)
 - io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(long) @bci=26, line=357 (Compiled frame)
 - io.netty.channel.nio.NioEventLoop.run() @bci=106, line=357 (Compiled frame)
 - io.netty.util.concurrent.SingleThreadEventExecutor$2.run() @bci=13, line=111 (Interpreted frame)
 - java.lang.Thread.run() @bci=11, line=745 (Interpreted frame)

这里是我的环境。

java version "1.8.0_66"
Linux version 2.6.32-504.el6.x86_64

Answer 1

Linux版本2.6.32-504.el6.x86_64

看起来您使用的内核受到futex_wait bug的困扰。

解决方案是更新到较新的内核。