hbase-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jean-Adrien (JIRA)" <j...@apache.org>
Subject [jira] Created: (HBASE-1214) HRegionServer fails to stop if hdfs client it tries to recover a block
Date Tue, 24 Feb 2009 12:22:02 GMT
HRegionServer fails to stop if hdfs client it tries to recover a block 
-----------------------------------------------------------------------

                 Key: HBASE-1214
                 URL: https://issues.apache.org/jira/browse/HBASE-1214
             Project: Hadoop HBase
          Issue Type: Bug
          Components: master, regionserver
    Affects Versions: 0.19.0
         Environment: 4 Node cluster with poor hardware: (DN+RS / DN+RS / RS / MA+NN)
1 Gb memory each 
Ubuntu linux
Java 6
            Reporter: Jean-Adrien


One of my region server falls in a long GC time that get it unresponsive during about 10 minutes.
As I can see in the log, it seems that its DFSClient component was sending a file to hdfs,
the sending times out when it recovers from GC:

h5. Region server log after recovering from GC
{noformat}
2009-02-21 01:22:26,454 WARN org.apache.hadoop.hdfs.DFSClient: DFSOutputStream ResponseProcessor
exception  for block blk_7545556036225037274_1820952java.io.IOException: Bad response 1 for
block blk_7545556036225037274_1820952 from datanode 192.168.1.10:50010
        at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$ResponseProcessor.run(DFSClient.java:2342)
{noformat}

h5. corresponding error in receiving datanode
{noformat}
2009-02-21 01:23:56,608 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Exception in
receiveBlock for block blk_7545556036225037274_1820952 java.io.EOFException: while trying
to read 65557 bytes
[...]
2009-02-21 01:23:59,076 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder
0 for block blk_7545556036225037274_1820952 Interrupted.
2009-02-21 01:24:01,484 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: PacketResponder
0 for block blk_7545556036225037274_1820952 terminating
2009-02-21 01:24:01,485 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: writeBlock blk_7545556036225037274_1820952
received exception java.io.EOFException: while trying to read 65557 bytes
{noformat}

Since region server misses its lease to report to the master, it has to close all its regions
before recover, and reopens them when the master asks for.
>From this time, it tries to _recover_ this block, as seen in the regionserver log:

h5. Region server log in an endless loop to recover
{noformat}
009-02-21 01:22:29,327 WARN org.apache.hadoop.hdfs.DFSClient: Error Recovery for block blk_7545556036225037274_1820952
bad datanode[1] 192.168.1.10:50010
2009-02-21 01:22:29,327 WARN org.apache.hadoop.hdfs.DFSClient: Error Recovery for block blk_7545556036225037274_1820952
in pipeline 192.168.1.13:50010, 192.
168.1.10:50010: bad datanode 192.168.1.10:50010
2009-02-21 01:22:29,689 WARN org.apache.hadoop.hdfs.DFSClient: Error Recovery for block blk_7545556036225037274_1820952
failed  because recovery from primary datanode 192.168.1.13:50010 failed 2 times. Will retry...
{noformat}

To this _recover_ request, all datanodes fail with this Exception

{noformat}
2009-02-21 01:24:18,650 INFO org.apache.hadoop.ipc.Server: IPC Server handler 1 on 50020,
call recoverBlock(blk_7545556036225037274_1820952, false, [Lorg.apache.hadoop.hdfs.protocol.DatanodeInfo;@311c4f)
from 192.168.1.13:56968: error: org.apache.hadoop.ipc.RemoteException: java.io.IOException:
blk_7545556036225037274_1820952 is already commited, storedBlock == null.
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.nextGenerationStampForBlock(FSNamesystem.java:4536)
        at org.apache.hadoop.hdfs.server.namenode.NameNode.nextGenerationStamp(NameNode.java:402)
        at sun.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:452)
        at org.apache.hadoop.ipc.Server$Handler.run(Server.java:892)

