[ 
https://issues.apache.org/jira/browse/HBASE-10059?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13844132#comment-13844132
 ] 

Hudson commented on HBASE-10059:
--------------------------------

SUCCESS: Integrated in hbase-0.96-hadoop2 #146 (See 
[https://builds.apache.org/job/hbase-0.96-hadoop2/146/])
HBASE-10059: TestSplitLogWorker#testMultipleTasks fails occasionally (jeffreyz: 
rev 1549742)
* 
/hbase/branches/0.96/hbase-server/src/test/java/org/apache/hadoop/hbase/regionserver/TestSplitLogWorker.java


> TestSplitLogWorker#testMultipleTasks fails occasionally
> -------------------------------------------------------
>
>                 Key: HBASE-10059
>                 URL: https://issues.apache.org/jira/browse/HBASE-10059
>             Project: HBase
>          Issue Type: Test
>            Reporter: Ted Yu
>            Assignee: Jeffrey Zhong
>             Fix For: 0.98.0, 0.96.2
>
>         Attachments: hbase-10059.patch
>
>
> From 
> https://builds.apache.org/job/HBase-TRUNK-on-Hadoop-2.0.0/857/testReport/junit/org.apache.hadoop.hbase.regionserver/TestSplitLogWorker/testMultipleTasks/
>  :
> {code}
> 2013-11-30 01:13:23,022 INFO  [pool-1-thread-1] hbase.ResourceChecker(147): 
> before: regionserver.TestSplitLogWorker#testMultipleTasks Thread=16, 
> OpenFileDescriptor=157, MaxFileDescriptor=40000, SystemLoadAverage=338, 
> ProcessCount=144, AvailableMemoryMB=1474, ConnectionCount=0
> 2013-11-30 01:13:23,026 INFO  [pool-1-thread-1] 
> zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK 
> server on client port: 53800
> 2013-11-30 01:13:23,029 INFO  [pool-1-thread-1] 
> zookeeper.RecoverableZooKeeper(120): Process 
> identifier=split-log-worker-tests connecting to ZooKeeper 
> ensemble=localhost:53800
> 2013-11-30 01:13:23,249 DEBUG [pool-1-thread-1-EventThread] 
> zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, 
> quorum=localhost:53800, baseZNode=/hbase Received ZooKeeper Event, type=None, 
> state=SyncConnected, path=null
> 2013-11-30 01:13:23,251 DEBUG [pool-1-thread-1-EventThread] 
> zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x142a69133500000 
> connected
> 2013-11-30 01:13:23,261 DEBUG [pool-1-thread-1] 
> regionserver.TestSplitLogWorker(105): /hbase created
> 2013-11-30 01:13:23,270 DEBUG [pool-1-thread-1] 
> regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2013-11-30 01:13:23,278 DEBUG [pool-1-thread-1] executor.ExecutorService(99): 
> Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, 
> corePoolSize=10, maxPoolSize=10
> 2013-11-30 01:13:23,278 INFO  [pool-1-thread-1] 
> regionserver.TestSplitLogWorker(246): testMultipleTasks
> 2013-11-30 01:13:23,280 INFO  [SplitLogWorker-tmt_svr,1,1] 
> regionserver.SplitLogWorker(175): SplitLogWorker tmt_svr,1,1 starting
> 2013-11-30 01:13:23,380 INFO  [pool-1-thread-1] hbase.Waiter(174): Waiting up 
> to [1,500] milli-secs(wait.for.ratio=[1])
> 2013-11-30 01:13:23,394 DEBUG [pool-1-thread-1-EventThread] 
> zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x142a69133500000, 
> quorum=localhost:53800, baseZNode=/hbase Received ZooKeeper Event, 
> type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2013-11-30 01:13:23,394 DEBUG [pool-1-thread-1-EventThread] 
> regionserver.SplitLogWorker(595): tasks arrived or departed
> 2013-11-30 01:13:23,394 INFO  [pool-1-thread-1] hbase.Waiter(174): Waiting up 
> to [1,500] milli-secs(wait.for.ratio=[1])
> 2013-11-30 01:13:23,402 INFO  [SplitLogWorker-tmt_svr,1,1] 
> regionserver.SplitLogWorker(363): worker tmt_svr,1,1 acquired task 
> /hbase/splitWAL/tmt_task
> 2013-11-30 01:13:23,410 DEBUG [pool-1-thread-1-EventThread] 
> zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x142a69133500000, 
> quorum=localhost:53800, baseZNode=/hbase Received ZooKeeper Event, 
> type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2013-11-30 01:13:23,410 DEBUG [pool-1-thread-1-EventThread] 
> regionserver.SplitLogWorker(595): tasks arrived or departed
> 2013-11-30 01:13:23,418 DEBUG [pool-1-thread-1-EventThread] 
> zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x142a69133500000, 
> quorum=localhost:53800, baseZNode=/hbase Received ZooKeeper Event, 
> type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/tmt_task
> 2013-11-30 01:13:23,419 INFO  [pool-1-thread-1] hbase.Waiter(174): Waiting up 
> to [1,500] milli-secs(wait.for.ratio=[1])
> 2013-11-30 01:13:23,420 INFO  [pool-1-thread-1-EventThread] 
> regionserver.SplitLogWorker(522): task /hbase/splitWAL/tmt_task preempted 
> from tmt_svr,1,1, current task state and owner=OWNED another-worker,1,1
> 2013-11-30 01:13:23,420 INFO  [pool-1-thread-1-EventThread] 
> regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2013-11-30 01:13:23,420 WARN  [SplitLogWorker-tmt_svr,1,1] 
> regionserver.SplitLogWorker(374): Interrupted while yielding for other region 
> servers
> java.lang.InterruptedException: sleep interrupted
>       at java.lang.Thread.sleep(Native Method)
>       at 
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.grabTask(SplitLogWorker.java:372)
>       at 
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:251)
>       at 
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209)
>       at java.lang.Thread.run(Thread.java:662)
> 2013-11-30 01:13:23,427 INFO  [SplitLogWorker-tmt_svr,1,1] 
> regionserver.SplitLogWorker(363): worker tmt_svr,1,1 acquired task 
> /hbase/splitWAL/tmt_task_2
> 2013-11-30 01:13:24,331 DEBUG [SplitLogWorker-tmt_svr,1,1] 
> regionserver.SplitLogWorker(253): Current region server tmt_svr,1,1 has 2 
> tasks in progress and can't take more.
> 2013-11-30 01:13:24,921 INFO  [pool-1-thread-1] 
> regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2013-11-30 01:13:24,921 INFO  [SplitLogWorker-tmt_svr,1,1] 
> regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting 
> for task, exiting: java.lang.InterruptedException
> 2013-11-30 01:13:24,921 INFO  [SplitLogWorker-tmt_svr,1,1] 
> regionserver.SplitLogWorker(216): SplitLogWorker tmt_svr,1,1 exiting
> 2013-11-30 01:13:24,922 WARN  [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] 
> regionserver.SplitLogWorker(426): Interrupted while trying to assert 
> ownership of /hbase/splitWAL/tmt_task java.lang.InterruptedException
>       at java.lang.Object.wait(Native Method)
>       at java.lang.Object.wait(Object.java:485)
>       at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
>       at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1264)
>       at 
> org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:407)
>       at 
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.attemptToOwnTask(SplitLogWorker.java:406)
>       at 
> org.apache.hadoop.hbase.regionserver.SplitLogWorker$2.progress(SplitLogWorker.java:474)
>       at 
> org.apache.hadoop.hbase.regionserver.TestSplitLogWorker$2.exec(TestSplitLogWorker.java:135)
>       at 
> org.apache.hadoop.hbase.regionserver.handler.HLogSplitterHandler.process(HLogSplitterHandler.java:79)
>       at 
> org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128)
>       at 
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
>       at 
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
>       at java.lang.Thread.run(Thread.java:662)
> 2013-11-30 01:13:24,922 WARN  [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] 
> regionserver.SplitLogWorker(426): Interrupted while trying to assert 
> ownership of /hbase/splitWAL/tmt_task_2 java.lang.InterruptedException
>       at java.lang.Object.wait(Native Method)
>       at java.lang.Object.wait(Object.java:485)
>       at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1309)
>       at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1264)
>       at 
> org.apache.hadoop.hbase.zookeeper.RecoverableZooKeeper.setData(RecoverableZooKeeper.java:407)
>       at 
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.attemptToOwnTask(SplitLogWorker.java:406)
>       at 
> org.apache.hadoop.hbase.regionserver.SplitLogWorker$2.progress(SplitLogWorker.java:474)
>       at 
> org.apache.hadoop.hbase.regionserver.TestSplitLogWorker$2.exec(TestSplitLogWorker.java:135)
>       at 
> org.apache.hadoop.hbase.regionserver.handler.HLogSplitterHandler.process(HLogSplitterHandler.java:79)
>       at 
> org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128)
>       at 
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
>       at 
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
>       at java.lang.Thread.run(Thread.java:662)
> 2013-11-30 01:13:24,922 WARN  [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] 
> regionserver.SplitLogWorker$2(477): Failed to heartbeat the 
> task/hbase/splitWAL/tmt_task
> 2013-11-30 01:13:24,923 WARN  [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] 
> regionserver.SplitLogWorker$2(477): Failed to heartbeat the 
> task/hbase/splitWAL/tmt_task_2
> 2013-11-30 01:13:24,923 WARN  [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] 
> handler.HLogSplitterHandler(87): task execution prempted tmt_task
> 2013-11-30 01:13:24,923 WARN  [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] 
> handler.HLogSplitterHandler(87): task execution prempted tmt_task_2
> 2013-11-30 01:13:24,923 INFO  [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] 
> handler.HLogSplitterHandler(107): worker tmt_svr,1,1 done with task 
> /hbase/splitWAL/tmt_task in 1520ms
> 2013-11-30 01:13:24,924 INFO  [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] 
> handler.HLogSplitterHandler(107): worker tmt_svr,1,1 done with task 
> /hbase/splitWAL/tmt_task_2 in 1497ms
> 2013-11-30 01:13:24,951 ERROR [SyncThread:0] server.NIOServerCnxn(180): 
> Unexpected Exception: 
> java.nio.channels.CancelledKeyException
>       at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
>       at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
>       at 
> org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:153)
>       at 
> org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1076)
>       at 
> org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:404)
>       at 
> org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:167)
>       at 
> org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:101)
> 2013-11-30 01:13:24,952 INFO  [pool-1-thread-1] 
> zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK 
> servers
> 2013-11-30 01:13:24,966 INFO  [pool-1-thread-1] hbase.ResourceChecker(171): 
> after: regionserver.TestSplitLogWorker#testMultipleTasks Thread=18 (was 16)
> Potentially hanging thread: pool-1-thread-1-SendThread(localhost:53800)
>       java.lang.Thread.sleep(Native Method)
>       
> org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219)
>       org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1157)
>       org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1097)
>  - Thread LEAK? -, OpenFileDescriptor=163 (was 157) - OpenFileDescriptor 
> LEAK? -, MaxFileDescriptor=40000 (was 40000), SystemLoadAverage=327 (was 
> 338), 
> {code}
> 'Interrupted while trying to assert ownership' doesn't show up in a green run.



--
This message was sent by Atlassian JIRA
(v6.1.4#6159)

Reply via email to