You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "stack (JIRA)" <ji...@apache.org> on 2015/10/19 23:56:27 UTC
[jira] [Resolved] (HBASE-10978) TestSplitLogWorker.testRescan times
out waiting on preempt count to go up
[ https://issues.apache.org/jira/browse/HBASE-10978?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
stack resolved HBASE-10978.
---------------------------
Resolution: Later
Resolving as 'later'.
> TestSplitLogWorker.testRescan times out waiting on preempt count to go up
> -------------------------------------------------------------------------
>
> Key: HBASE-10978
> URL: https://issues.apache.org/jira/browse/HBASE-10978
> Project: HBase
> Issue Type: Bug
> Reporter: stack
> Priority: Minor
>
> On our internal rig we got the below. The test times out waiting on the preempted worker tasks to go up:
> ZKUtil.setData(zkw, task, slt.toByteArray());
> waitForCounter(SplitLogCounters.tot_wkr_preempt_task, 1, 2, WAIT_TIME);
> I see the preempt come in and get logged but at same time, the task has completed in about the timeout time:
> 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted task
> 2014-04-13 22:38:26,868 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1504ms
> We timed out before the preempt got to up the counter. Let me keep an eye on these...... Will up timeout and add more logging if we see this again.
> {code}
> Regression
> org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.testRescan
> Failing for the past 1 build (Since Failed#4 )
> Took 2 ms.
> add description
> Error Message
> Waiting timed out after [1,500] msec
> Stacktrace
> junit.framework.AssertionFailedError: Waiting timed out after [1,500] msec
> at junit.framework.Assert.fail(Assert.java:57)
> at org.apache.hadoop.hbase.Waiter.waitFor(Waiter.java:193)
> at org.apache.hadoop.hbase.HBaseTestingUtility.waitFor(HBaseTestingUtility.java:3247)
> at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.waitForCounterBoolean(TestSplitLogWorker.java:82)
> at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.waitForCounterBoolean(TestSplitLogWorker.java:76)
> at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.waitForCounter(TestSplitLogWorker.java:69)
> at org.apache.hadoop.hbase.regionserver.TestSplitLogWorker.testRescan(TestSplitLogWorker.java:320)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:606)
> at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> at org.junit.runners.Suite.runChild(Suite.java:127)
> at org.junit.runners.Suite.runChild(Suite.java:26)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> 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:724)
> Standard Output
> 2014-04-13 22:38:12,096 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testPreemptTask Thread=5, OpenFileDescriptor=95, MaxFileDescriptor=32768, SystemLoadAverage=708, ProcessCount=459, AvailableMemoryMB=4258, ConnectionCount=0
> 2014-04-13 22:38:12,145 INFO [pool-1-thread-1] hbase.HBaseTestingUtility(375): Created new mini-cluster data directory: /var/lib/jenkins/workspace/CDH5.0.1-HBase-0.96.1.1/hbase-server/target/test-data/c8c0b7df-ee6e-4987-96f6-31450e4b21a7/dfscluster_8023fe06-5515-41e4-8ed1-dc0ef9642d55, deleteOnExit=true
> 2014-04-13 22:38:12,389 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 64068
> 2014-04-13 22:38:12,456 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:64068
> 2014-04-13 22:38:13,941 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:64068, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
> 2014-04-13 22:38:13,943 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe2ab80000 connected
> 2014-04-13 22:38:13,979 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created
> 2014-04-13 22:38:13,985 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2014-04-13 22:38:14,014 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10
> 2014-04-13 22:38:14,014 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(213): testPreemptTask
> 2014-04-13 22:38:14,246 INFO [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(175): SplitLogWorker tpt_svr,1,1 starting
> 2014-04-13 22:38:15,256 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [5,000] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:15,493 WARN [pool-1-thread-1] util.NativeCodeLoader(62): Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
> 2014-04-13 22:38:15,736 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe2ab80000, quorum=localhost:64068, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2014-04-13 22:38:15,736 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed
> 2014-04-13 22:38:15,736 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [8,000] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:15,768 INFO [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(363): worker tpt_svr,1,1 acquired task /hbase/splitWAL/tpt_task
> 2014-04-13 22:38:15,784 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe2ab80000, quorum=localhost:64068, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/tpt_task
> 2014-04-13 22:38:15,785 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:15,786 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/tpt_task preempted from tpt_svr,1,1, current task state and owner=OWNED manager,1,1
> 2014-04-13 22:38:15,786 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:15,862 WARN [SplitLogWorker-tpt_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:724)
> 2014-04-13 22:38:16,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker(420): BADVERSION failed to assert ownership for /hbase/splitWAL/tpt_task
> org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/tpt_task
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:115)
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
> at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1266)
> 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.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-04-13 22:38:16,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/tpt_task
> 2014-04-13 22:38:16,870 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tpt_task
> 2014-04-13 22:38:16,870 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker tpt_svr,1,1 done with task /hbase/splitWAL/tpt_task in 1011ms
> 2014-04-13 22:38:16,875 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:16,876 INFO [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException
> 2014-04-13 22:38:16,876 INFO [SplitLogWorker-tpt_svr,1,1] regionserver.SplitLogWorker(216): SplitLogWorker tpt_svr,1,1 exiting
> 2014-04-13 22:38:16,879 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers
> 2014-04-13 22:38:16,914 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testPreemptTask Thread=9 (was 5)
> Potentially hanging thread: pool-1-thread-1-SendThread(localhost:64068)
> java.lang.Thread.sleep(Native Method)
> org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219)
> org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164)
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104)
> Potentially hanging thread: pool-1-thread-1-EventThread
> sun.misc.Unsafe.park(Native Method)
> java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
> java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
> org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:494)
> Potentially hanging thread: process reaper
> sun.misc.Unsafe.park(Native Method)
> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
> java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
> java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:359)
> java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:942)
> java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> java.lang.Thread.run(Thread.java:724)
> Potentially hanging thread: SessionTracker
> java.lang.Object.wait(Native Method)
> org.apache.zookeeper.server.SessionTrackerImpl.run(SessionTrackerImpl.java:146)
> - Thread LEAK? -, OpenFileDescriptor=103 (was 95) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=700 (was 708), ProcessCount=459 (was 459), AvailableMemoryMB=4391 (was 4258) - AvailableMemoryMB LEAK? -, ConnectionCount=0 (was 0)
> 2014-04-13 22:38:16,978 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe2ab80000, quorum=localhost:64068, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null
> 2014-04-13 22:38:16,979 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe2ab80000, quorum=localhost:64068, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring
> 2014-04-13 22:38:16,939 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testAcquireMultiTasks Thread=9, OpenFileDescriptor=103, MaxFileDescriptor=32768, SystemLoadAverage=700, ProcessCount=459, AvailableMemoryMB=4390, ConnectionCount=0
> 2014-04-13 22:38:16,949 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 62039
> 2014-04-13 22:38:16,953 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:62039
> 2014-04-13 22:38:17,013 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:62039, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
> 2014-04-13 22:38:17,015 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe3cf10000 connected
> 2014-04-13 22:38:17,025 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created
> 2014-04-13 22:38:17,032 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2014-04-13 22:38:17,040 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10
> 2014-04-13 22:38:17,041 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(341): testAcquireMultiTasks
> 2014-04-13 22:38:17,118 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [6,000] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:17,119 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(175): SplitLogWorker rs,1,1 starting
> 2014-04-13 22:38:17,131 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas2
> 2014-04-13 22:38:17,797 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas0
> 2014-04-13 22:38:18,139 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe3cf10000, quorum=localhost:62039, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/tatas2
> 2014-04-13 22:38:18,423 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas1
> 2014-04-13 22:38:18,428 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:18,429 WARN [SplitLogWorker-rs,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:724)
> 2014-04-13 22:38:18,430 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(216): SplitLogWorker rs,1,1 exiting
> 2014-04-13 22:38:18,430 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted tatas0
> 2014-04-13 22:38:18,430 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tatas2
> 2014-04-13 22:38:18,431 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-2] handler.HLogSplitterHandler(87): task execution prempted tatas1
> 2014-04-13 22:38:18,430 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas0 in 630ms
> 2014-04-13 22:38:18,431 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-2] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas1 in 7ms
> 2014-04-13 22:38:18,431 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas2 in 1297ms
> 2014-04-13 22:38:18,433 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers
> 2014-04-13 22:38:18,469 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testAcquireMultiTasks Thread=11 (was 9)
> Potentially hanging thread: pool-1-thread-1-SendThread(localhost:62039)
> java.lang.Thread.sleep(Native Method)
> org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219)
> org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164)
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104)
> - Thread LEAK? -, OpenFileDescriptor=107 (was 103) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=644 (was 700), ProcessCount=459 (was 459), AvailableMemoryMB=4223 (was 4390), ConnectionCount=0 (was 0)
> 2014-04-13 22:38:18,532 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe3cf10000, quorum=localhost:62039, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null
> 2014-04-13 22:38:18,532 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe3cf10000, quorum=localhost:62039, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring
> 2014-04-13 22:38:18,505 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testAcquireTaskAtStartup Thread=11, OpenFileDescriptor=107, MaxFileDescriptor=32768, SystemLoadAverage=644, ProcessCount=459, AvailableMemoryMB=4217, ConnectionCount=0
> 2014-04-13 22:38:18,512 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 49163
> 2014-04-13 22:38:18,517 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:49163
> 2014-04-13 22:38:18,608 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:49163, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
> 2014-04-13 22:38:18,610 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe430c0000 connected
> 2014-04-13 22:38:18,628 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created
> 2014-04-13 22:38:18,635 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2014-04-13 22:38:18,645 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10
> 2014-04-13 22:38:18,645 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(145): testAcquireTaskAtStartup
> 2014-04-13 22:38:18,652 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(175): SplitLogWorker rs,1,1 starting
> 2014-04-13 22:38:18,652 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:18,659 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas
> 2014-04-13 22:38:18,663 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:18,664 WARN [SplitLogWorker-rs,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:724)
> 2014-04-13 22:38:18,664 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(216): SplitLogWorker rs,1,1 exiting
> 2014-04-13 22:38:18,672 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tatas
> 2014-04-13 22:38:18,672 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas in 10ms
> 2014-04-13 22:38:18,674 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers
> 2014-04-13 22:38:18,709 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testAcquireTaskAtStartup Thread=14 (was 11)
> Potentially hanging thread: pool-1-thread-1-SendThread(localhost:49163)
> java.lang.Thread.sleep(Native Method)
> org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219)
> org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164)
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104)
> - Thread LEAK? -, OpenFileDescriptor=111 (was 107) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=644 (was 644), ProcessCount=459 (was 459), AvailableMemoryMB=4184 (was 4217), ConnectionCount=0 (was 0)
> 2014-04-13 22:38:18,773 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe430c0000, quorum=localhost:49163, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null
> 2014-04-13 22:38:18,773 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe430c0000, quorum=localhost:49163, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring
> 2014-04-13 22:38:18,746 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testAcquireMultiTasksByAvgTasksPerRS Thread=14, OpenFileDescriptor=111, MaxFileDescriptor=32768, SystemLoadAverage=644, ProcessCount=459, AvailableMemoryMB=4334, ConnectionCount=0
> 2014-04-13 22:38:18,752 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 61696
> 2014-04-13 22:38:18,756 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:61696
> 2014-04-13 22:38:18,859 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:61696, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
> 2014-04-13 22:38:18,861 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe43fc0000 connected
> 2014-04-13 22:38:18,874 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created
> 2014-04-13 22:38:18,882 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2014-04-13 22:38:18,891 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10
> 2014-04-13 22:38:18,891 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(377): testAcquireMultiTasks
> 2014-04-13 22:38:19,065 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [6,000] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:19,066 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(175): SplitLogWorker rs,1,1 starting
> 2014-04-13 22:38:19,081 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas0
> 2014-04-13 22:38:19,731 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(363): worker rs,1,1 acquired task /hbase/splitWAL/tatas1
> 2014-04-13 22:38:19,744 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:19,744 WARN [SplitLogWorker-rs,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:724)
> 2014-04-13 22:38:19,744 INFO [SplitLogWorker-rs,1,1] regionserver.SplitLogWorker(216): SplitLogWorker rs,1,1 exiting
> 2014-04-13 22:38:19,745 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted tatas1
> 2014-04-13 22:38:19,745 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tatas0
> 2014-04-13 22:38:19,745 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas1 in 13ms
> 2014-04-13 22:38:19,745 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker rs,1,1 done with task /hbase/splitWAL/tatas0 in 661ms
> 2014-04-13 22:38:19,747 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers
> 2014-04-13 22:38:19,780 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testAcquireMultiTasksByAvgTasksPerRS Thread=17 (was 14)
> Potentially hanging thread: pool-1-thread-1-SendThread(localhost:61696)
> java.lang.Thread.sleep(Native Method)
> org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219)
> org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164)
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104)
> - Thread LEAK? -, OpenFileDescriptor=115 (was 111) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=644 (was 644), ProcessCount=459 (was 459), AvailableMemoryMB=4241 (was 4334), ConnectionCount=0 (was 0)
> 2014-04-13 22:38:19,846 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe43fc0000, quorum=localhost:61696, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null
> 2014-04-13 22:38:19,846 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe43fc0000, quorum=localhost:61696, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring
> 2014-04-13 22:38:19,812 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testRaceForTask Thread=17, OpenFileDescriptor=115, MaxFileDescriptor=32768, SystemLoadAverage=644, ProcessCount=459, AvailableMemoryMB=4237, ConnectionCount=0
> 2014-04-13 22:38:19,817 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 52736
> 2014-04-13 22:38:19,822 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:52736
> 2014-04-13 22:38:20,865 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:52736, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
> 2014-04-13 22:38:20,867 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe48260000 connected
> 2014-04-13 22:38:20,881 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created
> 2014-04-13 22:38:20,898 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2014-04-13 22:38:20,914 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10
> 2014-04-13 22:38:20,914 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(180): testRaceForTask
> 2014-04-13 22:38:20,924 INFO [SplitLogWorker-svr1,1,1] regionserver.SplitLogWorker(175): SplitLogWorker svr1,1,1 starting
> 2014-04-13 22:38:20,925 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:20,924 INFO [SplitLogWorker-svr2,1,1] regionserver.SplitLogWorker(175): SplitLogWorker svr2,1,1 starting
> 2014-04-13 22:38:21,055 INFO [SplitLogWorker-svr1,1,1] regionserver.SplitLogWorker(363): worker svr1,1,1 acquired task /hbase/splitWAL/trft
> 2014-04-13 22:38:21,058 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:22,071 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe48260000, quorum=localhost:52736, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/trft
> 2014-04-13 22:38:22,558 WARN [pool-1-thread-1] hbase.Waiter(195): Waiting timed out after [1,500] msec
> 2014-04-13 22:38:22,560 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:22,560 INFO [SplitLogWorker-svr1,1,1] regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException
> 2014-04-13 22:38:22,561 INFO [SplitLogWorker-svr1,1,1] regionserver.SplitLogWorker(216): SplitLogWorker svr1,1,1 exiting
> 2014-04-13 22:38:22,561 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:22,561 INFO [SplitLogWorker-svr2,1,1] regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException
> 2014-04-13 22:38:22,561 INFO [SplitLogWorker-svr2,1,1] regionserver.SplitLogWorker(216): SplitLogWorker svr2,1,1 exiting
> 2014-04-13 22:38:22,561 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted trft
> 2014-04-13 22:38:22,564 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker svr1,1,1 done with task /hbase/splitWAL/trft in 1507ms
> 2014-04-13 22:38:22,566 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers
> 2014-04-13 22:38:22,601 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testRaceForTask Thread=17 (was 17), OpenFileDescriptor=119 (was 115) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=644 (was 644), ProcessCount=459 (was 459), AvailableMemoryMB=3761 (was 4237), ConnectionCount=0 (was 0)
> 2014-04-13 22:38:22,665 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe48260000, quorum=localhost:52736, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null
> 2014-04-13 22:38:22,665 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe48260000, quorum=localhost:52736, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring
> 2014-04-13 22:38:22,634 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testMultipleTasks Thread=17, OpenFileDescriptor=119, MaxFileDescriptor=32768, SystemLoadAverage=664, ProcessCount=459, AvailableMemoryMB=3758, ConnectionCount=0
> 2014-04-13 22:38:22,648 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 65092
> 2014-04-13 22:38:22,651 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:65092
> 2014-04-13 22:38:22,724 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
> 2014-04-13 22:38:22,726 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe53350000 connected
> 2014-04-13 22:38:22,733 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created
> 2014-04-13 22:38:22,739 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2014-04-13 22:38:22,748 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10
> 2014-04-13 22:38:22,749 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(246): testMultipleTasks
> 2014-04-13 22:38:22,751 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(175): SplitLogWorker tmt_svr,1,1 starting
> 2014-04-13 22:38:22,851 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:22,866 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2014-04-13 22:38:22,867 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed
> 2014-04-13 22:38:22,867 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:22,883 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(363): worker tmt_svr,1,1 acquired task /hbase/splitWAL/tmt_task
> 2014-04-13 22:38:22,897 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2014-04-13 22:38:22,897 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed
> 2014-04-13 22:38:22,906 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/tmt_task
> 2014-04-13 22:38:22,906 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:22,907 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
> 2014-04-13 22:38:22,907 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:22,907 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:724)
> 2014-04-13 22:38:22,922 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(363): worker tmt_svr,1,1 acquired task /hbase/splitWAL/tmt_task_2
> 2014-04-13 22:38:23,897 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker(420): BADVERSION failed to assert ownership for /hbase/splitWAL/tmt_task
> org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/tmt_task
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:115)
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
> at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1266)
> 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.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-04-13 22:38:23,898 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/tmt_task
> 2014-04-13 22:38:23,898 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted tmt_task
> 2014-04-13 22:38:23,898 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker tmt_svr,1,1 done with task /hbase/splitWAL/tmt_task in 1014ms
> 2014-04-13 22:38:23,900 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:23,902 INFO [pool-1-thread-1] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:23,902 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(299): SplitLogWorker interrupted while waiting for task, exiting: java.lang.InterruptedException
> 2014-04-13 22:38:23,903 INFO [SplitLogWorker-tmt_svr,1,1] regionserver.SplitLogWorker(216): SplitLogWorker tmt_svr,1,1 exiting
> 2014-04-13 22:38:23,903 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted tmt_task_2
> 2014-04-13 22:38:23,903 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker tmt_svr,1,1 done with task /hbase/splitWAL/tmt_task_2 in 977ms
> 2014-04-13 22:38:23,905 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers
> 2014-04-13 22:38:23,952 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testMultipleTasks Thread=20 (was 17)
> Potentially hanging thread: pool-1-thread-1-SendThread(localhost:65092)
> java.lang.Thread.sleep(Native Method)
> org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(ClientCnxnSocketNIO.java:219)
> org.apache.zookeeper.ClientCnxn$SendThread.cleanup(ClientCnxn.java:1164)
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1104)
> - Thread LEAK? -, OpenFileDescriptor=123 (was 119) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=664 (was 664), ProcessCount=459 (was 459), AvailableMemoryMB=3604 (was 3758), ConnectionCount=0 (was 0)
> 2014-04-13 22:38:24,004 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null
> 2014-04-13 22:38:24,004 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe53350000, quorum=localhost:65092, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring
> 2014-04-13 22:38:24,010 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testRescan Thread=20, OpenFileDescriptor=125, MaxFileDescriptor=32768, SystemLoadAverage=664, ProcessCount=459, AvailableMemoryMB=3599, ConnectionCount=0
> 2014-04-13 22:38:24,031 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 55247
> 2014-04-13 22:38:24,041 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:55247
> 2014-04-13 22:38:24,100 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
> 2014-04-13 22:38:24,102 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe588d0000 connected
> 2014-04-13 22:38:24,114 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created
> 2014-04-13 22:38:24,135 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2014-04-13 22:38:24,147 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10
> 2014-04-13 22:38:24,148 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(289): testRescan
> 2014-04-13 22:38:24,150 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(175): SplitLogWorker svr,1,1 starting
> 2014-04-13 22:38:24,271 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2014-04-13 22:38:24,272 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed
> 2014-04-13 22:38:24,275 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:24,306 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(363): worker svr,1,1 acquired task /hbase/splitWAL/task
> 2014-04-13 22:38:24,325 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task
> 2014-04-13 22:38:24,325 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:24,327 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/task preempted from svr,1,1, current task state and owner=UNASSIGNED manager,1,1
> 2014-04-13 22:38:24,327 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:24,328 WARN [SplitLogWorker-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:724)
> 2014-04-13 22:38:25,321 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker(420): BADVERSION failed to assert ownership for /hbase/splitWAL/task
> org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/task
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:115)
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
> at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1266)
> 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.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-04-13 22:38:25,322 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/task
> 2014-04-13 22:38:25,322 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted task
> 2014-04-13 22:38:25,322 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1009ms
> 2014-04-13 22:38:25,338 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2014-04-13 22:38:25,338 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:25,338 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed
> 2014-04-13 22:38:25,355 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task
> 2014-04-13 22:38:25,357 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(363): worker svr,1,1 acquired task /hbase/splitWAL/task
> 2014-04-13 22:38:25,363 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task
> 2014-04-13 22:38:25,363 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:25,367 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/task preempted from svr,1,1, current task state and owner=UNASSIGNED manager,1,1
> 2014-04-13 22:38:25,367 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:25,368 WARN [SplitLogWorker-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:724)
> 2014-04-13 22:38:25,388 INFO [SplitLogWorker-svr,1,1] handler.HLogSplitterHandler(123): successfully transitioned task /hbase/splitWAL/RESCANsplit-log-worker-tests0000000001 to final state DONE svr,1,1
> 2014-04-13 22:38:26,867 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] regionserver.SplitLogWorker(426): Interrupted while trying to assert ownership of /hbase/splitWAL/task java.lang.InterruptedException
> at java.lang.Object.wait(Native Method)
> at java.lang.Object.wait(Object.java:503)
> at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1316)
> 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.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/task
> 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted task
> 2014-04-13 22:38:26,868 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1504ms
> 2014-04-13 22:38:26,968 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null
> 2014-04-13 22:38:26,969 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring
> 2014-04-13 22:38:27,112 ERROR [SyncThread:0] server.NIOServerCnxn(180): Unexpected Exception:
> java.nio.channels.CancelledKeyException
> at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
> at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77)
> 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)
> 2014-04-13 22:38:27,114 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers
> 2014-04-13 22:38:27,143 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testRescan Thread=22 (was 20)
> Potentially hanging thread: pool-1-thread-1-SendThread(localhost:55247)
> java.lang.Thread.sleep(Native Method)
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:991)
> Potentially hanging thread: SplitLogWorker-svr,1,1
> java.lang.Object.wait(Native Method)
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:265)
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209)
> java.lang.Thread.run(Thread.java:724)
> - Thread LEAK? -, OpenFileDescriptor=127 (was 125) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=664 (was 664), ProcessCount=459 (was 459), AvailableMemoryMB=3706 (was 3599) - AvailableMemoryMB LEAK? -, ConnectionCount=0 (was 0)
> Standard Error
> 2014-04-13 22:38:24,010 INFO [pool-1-thread-1] hbase.ResourceChecker(147): before: regionserver.TestSplitLogWorker#testRescan Thread=20, OpenFileDescriptor=125, MaxFileDescriptor=32768, SystemLoadAverage=664, ProcessCount=459, AvailableMemoryMB=3599, ConnectionCount=0
> 2014-04-13 22:38:24,031 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(200): Started MiniZK Cluster and connect 1 ZK server on client port: 55247
> 2014-04-13 22:38:24,041 INFO [pool-1-thread-1] zookeeper.RecoverableZooKeeper(120): Process identifier=split-log-worker-tests connecting to ZooKeeper ensemble=localhost:55247
> 2014-04-13 22:38:24,100 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=None, state=SyncConnected, path=null
> 2014-04-13 22:38:24,102 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(387): split-log-worker-tests-0x1455ebe588d0000 connected
> 2014-04-13 22:38:24,114 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(105): /hbase created
> 2014-04-13 22:38:24,135 DEBUG [pool-1-thread-1] regionserver.TestSplitLogWorker(108): /hbase/splitWAL created
> 2014-04-13 22:38:24,147 DEBUG [pool-1-thread-1] executor.ExecutorService(99): Starting executor service name=RS_LOG_REPLAY_OPS-TestSplitLogWorker, corePoolSize=10, maxPoolSize=10
> 2014-04-13 22:38:24,148 INFO [pool-1-thread-1] regionserver.TestSplitLogWorker(289): testRescan
> 2014-04-13 22:38:24,150 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(175): SplitLogWorker svr,1,1 starting
> 2014-04-13 22:38:24,271 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2014-04-13 22:38:24,272 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed
> 2014-04-13 22:38:24,275 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:24,306 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(363): worker svr,1,1 acquired task /hbase/splitWAL/task
> 2014-04-13 22:38:24,325 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task
> 2014-04-13 22:38:24,325 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:24,327 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/task preempted from svr,1,1, current task state and owner=UNASSIGNED manager,1,1
> 2014-04-13 22:38:24,327 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:24,328 WARN [SplitLogWorker-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:724)
> 2014-04-13 22:38:25,321 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker(420): BADVERSION failed to assert ownership for /hbase/splitWAL/task
> org.apache.zookeeper.KeeperException$BadVersionException: KeeperErrorCode = BadVersion for /hbase/splitWAL/task
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:115)
> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
> at org.apache.zookeeper.ZooKeeper.setData(ZooKeeper.java:1266)
> 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.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-04-13 22:38:25,322 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/task
> 2014-04-13 22:38:25,322 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(87): task execution prempted task
> 2014-04-13 22:38:25,322 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-0] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1009ms
> 2014-04-13 22:38:25,338 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeChildrenChanged, state=SyncConnected, path=/hbase/splitWAL
> 2014-04-13 22:38:25,338 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:25,338 DEBUG [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(595): tasks arrived or departed
> 2014-04-13 22:38:25,355 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task
> 2014-04-13 22:38:25,357 INFO [SplitLogWorker-svr,1,1] regionserver.SplitLogWorker(363): worker svr,1,1 acquired task /hbase/splitWAL/task
> 2014-04-13 22:38:25,363 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=NodeDataChanged, state=SyncConnected, path=/hbase/splitWAL/task
> 2014-04-13 22:38:25,363 INFO [pool-1-thread-1] hbase.Waiter(174): Waiting up to [1,500] milli-secs(wait.for.ratio=[1])
> 2014-04-13 22:38:25,367 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(522): task /hbase/splitWAL/task preempted from svr,1,1, current task state and owner=UNASSIGNED manager,1,1
> 2014-04-13 22:38:25,367 INFO [pool-1-thread-1-EventThread] regionserver.SplitLogWorker(608): Sending interrupt to stop the worker thread
> 2014-04-13 22:38:25,368 WARN [SplitLogWorker-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:724)
> 2014-04-13 22:38:25,388 INFO [SplitLogWorker-svr,1,1] handler.HLogSplitterHandler(123): successfully transitioned task /hbase/splitWAL/RESCANsplit-log-worker-tests0000000001 to final state DONE svr,1,1
> 2014-04-13 22:38:26,867 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] regionserver.SplitLogWorker(426): Interrupted while trying to assert ownership of /hbase/splitWAL/task java.lang.InterruptedException
> at java.lang.Object.wait(Native Method)
> at java.lang.Object.wait(Object.java:503)
> at org.apache.zookeeper.ClientCnxn.submitRequest(ClientCnxn.java:1316)
> 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.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:724)
> 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] regionserver.SplitLogWorker$2(477): Failed to heartbeat the task/hbase/splitWAL/task
> 2014-04-13 22:38:26,868 WARN [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(87): task execution prempted task
> 2014-04-13 22:38:26,868 INFO [RS_LOG_REPLAY_OPS-TestSplitLogWorker-1] handler.HLogSplitterHandler(107): worker svr,1,1 done with task /hbase/splitWAL/task in 1504ms
> 2014-04-13 22:38:26,968 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(310): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received ZooKeeper Event, type=None, state=Disconnected, path=null
> 2014-04-13 22:38:26,969 DEBUG [pool-1-thread-1-EventThread] zookeeper.ZooKeeperWatcher(392): split-log-worker-tests-0x1455ebe588d0000, quorum=localhost:55247, baseZNode=/hbase Received Disconnected from ZooKeeper, ignoring
> 2014-04-13 22:38:27,112 ERROR [SyncThread:0] server.NIOServerCnxn(180): Unexpected Exception:
> java.nio.channels.CancelledKeyException
> at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73)
> at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77)
> 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)
> 2014-04-13 22:38:27,114 INFO [pool-1-thread-1] zookeeper.MiniZooKeeperCluster(249): Shutdown MiniZK cluster with all ZK servers
> 2014-04-13 22:38:27,143 INFO [pool-1-thread-1] hbase.ResourceChecker(171): after: regionserver.TestSplitLogWorker#testRescan Thread=22 (was 20)
> Potentially hanging thread: pool-1-thread-1-SendThread(localhost:55247)
> java.lang.Thread.sleep(Native Method)
> org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:991)
> Potentially hanging thread: SplitLogWorker-svr,1,1
> java.lang.Object.wait(Native Method)
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.taskLoop(SplitLogWorker.java:265)
> org.apache.hadoop.hbase.regionserver.SplitLogWorker.run(SplitLogWorker.java:209)
> java.lang.Thread.run(Thread.java:724)
> - Thread LEAK? -, OpenFileDescriptor=127 (was 125) - OpenFileDescriptor LEAK? -, MaxFileDescriptor=32768 (was 32768), SystemLoadAverage=664 (was 664), ProcessCount=459 (was 459), AvailableMemoryMB=3706 (was 3599) - AvailableMemoryMB LEAK? -, ConnectionCount=0 (was 0)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)