org.apache.hadoop.ipc.RemoteException: java.io.IOException: blk_7545556036225037274_1820952
is already commited, storedBlock == null.
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.nextGenerationStampForBlock(FSNamesystem.java:4536)
        at org.apache.hadoop.hdfs.server.namenode.NameNode.nextGenerationStamp(NameNode.java:402)
        at sun.reflect.GeneratedMethodAccessor16.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:452)
        at org.apache.hadoop.ipc.Server$Handler.run(Server.java:892)

        at org.apache.hadoop.ipc.Client.call(Client.java:696)
        at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:216)
        at $Proxy4.nextGenerationStamp(Unknown Source)
        at org.apache.hadoop.hdfs.server.datanode.DataNode.syncBlock(DataNode.java:1466)
        at org.apache.hadoop.hdfs.server.datanode.DataNode.recoverBlock(DataNode.java:1440)
        at org.apache.hadoop.hdfs.server.datanode.DataNode.recoverBlock(DataNode.java:1506)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:452)
        at org.apache.hadoop.ipc.Server$Handler.run(Server.java:892)
{noformat}

The problem is that, in this case, the RegionServer and therefore the master fails to stop
when I launch the stop-hbase script.
A kill (-TERM) on the region server launches the SIGTERM handler thread, but the loop which
try to reach the block does not stop.
here is a thread dump of the region server at this time:

h5. Thread dump of the region server
{noformat}
Full thread dump Java HotSpot(TM) Server VM (10.0-b23 mixed mode):

"Thread-16" prio=10 tid=0x081c3c00 nid=0x6e81 in Object.wait() [0x8f74f000..0x8f74fec0]
   java.lang.Thread.State: WAITING (on object monitor)                                
        at java.lang.Object.wait(Native Method)                                        
        at java.lang.Thread.join(Thread.java:1143)                                    
        - locked <0x93d0d060> (a java.lang.Thread)                                 
  
        at java.lang.Thread.join(Thread.java:1196)                                    
        at org.apache.hadoop.hbase.util.Threads.shutdown(Threads.java:78)              
        at org.apache.hadoop.hbase.util.Threads.shutdown(Threads.java:66)              
        at org.apache.hadoop.hbase.regionserver.HRegionServer$ShutdownThread.run(HRegionServer.java:814)

"SIGTERM handler" daemon prio=10 tid=0x08dbcc00 nid=0x6e80 in Object.wait() [0x8edaf000..0x8edaff40]
   java.lang.Thread.State: WAITING (on object monitor)                                   
          
        at java.lang.Object.wait(Native Method)                                          
         
        at java.lang.Thread.join(Thread.java:1143)                                       
          
        - locked <0x93d0f3c0> (a org.apache.hadoop.hbase.regionserver.HRegionServer$ShutdownThread)
        at java.lang.Thread.join(Thread.java:1196)                                       
          
        at java.lang.ApplicationShutdownHooks.run(ApplicationShutdownHooks.java:79)      
         
        at java.lang.Shutdown.runHooks(Shutdown.java:89)                                 
          
        at java.lang.Shutdown.sequence(Shutdown.java:133)                                
         
        at java.lang.Shutdown.exit(Shutdown.java:178)                                    
         
        - locked <0xb0d3ed60> (a java.lang.Class for java.lang.Shutdown)           
                
        at java.lang.Terminator$1.handle(Terminator.java:35)                             
          
        at sun.misc.Signal$1.run(Signal.java:195)                                        
         
        at java.lang.Thread.run(Thread.java:619)                                         
          

"Attach Listener" daemon prio=10 tid=0x081e8800 nid=0x6e50 waiting on condition [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE                                                      
             

"IPC Client (47) connection to /192.168.1.13:50020 from an unknown user" daemon prio=10 tid=0x8e97a400
nid=0x39d1 in Object.wait() [0x8ec81000..0x8ec81fc0]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)                             
                                                                
        at java.lang.Object.wait(Native Method)                                          
                                                                 
        at org.apache.hadoop.ipc.Client$Connection.waitForWork(Client.java:395)          
                                                                 
        - locked <0xa44a36a0> (a org.apache.hadoop.ipc.Client$Connection)          
                                                                       
        at org.apache.hadoop.ipc.Client$Connection.run(Client.java:437)                  
                                                                 

