crazyjohn / crazyjohn.github.io

crazyjohn's blog
9 stars 3 forks source link

oversea2016420线上事故还原 #49

Open crazyjohn opened 8 years ago

crazyjohn commented 8 years ago

20160420早上,连平反馈服务器无法登陆。

1. 问题定位

看下堆栈:

  1. nttty的所有io线程都在阻塞等待一个锁:0x00000000d03a4c80

    "nioEventLoopGroup-3-16" prio=10 tid=0x00007ffab8027800 nid=0x286b waiting for monitor entry [0x00007ffaf4fac000]
      java.lang.Thread.State: BLOCKED (on object monitor)
       at org.apache.log4j.Category.callAppenders(Category.java:204)
       - waiting to lock <0x00000000d03a4c80> (a org.apache.log4j.spi.RootLogger)
       at org.apache.log4j.Category.forcedLog(Category.java:391)
       at org.apache.log4j.Category.info(Category.java:666)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.channelInactive(WebSocketIoHandler.java:168)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
       at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
       at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:306)
       at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:132)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
       at io.netty.handler.codec.ReplayingDecoder.channelInactive(ReplayingDecoder.java:352)
       at io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder.channelInactive(WebSocket08FrameDecoder.java:506)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
       at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
       at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
       at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
       at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
       at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
       at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
       at java.lang.Thread.run(Thread.java:745)
    
      Locked ownable synchronizers:
       - None
    
    "nioEventLoopGroup-3-15" prio=10 tid=0x00007ffab8026000 nid=0x2869 waiting for monitor entry [0x00007ffaf50ad000]
      java.lang.Thread.State: BLOCKED (on object monitor)
       at org.apache.log4j.Category.callAppenders(Category.java:204)
       - waiting to lock <0x00000000d03a4c80> (a org.apache.log4j.spi.RootLogger)
       at org.apache.log4j.Category.forcedLog(Category.java:391)
       at org.apache.log4j.Category.log(Category.java:856)
       at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:229)
       at io.netty.util.internal.logging.Slf4JLogger.debug(Slf4JLogger.java:76)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker13.newHandshakeResponse(WebSocketServerHandshaker13.java:122)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker.handshake(WebSocketServerHandshaker.java:170)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker.handshake(WebSocketServerHandshaker.java:145)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.handleHttpRequest(WebSocketIoHandler.java:103)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.channelRead0(WebSocketIoHandler.java:52)
       at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
       at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
       at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
       at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
       at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
       at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
       at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
       at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
       at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
       at java.lang.Thread.run(Thread.java:745)
    
      Locked ownable synchronizers:
       - None
    
    "nioEventLoopGroup-3-14" prio=10 tid=0x00007ffab8024800 nid=0x2867 waiting for monitor entry [0x00007ffaf51ad000]
      java.lang.Thread.State: BLOCKED (on object monitor)
       at org.apache.log4j.Category.callAppenders(Category.java:204)
       - waiting to lock <0x00000000d03a4c80> (a org.apache.log4j.spi.RootLogger)
       at org.apache.log4j.Category.forcedLog(Category.java:391)
       at org.apache.log4j.Category.info(Category.java:666)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.channelInactive(WebSocketIoHandler.java:168)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
       at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
       at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:306)
       at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:132)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
       at io.netty.handler.codec.ReplayingDecoder.channelInactive(ReplayingDecoder.java:352)
       at io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder.channelInactive(WebSocket08FrameDecoder.java:506)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
       at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
       at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
       at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:358)
       at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
       at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
       at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
       at java.lang.Thread.run(Thread.java:745)
    
      Locked ownable synchronizers:
       - None
    
    "nioEventLoopGroup-3-13" prio=10 tid=0x00007ffab8023000 nid=0x2865 waiting for monitor entry [0x00007ffaf52af000]
      java.lang.Thread.State: BLOCKED (on object monitor)
       at org.apache.log4j.Category.callAppenders(Category.java:204)
       - waiting to lock <0x00000000d03a4c80> (a org.apache.log4j.spi.RootLogger)
       at org.apache.log4j.Category.forcedLog(Category.java:391)
       at org.apache.log4j.Category.log(Category.java:856)
       at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:252)
       at io.netty.util.internal.logging.Slf4JLogger.debug(Slf4JLogger.java:81)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker.handshake(WebSocketServerHandshaker.java:168)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker.handshake(WebSocketServerHandshaker.java:145)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.handleHttpRequest(WebSocketIoHandler.java:103)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.channelRead0(WebSocketIoHandler.java:52)
       at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
       at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
       at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
       at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
       at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
       at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
       at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
       at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
       at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
       at java.lang.Thread.run(Thread.java:745)
    
      Locked ownable synchronizers:
       - None
    
    "nioEventLoopGroup-3-12" prio=10 tid=0x00007ffab8021000 nid=0x2863 waiting for monitor entry [0x00007ffaf53af000]
      java.lang.Thread.State: BLOCKED (on object monitor)
       at org.apache.log4j.Category.callAppenders(Category.java:204)
       - waiting to lock <0x00000000d03a4c80> (a org.apache.log4j.spi.RootLogger)
       at org.apache.log4j.Category.forcedLog(Category.java:391)
       at org.apache.log4j.Category.log(Category.java:856)
       at org.slf4j.impl.Log4jLoggerAdapter.warn(Log4jLoggerAdapter.java:421)
       at io.netty.util.internal.logging.Slf4JLogger.warn(Slf4JLogger.java:136)
       at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:673)
       at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:262)
       at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:342)
       at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:318)
       at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:761)
       at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:311)
       at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:729)
       at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1127)
       at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:663)
       at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:644)
       at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:115)
       at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:663)
       at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:644)
       at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:115)
       at io.netty.channel.CombinedChannelDuplexHandler.flush(CombinedChannelDuplexHandler.java:197)
       at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:663)
       at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:644)
       at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:115)
       at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:663)
       at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:693)
       at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:681)
       at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:716)
       at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:954)
       at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:244)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker.handshake(WebSocketServerHandshaker.java:197)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker.handshake(WebSocketServerHandshaker.java:145)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.handleHttpRequest(WebSocketIoHandler.java:103)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.channelRead0(WebSocketIoHandler.java:52)
       at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
       at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
       at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
       at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
       at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
       at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
       at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
       at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
       at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
       at java.lang.Thread.run(Thread.java:745)
    
      Locked ownable synchronizers:
       - None
    
    "nioEventLoopGroup-3-11" prio=10 tid=0x00007ffab801f000 nid=0x2862 waiting for monitor entry [0x00007ffaf54b1000]
      java.lang.Thread.State: BLOCKED (on object monitor)
       at org.apache.log4j.Category.callAppenders(Category.java:204)
       - waiting to lock <0x00000000d03a4c80> (a org.apache.log4j.spi.RootLogger)
       at org.apache.log4j.Category.forcedLog(Category.java:391)
       at org.apache.log4j.Category.log(Category.java:856)
       at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:252)
       at io.netty.util.internal.logging.Slf4JLogger.debug(Slf4JLogger.java:81)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker.handshake(WebSocketServerHandshaker.java:168)
       at io.netty.handler.codec.http.websocketx.WebSocketServerHandshaker.handshake(WebSocketServerHandshaker.java:145)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.handleHttpRequest(WebSocketIoHandler.java:103)
       at com.mind.core.net.websocket.server.WebSocketIoHandler.channelRead0(WebSocketIoHandler.java:52)
       at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)
       at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:147)
       at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:308)
       at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:294)
       at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)
       at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
       at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
       at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
       at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
       at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
       at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
       at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
       at java.lang.Thread.run(Thread.java:745)
    
      Locked ownable synchronizers:
       - None
  2. 再看看这个锁谁在持有:

    "pool-2-thread-2" prio=10 tid=0x00007ffb9c51d000 nid=0x282c runnable [0x00007ffaf65c2000]
      java.lang.Thread.State: RUNNABLE
       at java.io.FileOutputStream.writeBytes(Native Method)
       at java.io.FileOutputStream.write(FileOutputStream.java:345)
       at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
       at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
       at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)
       - locked <0x00000000ddc7f4c0> (a java.io.OutputStreamWriter)
       at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:135)
       at java.io.OutputStreamWriter.write(OutputStreamWriter.java:220)
       at java.io.Writer.write(Writer.java:157)
       at org.apache.log4j.helpers.QuietWriter.write(QuietWriter.java:48)
       at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:317)
       at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)
       at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
       at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
       - locked <0x00000000d03a8a30> (a org.apache.log4j.DailyRollingFileAppender)
       at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
       at org.apache.log4j.Category.callAppenders(Category.java:206)
       - locked <0x00000000d03a4c80> (a org.apache.log4j.spi.RootLogger)
       at org.apache.log4j.Category.forcedLog(Category.java:391)
       at org.apache.log4j.Category.log(Category.java:856)
       at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:576)
       at com.mind.common.TimerTaskManager$FeedbackData.run(TimerTaskManager.java:231)
       at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
       at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
       at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
       at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
       at java.lang.Thread.run(Thread.java:745)
    
      Locked ownable synchronizers:
       - <0x00000000d68f7730> (a java.util.concurrent.ThreadPoolExecutor$Worker)
    - 

