Return-Path: X-Original-To: apmail-hbase-issues-archive@www.apache.org Delivered-To: apmail-hbase-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 871BC1074D for ; Tue, 10 Dec 2013 02:28:07 +0000 (UTC) Received: (qmail 47717 invoked by uid 500); 10 Dec 2013 02:28:07 -0000 Delivered-To: apmail-hbase-issues-archive@hbase.apache.org Received: (qmail 47690 invoked by uid 500); 10 Dec 2013 02:28:07 -0000 Mailing-List: contact issues-help@hbase.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list issues@hbase.apache.org Received: (qmail 47681 invoked by uid 99); 10 Dec 2013 02:28:07 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 10 Dec 2013 02:28:07 +0000 Date: Tue, 10 Dec 2013 02:28:07 +0000 (UTC) From: "Jeffrey Zhong (JIRA)" To: issues@hbase.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (HBASE-10059) TestSplitLogWorker#testMultipleTasks fails occasionally MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HBASE-10059?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ] Jeffrey Zhong updated HBASE-10059: ---------------------------------- Resolution: Fixed Fix Version/s: 0.96.2 0.98.0 Hadoop Flags: Reviewed Status: Resolved (was: Patch Available) Thanks [~jxiang] for the review. I've integrated the minor fix into 0.96, 0.98 and trunk.Thanks. > 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)