"IPC Client (47) connection to /192.168.1.10:50020 from an unknown user" daemon prio=10 tid=0x8e5f1c00
nid=0x523f in Object.wait() [0x8ecd3000..0x8ecd3140]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)                             
                                                                
        at java.lang.Object.wait(Native Method)                                          
                                                                 
        at org.apache.hadoop.ipc.Client$Connection.waitForWork(Client.java:395)          
                                                                 
        - locked <0xa448ca50> (a org.apache.hadoop.ipc.Client$Connection)          
                                                                       
        at org.apache.hadoop.ipc.Client$Connection.run(Client.java:437)                  
                                                                 

"BlockFSInputStreamReferenceQueueChecker" daemon prio=10 tid=0x085a9400 nid=0x8c8 waiting
on condition [0x8ee6c000..0x8ee6cdc0]
   java.lang.Thread.State: WAITING (parking)                                             
                                    
        at sun.misc.Unsafe.park(Native Method)                                           
                                    
        - parking to wait for  <0x93e76068> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
         
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                                    
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
 
        at java.util.concurrent.DelayQueue.take(DelayQueue.java:160)                     
                                    
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:582)
       
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:575)
       
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:946)  
                                     
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:906)
                                   
        at java.lang.Thread.run(Thread.java:619)                                         
                                    

"IPC Server handler 9 on 60020" daemon prio=10 tid=0x0882e000 nid=0x889 waiting on condition
[0x8eebd000..0x8eebdfc0]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 8 on 60020" daemon prio=10 tid=0x0882cc00 nid=0x888 waiting on condition
[0x8ef0e000..0x8ef0f040]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 7 on 60020" daemon prio=10 tid=0x0882b800 nid=0x887 waiting on condition
[0x8ef5f000..0x8ef5fec0]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 6 on 60020" daemon prio=10 tid=0x0882a400 nid=0x886 waiting on condition
[0x8efb0000..0x8efb0f40]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 5 on 60020" daemon prio=10 tid=0x08829000 nid=0x885 waiting on condition
[0x8f001000..0x8f001dc0]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 4 on 60020" daemon prio=10 tid=0x083bcc00 nid=0x884 waiting on condition
[0x8f052000..0x8f052e40]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 3 on 60020" daemon prio=10 tid=0x083bb800 nid=0x883 waiting on condition
[0x8f0a3000..0x8f0a40c0]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 2 on 60020" daemon prio=10 tid=0x083ba400 nid=0x882 waiting on condition
[0x8f0f4000..0x8f0f5140]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 1 on 60020" daemon prio=10 tid=0x083b9400 nid=0x881 waiting on condition
[0x8f145000..0x8f145fc0]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server handler 0 on 60020" daemon prio=10 tid=0x083b8400 nid=0x880 waiting on condition
[0x8f196000..0x8f197040]
   java.lang.Thread.State: WAITING (parking)                                             
                          
        at sun.misc.Unsafe.park(Native Method)                                           
                          
        - parking to wait for  <0x93d0e9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)             
                          
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:358)   
                                  
        at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:881)     
                                  

"IPC Server listener on 60020" daemon prio=10 tid=0x083bfc00 nid=0x87f runnable [0x8f1e7000..0x8f1e7ec0]
   java.lang.Thread.State: RUNNABLE                                                      
             
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)                         
              
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:215)                 
              
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)              
             
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)                 
              
        - locked <0x93d0c090> (a sun.nio.ch.Util$1)                                
                   
        - locked <0x93d0c120> (a java.util.Collections$UnmodifiableSet)            
                   
        - locked <0x93d0c0b0> (a sun.nio.ch.EPollSelectorImpl)                     
                    
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)                          
             
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)                          
             
        at org.apache.hadoop.hbase.ipc.HBaseServer$Listener.run(HBaseServer.java:299)    
             

