You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hbase.apache.org by "stack (JIRA)" <ji...@apache.org> on 2014/04/15 01:27:15 UTC
[jira] [Created] (HBASE-10978) TestSplitLogWorker.testRescan times
out waiting on preempt count to go up
stack created HBASE-10978:
-----------------------------
Summary: 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.2#6252)