是它是它就是它。是类TimerTaskManagerFeedbackData的执行时候持有锁一直没有释放,所有io线程都在等这个锁。

2. 问题处理

@旭宁@涅槃@航儿紧急停服重启,发现服务器无法启动无日志输出,接着拉堆栈看信息:

"pool-1-thread-30" prio=10 tid=0x00007f305c859800 nid=0x7cb3 runnable [0x00007f2fd70ee000]
   java.lang.Thread.State: RUNNABLE
    at java.io.FileOutputStream.writeBytes(Native Method)
    at java.io.FileOutputStream.write(FileOutputStream.java:345)
    at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
    at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
    at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)
    - locked <0x00000000d16e9a80> (a java.io.OutputStreamWriter)
    at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:135)
    at java.io.OutputStreamWriter.write(OutputStreamWriter.java:220)
    at java.io.Writer.write(Writer.java:157)
    at org.apache.log4j.helpers.QuietWriter.write(QuietWriter.java:48)
    at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
    at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)
    at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
    at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
    - locked <0x00000000d16df730> (a org.apache.log4j.DailyRollingFileAppender)
    at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
    at org.apache.log4j.Category.callAppenders(Category.java:206)
    - locked <0x00000000d162ed30> (a org.apache.log4j.spi.RootLogger)
    at org.apache.log4j.Category.forcedLog(Category.java:391)
    at org.apache.log4j.Category.log(Category.java:856)
    at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:498)
    at com.mind.login.manager.LoginManager.login(LoginManager.java:288)
    at com.mind.login.LoginHandler.execute(LoginHandler.java:36)
    at com.mind.core.net.handler.HandlerManager.execute(HandlerManager.java:95)
    at com.mind.core.net.processor.QueueMessageProcessor.process(QueueMessageProcessor.java:163)
    at com.mind.core.net.processor.QueueMessageProcessor.run(QueueMessageProcessor.java:127)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - <0x00000000d76539d8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

发现很多io线程在等待这个锁,那为何写日志的时候回阻塞呢?猜想磁盘满了,看下磁盘信息:

[root@vm10-254-169-156 ~]# df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/VolGroup-lv_root
                       12G  4.0G  7.1G  36% /
tmpfs                  18G     0   18G   0% /dev/shm
/dev/vda1             194M   36M  149M  20% /boot
/dev/vdc1             493G  493G     0 100% /data

果然,data那里满了,需要清理磁盘。

3. 描述问题

整体来说这次的问题就是:mysql反馈那里的异常一直输出+磁盘大量无用日志堆积,最后导致磁盘满,log4j无法输出,而log4j的锁用的是synchronized独占锁,所以其它需要记录日志的地方都在饥饿等待,阻塞掉了,io线程阻塞以后,netty不处理io事件,导致无法登陆。

4. 技术定位以及故障处理时间

收到反馈以后处理时间在20分钟以内。

888. 反思总结

  1. 目前反馈机制以及流程这里有问题,客服是最接近玩家的一个群体,要第一时间搜集玩家反馈信息,然后反馈给内部相应部门进行处理。
  2. 我们需要有专业的运维来进行服务器的监控,预警,维护,防止出现磁盘满这种情况。
  3. 剩余大家补充。。。