"IPC Server Responder" daemon prio=10 tid=0x083bec00 nid=0x87e runnable [0x8f238000..0x8f238f40]
   java.lang.Thread.State: RUNNABLE                                                      
     
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)                         
      
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:215)                 
      
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)              
     
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)                 
      
        - locked <0x93d0c0f0> (a sun.nio.ch.Util$1)                                
           
        - locked <0x93d0c100> (a java.util.Collections$UnmodifiableSet)            
           
        - locked <0x93d0be30> (a sun.nio.ch.EPollSelectorImpl)                     
            
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)                          
     
        at org.apache.hadoop.hbase.ipc.HBaseServer$Responder.run(HBaseServer.java:458)   
      

"SocketListener0-1" prio=10 tid=0x088d5000 nid=0x87c in Object.wait() [0x8f2da000..0x8f2dae40]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)                             
    
        at java.lang.Object.wait(Native Method)                                          
   
        at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)               
    
        - locked <0x93e39bc8> (a org.mortbay.util.ThreadPool$PoolThread)           
          

"SocketListener0-0" prio=10 tid=0x08ab5000 nid=0x87b in Object.wait() [0x8f32b000..0x8f32c0c0]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)                             
    
        at java.lang.Object.wait(Native Method)                                          
   
        at org.mortbay.util.ThreadPool$PoolThread.run(ThreadPool.java:522)               
    
        - locked <0x93e39920> (a org.mortbay.util.ThreadPool$PoolThread)           
          

"Acceptor ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=60030]" prio=10 tid=0x084f6800
nid=0x87a runnable [0x8f37c000..0x8f37d140]
   java.lang.Thread.State: RUNNABLE                                                      
                                             
        at java.net.PlainSocketImpl.socketAccept(Native Method)                          
                                             
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)                     
                                            
        - locked <0x93e382a8> (a java.net.SocksSocketImpl)                         
                                                  
        at java.net.ServerSocket.implAccept(ServerSocket.java:453)                       
                                            
        at java.net.ServerSocket.accept(ServerSocket.java:421)                           
                                            
        at org.mortbay.util.ThreadedServer.acceptSocket(ThreadedServer.java:432)         
                                            
        at org.mortbay.util.ThreadedServer$Acceptor.run(ThreadedServer.java:631)         
                                            

"SessionScavenger" daemon prio=10 tid=0x088f1400 nid=0x879 waiting on condition [0x8f3cd000..0x8f3cdfc0]
   java.lang.Thread.State: TIMED_WAITING (sleeping)                                      
             
        at java.lang.Thread.sleep(Native Method)                                         
              
        at org.mortbay.jetty.servlet.AbstractSessionManager$SessionScavenger.run(AbstractSessionManager.java:587)

"SessionScavenger" daemon prio=10 tid=0x08ab5c00 nid=0x878 waiting on condition [0x8f41e000..0x8f41f040]
   java.lang.Thread.State: TIMED_WAITING (sleeping)                                      
             
        at java.lang.Thread.sleep(Native Method)                                         
              
        at org.mortbay.jetty.servlet.AbstractSessionManager$SessionScavenger.run(AbstractSessionManager.java:587)

"regionserver/0.0.0.0:60020.leaseChecker" prio=10 tid=0x086d5800 nid=0x877 waiting on condition
[0x8f476000..0x8f476ec0]
   java.lang.Thread.State: TIMED_WAITING (parking)                                       
                              
        at sun.misc.Unsafe.park(Native Method)                                           
                              
        - parking to wait for  <0x93d0e980> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
 
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)        
                             
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1963)
        at java.util.concurrent.DelayQueue.poll(DelayQueue.java:201)                     
                                      
        at org.apache.hadoop.hbase.Leases.run(Leases.java:78)                            
                                       

"regionserver/0.0.0.0:60020.majorCompactionChecker" daemon prio=10 tid=0x086d4000 nid=0x876
waiting on condition [0x8f4c7000..0x8f4c7f40]
   java.lang.Thread.State: TIMED_WAITING (sleeping)                                      
                                               
        at java.lang.Thread.sleep(Native Method)                                         
                                              
        at org.apache.hadoop.hbase.util.Sleeper.sleep(Sleeper.java:74)                   
                                              
        at org.apache.hadoop.hbase.Chore.run(Chore.java:72)                              
                                               

"LeaseChecker" daemon prio=10 tid=0x0837cc00 nid=0x870 waiting on condition [0x8f6ad000..0x8f6ae040]
   java.lang.Thread.State: TIMED_WAITING (sleeping)                                      
         
        at java.lang.Thread.sleep(Native Method)                                         
          
        at org.apache.hadoop.hdfs.DFSClient$LeaseChecker.run(DFSClient.java:979)         
          
        at java.lang.Thread.run(Thread.java:619)                                         
          

"DataStreamer for file /hbase/log_192.168.1.13_1235129194745_60020/hlog.dat.1235129195649
block blk_7545556036225037274_1820952" daemon prio=10 tid=0x08375400 nid=0x86f in Object.wait()
[0x8f6fe000..0x8f6feec0]                                                                 
                                    
   java.lang.Thread.State: TIMED_WAITING (on object monitor)                             
                                                                  
        at java.lang.Object.wait(Native Method)                                          
                                                                 
        at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer.run(DFSClient.java:2166)
                                                         
        - locked <0x93d0ea10> (a java.util.LinkedList)                             
                                                                        

"DestroyJavaVM" prio=10 tid=0x0805a000 nid=0x855 waiting on condition [0x00000000..0xb7dd2090]
   java.lang.Thread.State: RUNNABLE                                                      
   

"regionserver/0.0.0.0:60020" prio=10 tid=0x085b2400 nid=0x863 in Object.wait() [0x8f7f7000..0x8f7f7f40]
   java.lang.Thread.State: WAITING (on object monitor)                                   
            
        at java.lang.Object.wait(Native Method)                                          
             
        at java.lang.Object.wait(Object.java:485)                                        
             
        at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.flushInternal(DFSClient.java:3015)
       
        - locked <0x93d0ea10> (a java.util.LinkedList)                             
                  
        - locked <0x93d0ec58> (a org.apache.hadoop.hdfs.DFSClient$DFSOutputStream) 
                  
        at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.closeInternal(DFSClient.java:3104)
       
        - locked <0x93d0ec58> (a org.apache.hadoop.hdfs.DFSClient$DFSOutputStream) 
                  
        at org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.close(DFSClient.java:3053)
        at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.close(FSDataOutputStream.java:59)
        at org.apache.hadoop.fs.FSDataOutputStream.close(FSDataOutputStream.java:79)
        at org.apache.hadoop.io.SequenceFile$Writer.close(SequenceFile.java:959)
        - locked <0x93d50d20> (a org.apache.hadoop.io.SequenceFile$Writer)
        at org.apache.hadoop.hbase.regionserver.HLog.close(HLog.java:421)
        - locked <0x93d4ce00> (a java.lang.Integer)
        at org.apache.hadoop.hbase.regionserver.HLog.closeAndDelete(HLog.java:404)
        at org.apache.hadoop.hbase.regionserver.HRegionServer.run(HRegionServer.java:373)
        at java.lang.Thread.run(Thread.java:619)

"Low Memory Detector" daemon prio=10 tid=0x080dd800 nid=0x85e runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x080dc400 nid=0x85d waiting on condition [0x00000000..0x8fbc1588]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x080d9c00 nid=0x85c waiting on condition [0x00000000..0x8fc42608]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x080d8800 nid=0x85b runnable [0x00000000..0x8fc93e80]
   java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (CMS)" daemon prio=10 tid=0x080d7800 nid=0x85a waiting on condition
[0x00000000..0x8fce522c]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x080bbc00 nid=0x859 in Object.wait() [0x8fd7b000..0x8fd7bec0]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x93d0bdc0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x080ba800 nid=0x858 in Object.wait() [0x8fdcc000..0x8fdccf40]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x93d0c110> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x080b7800 nid=0x857 runnable

"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x0806c800 nid=0x856 runnable
"VM Periodic Task Thread" prio=10 tid=0x080df000 nid=0x85f waiting on condition

JNI global references: 922
{noformat}

Notice the DataStreamer thread that seems to work on the concerned block
This force me to kill (-KILL) the region server, and restart the hdfs (if I don't restart
hdfs some regions are not available because the block is still not available).

Note that the Hbase master does not end as well, and I have to kill (-KILL). Here is the thread
dump of the HMaster process:

h5. Master thread dump:

{noformat}
Full thread dump Java HotSpot(TM) Server VM (10.0-b23 mixed mode):

"Attach Listener" daemon prio=10 tid=0x0805a000 nid=0x2326 waiting on condition [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE                                                      
             

"SIGTERM handler" daemon prio=10 tid=0x089f0c00 nid=0x2303 waiting for monitor entry [0x8a6a5000..0x8a6a5ec0]
   java.lang.Thread.State: BLOCKED (on object monitor)                                   
                  
        at java.lang.Shutdown.exit(Shutdown.java:178)                                    
                   
        - waiting to lock <0xb0beed60> (a java.lang.Class for java.lang.Shutdown)  
                         
        at java.lang.Terminator$1.handle(Terminator.java:35)                             
                  
        at sun.misc.Signal$1.run(Signal.java:195)                                        
                   
        at java.lang.Thread.run(Thread.java:619)                                         
                  

"Thread-1" prio=10 tid=0x8f666000 nid=0x653c waiting on condition [0x8f1fe000..0x8f1fef40]
   java.lang.Thread.State: TIMED_WAITING (sleeping)                                      
        at java.lang.Thread.sleep(Native Method)                                         

        at org.apache.hadoop.ipc.Client.stop(Client.java:667)                            
        at org.apache.hadoop.ipc.RPC$ClientCache.stopClient(RPC.java:189)                
        at org.apache.hadoop.ipc.RPC$ClientCache.access$400(RPC.java:138)                
        at org.apache.hadoop.ipc.RPC$Invoker.close(RPC.java:229)                         

        - locked <0x938a1b18> (a org.apache.hadoop.ipc.RPC$Invoker)                
     
        at org.apache.hadoop.ipc.RPC$Invoker.access$500(RPC.java:196)                    
        at org.apache.hadoop.ipc.RPC.stopProxy(RPC.java:353)                             

        at org.apache.hadoop.hdfs.DFSClient.close(DFSClient.java:213)                    
        - locked <0x93878470> (a org.apache.hadoop.hdfs.DFSClient)                 
      
        at org.apache.hadoop.hdfs.DistributedFileSystem.close(DistributedFileSystem.java:243)
        at org.apache.hadoop.fs.FileSystem$Cache.closeAll(FileSystem.java:1413)          
   
        - locked <0x937d3c00> (a org.apache.hadoop.fs.FileSystem$Cache)            
         
        at org.apache.hadoop.fs.FileSystem.closeAll(FileSystem.java:236)                 
  
        at org.apache.hadoop.fs.FileSystem$ClientFinalizer.run(FileSystem.java:221)      
   
        - locked <0x937b8a78> (a org.apache.hadoop.fs.FileSystem$ClientFinalizer)  
         

"DestroyJavaVM" prio=10 tid=0x8f66c800 nid=0x36e9 in Object.wait() [0xb7d7d000..0xb7d7e0e0]
   java.lang.Thread.State: WAITING (on object monitor)                                   

        at java.lang.Object.wait(Native Method)                                          
 
        at java.lang.Thread.join(Thread.java:1143)                                       

        - locked <0x937b8a78> (a org.apache.hadoop.fs.FileSystem$ClientFinalizer)  
       
        at java.lang.Thread.join(Thread.java:1196)
        at java.lang.ApplicationShutdownHooks.run(ApplicationShutdownHooks.java:79)
        at java.lang.Shutdown.runHooks(Shutdown.java:89)
        at java.lang.Shutdown.sequence(Shutdown.java:133)
        at java.lang.Shutdown.shutdown(Shutdown.java:200)
        - locked <0xb0beed60> (a java.lang.Class for java.lang.Shutdown)

"Low Memory Detector" daemon prio=10 tid=0x8fe03800 nid=0x36f4 runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x8fe01c00 nid=0x36f3 waiting on condition [0x00000000..0x8f9ee488]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x8fe00800 nid=0x36f2 waiting on condition [0x00000000..0x8fa6f508]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x0813e800 nid=0x36f1 runnable [0x00000000..0x8fac0d80]
   java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (CMS)" daemon prio=10 tid=0x0813d800 nid=0x36f0 waiting on condition
[0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x08125000 nid=0x36ef in Object.wait() [0x8fba1000..0x8fba1dc0]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x937bafd8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x08120c00 nid=0x36ee in Object.wait() [0x8fbf2000..0x8fbf2e40]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x937baf18> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x0811d800 nid=0x36ed runnable

"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x0805e000 nid=0x36ea runnable

"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x0805f000 nid=0x36eb runnable

"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x080cd000 nid=0x36ec runnable
"VM Periodic Task Thread" prio=10 tid=0x8fe05000 nid=0x36f5 waiting on condition

JNI global references: 1044
{noformat}

When I restart dfs, the log shows me that the concerned block is marked as invalidate, and
it is therefore deleted:

h5. Namenode log
{noformat}
2009-02-23 10:33:49,245 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.processReport:
block blk_7545556036225037274_1820952 on 192.168.1.10:50010 size 27895296 does not
 belong to any file.
2009-02-23 10:33:49,245 INFO org.apache.hadoop.hdfs.StateChange: BLOCK* NameSystem.addToInvalidates:
blk_7545556036225037274 is added to invalidSet of 192.168.1.10:50010
{noformat}

Finally, when I restart HBase, I can see some of these messages in region server log, and
I have some data loss. (this log entry may not be linked with the  block traced before)

h5. Region server log:
{noformat}
2009-02-23 10:38:55,831 WARN org.apache.hadoop.hbase.regionserver.HStore: Exception processing
reconstruction log hdfs://lab5-2:9000/hbase/test-D-0.3/510178748/oldlogfile.log opening [B@ff65bf
-- continuing.  Probably lack-of-HADOOP-1700 causing DATA LOSS!
java.io.EOFException
        at java.io.DataInputStream.readFully(DataInputStream.java:180)
        at org.apache.hadoop.hbase.io.DataOutputBuffer$Buffer.write(DataOutputBuffer.java:70)
        at org.apache.hadoop.hbase.io.DataOutputBuffer.write(DataOutputBuffer.java:116)
        at org.apache.hadoop.hbase.io.SequenceFile$Reader.next(SequenceFile.java:1944)
        at org.apache.hadoop.hbase.io.SequenceFile$Reader.next(SequenceFile.java:1844)
        at org.apache.hadoop.hbase.io.SequenceFile$Reader.next(SequenceFile.java:1890)
        at org.apache.hadoop.hbase.regionserver.HStore.doReconstructionLog(HStore.java:352)
        at org.apache.hadoop.hbase.regionserver.HStore.runReconstructionLog(HStore.java:297)
        at org.apache.hadoop.hbase.regionserver.HStore.<init>(HStore.java:237)
        at org.apache.hadoop.hbase.regionserver.HRegion.instantiateHStore(HRegion.java:1764)
        at org.apache.hadoop.hbase.regionserver.HRegion.initialize(HRegion.java:276)
        at org.apache.hadoop.hbase.regionserver.HRegionServer.instantiateRegion(HRegionServer.java:1367)
        at org.apache.hadoop.hbase.regionserver.HRegionServer.openRegion(HRegionServer.java:1338)
        at org.apache.hadoop.hbase.regionserver.HRegionServer$Worker.run(HRegionServer.java:1253)
        at java.lang.Thread.run(Thread.java:619)
{noformat}

In my sense, since my hardware is in cause for RegionServer lease miss, I have to deal with
the fact that I have to stop/restart hbase + hadoop in such a case. The problem in my sense
is that a stop request should be able to perform a clean shutdown, and to avoid dataloss.

Hope this description helps.


-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


Mime
View raw message