[
https://issues.apache.org/jira/browse/HBASE-19965?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16361886#comment-16361886
]
stack commented on HBASE-19965:
-------------------------------
-------------------------------------------------------------------------------
Test set: org.apache.hadoop.hbase.client.TestAsyncTableAdminApi
-------------------------------------------------------------------------------
Tests run: 34, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 572.494 s <<<
FAILURE! - in org.apache.hadoop.hbase.client.TestAsyncTableAdminApi
org.apache.hadoop.hbase.client.TestAsyncTableAdminApi Time elapsed: 19.573 s
<<< ERROR!
org.junit.runners.model.TestTimedOutException: test timed out after 600 seconds
at
org.apache.hadoop.hbase.client.TestAsyncTableAdminApi.testListTables(TestAsyncTableAdminApi.java:122)
org.apache.hadoop.hbase.client.TestAsyncTableAdminApi Time elapsed: 19.604 s
<<< ERROR!
java.lang.Exception: Appears to be stuck in thread DataXceiver for client
DFSClient_NONMAPREDUCE_-1429371430_23 at /127.0.0.1:60612 [Receiving block
BP-217569409-172.17.0.2-1518490564363:blk_1073741829_1005]
.. has the same pattern. Parameterized. No particular test taking a while:
{code}
2018-02-13 02:56:30,183 INFO [Time-limited test] hbase.ResourceChecker(148):
before:
client.TestAsyncTableAdminApi#testCreateTableWithEmptyRowInTheSplitKeys[0]
Thread=302, OpenFileDescriptor=1610, MaxFileDescriptor=1048576,
SystemLoadAverage=1755, ProcessCount=17, AvailableMemoryMB=10328
2018-02-13 02:56:30,294 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDeleteTable[0] Thread=304,
OpenFileDescriptor=1612, MaxFileDescriptor=1048576, SystemLoadAverage=1755,
ProcessCount=17, AvailableMemoryMB=10317
2018-02-13 02:56:41,992 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDisableAndEnableTables[0] Thread=322,
OpenFileDescriptor=1613, MaxFileDescriptor=1048576, SystemLoadAverage=1763,
ProcessCount=17, AvailableMemoryMB=9131
2018-02-13 02:57:21,465 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testCreateTable[0] Thread=349,
OpenFileDescriptor=1596, MaxFileDescriptor=1048576, SystemLoadAverage=1841,
ProcessCount=17, AvailableMemoryMB=9816
2018-02-13 02:57:35,108 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testModifyColumnFamily[0] Thread=345,
OpenFileDescriptor=1571, MaxFileDescriptor=1048576, SystemLoadAverage=1801,
ProcessCount=17, AvailableMemoryMB=10954
2018-02-13 02:57:50,562 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDisableCatalogTable[0] Thread=343,
OpenFileDescriptor=1585, MaxFileDescriptor=1048576, SystemLoadAverage=1867,
ProcessCount=17, AvailableMemoryMB=11009
2018-02-13 02:58:03,013 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testCreateTableWithRegions[0] Thread=341,
OpenFileDescriptor=1574, MaxFileDescriptor=1048576, SystemLoadAverage=1876,
ProcessCount=17, AvailableMemoryMB=9139
2018-02-13 02:58:41,708 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testIsTableEnabledAndDisabled[0]
Thread=454, OpenFileDescriptor=1569, MaxFileDescriptor=1048576,
SystemLoadAverage=1901, ProcessCount=20, AvailableMemoryMB=9379
2018-02-13 02:58:51,803 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testListTables[0] Thread=459,
OpenFileDescriptor=1578, MaxFileDescriptor=1048576, SystemLoadAverage=1886,
ProcessCount=17, AvailableMemoryMB=9836
2018-02-13 02:59:28,658 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testTruncateTablePreservingSplits[0]
Thread=370, OpenFileDescriptor=1570, MaxFileDescriptor=1048576,
SystemLoadAverage=1823, ProcessCount=17, AvailableMemoryMB=8980
2018-02-13 02:59:52,804 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testCompactionTimestamps[0] Thread=385,
OpenFileDescriptor=1575, MaxFileDescriptor=1048576, SystemLoadAverage=1805,
ProcessCount=17, AvailableMemoryMB=8672
2018-02-13 03:00:11,715 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testTableAvailableWithRandomSplitKeys[0]
Thread=385, OpenFileDescriptor=1593, MaxFileDescriptor=1048576,
SystemLoadAverage=1863, ProcessCount=17, AvailableMemoryMB=8835
2018-02-13 03:00:24,545 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testAddSameColumnFamilyTwice[0]
Thread=388, OpenFileDescriptor=1584, MaxFileDescriptor=1048576,
SystemLoadAverage=2003, ProcessCount=17, AvailableMemoryMB=7541
2018-02-13 03:00:35,379 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDeleteColumnFamily[0] Thread=385,
OpenFileDescriptor=1583, MaxFileDescriptor=1048576, SystemLoadAverage=1838,
ProcessCount=20, AvailableMemoryMB=9449
2018-02-13 03:00:47,174 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testCreateTableNumberOfRegions[0]
Thread=375, OpenFileDescriptor=1583, MaxFileDescriptor=1048576,
SystemLoadAverage=1869, ProcessCount=17, AvailableMemoryMB=8005
2018-02-13 03:01:35,396 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testModifyNonExistingColumnFamily[0]
Thread=474, OpenFileDescriptor=1610, MaxFileDescriptor=1048576,
SystemLoadAverage=1780, ProcessCount=17, AvailableMemoryMB=11665
2018-02-13 03:01:45,858 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDisableAndEnableTable[0] Thread=473,
OpenFileDescriptor=1609, MaxFileDescriptor=1048576, SystemLoadAverage=1686,
ProcessCount=17, AvailableMemoryMB=9984
2018-02-13 03:02:01,911 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testEnableTableRetainAssignment[0]
Thread=473, OpenFileDescriptor=1608, MaxFileDescriptor=1048576,
SystemLoadAverage=1744, ProcessCount=17, AvailableMemoryMB=9619
2018-02-13 03:02:24,360 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testAddColumnFamily[0] Thread=508,
OpenFileDescriptor=1608, MaxFileDescriptor=1048576, SystemLoadAverage=1723,
ProcessCount=17, AvailableMemoryMB=9967
2018-02-13 03:02:41,339 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDeleteSameColumnFamilyTwice[0]
Thread=466, OpenFileDescriptor=1605, MaxFileDescriptor=1048576,
SystemLoadAverage=1755, ProcessCount=20, AvailableMemoryMB=9127
2018-02-13 03:02:57,573 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testTruncateTable[0] Thread=462,
OpenFileDescriptor=1599, MaxFileDescriptor=1048576, SystemLoadAverage=1873,
ProcessCount=17, AvailableMemoryMB=9838
2018-02-13 03:03:18,690 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testGetTableDescriptor[0] Thread=392,
OpenFileDescriptor=1594, MaxFileDescriptor=1048576, SystemLoadAverage=1851,
ProcessCount=17, AvailableMemoryMB=8470
2018-02-13 03:03:30,418 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testTableExist[0] Thread=392,
OpenFileDescriptor=1590, MaxFileDescriptor=1048576, SystemLoadAverage=1829,
ProcessCount=17, AvailableMemoryMB=8128
2018-02-13 03:03:41,935 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testCreateTableWithOnlyEmptyStartRow[0]
Thread=407, OpenFileDescriptor=1595, MaxFileDescriptor=1048576,
SystemLoadAverage=1986, ProcessCount=17, AvailableMemoryMB=8175
2018-02-13 03:03:41,970 INFO [Time-limited test] hbase.ResourceChecker(148):
before:
client.TestAsyncTableAdminApi#testCreateTableWithEmptyRowInTheSplitKeys[1]
Thread=407, OpenFileDescriptor=1595, MaxFileDescriptor=1048576,
SystemLoadAverage=1986, ProcessCount=17, AvailableMemoryMB=8175
2018-02-13 03:03:42,008 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDeleteTable[1] Thread=407,
OpenFileDescriptor=1595, MaxFileDescriptor=1048576, SystemLoadAverage=1986,
ProcessCount=17, AvailableMemoryMB=8173
2018-02-13 03:03:55,676 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDisableAndEnableTables[1] Thread=406,
OpenFileDescriptor=1600, MaxFileDescriptor=1048576, SystemLoadAverage=1943,
ProcessCount=17, AvailableMemoryMB=9118
2018-02-13 03:04:27,855 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testCreateTable[1] Thread=404,
OpenFileDescriptor=1597, MaxFileDescriptor=1048576, SystemLoadAverage=1951,
ProcessCount=17, AvailableMemoryMB=9735
2018-02-13 03:04:36,314 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testModifyColumnFamily[1] Thread=404,
OpenFileDescriptor=1596, MaxFileDescriptor=1048576, SystemLoadAverage=1805,
ProcessCount=17, AvailableMemoryMB=8979
2018-02-13 03:04:48,274 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testDisableCatalogTable[1] Thread=402,
OpenFileDescriptor=1600, MaxFileDescriptor=1048576, SystemLoadAverage=1907,
ProcessCount=17, AvailableMemoryMB=9479
2018-02-13 03:04:57,542 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testCreateTableWithRegions[1] Thread=407,
OpenFileDescriptor=1598, MaxFileDescriptor=1048576, SystemLoadAverage=1973,
ProcessCount=21, AvailableMemoryMB=8213
2018-02-13 03:05:32,167 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testIsTableEnabledAndDisabled[1]
Thread=491, OpenFileDescriptor=1590, MaxFileDescriptor=1048576,
SystemLoadAverage=2722, ProcessCount=17, AvailableMemoryMB=10923
2018-02-13 03:05:43,040 INFO [Time-limited test] hbase.ResourceChecker(148):
before: client.TestAsyncTableAdminApi#testListTables[1] Thread=488,
OpenFileDescriptor=1590, MaxFileDescriptor=1048576, SystemLoadAverage=2605,
ProcessCount=17, AvailableMemoryMB=9014
{code}
Let me push an addendum that breaks up this one too.
> Fix flaky TestAsyncRegionAdminApi
> ---------------------------------
>
> Key: HBASE-19965
> URL: https://issues.apache.org/jira/browse/HBASE-19965
> Project: HBase
> Issue Type: Sub-task
> Reporter: Guanghao Zhang
> Assignee: stack
> Priority: Critical
> Fix For: 2.0.0-beta-2
>
> Attachments: HBASE-19965.branch-2.001.patch
>
>
> See
> [https://builds.apache.org/job/HBase%20Nightly/job/branch-2/284/testReport/junit/org.apache.hadoop.hbase.client/TestAsyncRegionAdminApi/testMergeRegions_0_/]
>
> java.lang.AssertionError: expected:<2> but was:<3> at
> org.apache.hadoop.hbase.client.TestAsyncRegionAdminApi.testMergeRegions(TestAsyncRegionAdminApi.java:359)
>
> Merge regions not work. The table still have 3 regions after the
> MergeRegionsProcedure finished.
> The master start balance region 9e2773ba1efba79a2defa276e9a26ed4. But because
> the MergeRegionsProcedure pid=138 start work first, so the balance need wait
> for the lock. But after merge regions finished, the MoveRegionProcedure
> pid=139 start work and assign 9e2773ba1efba79a2defa276e9a26ed4 to a new
> region server. This is not right. The MoveRegionProcedure should skip to
> assign a region which was marked as offline. Or we should clear the merged
> regions' procedure when MergeRegionsProcedure finished.
>
> Logs:
> 2018-02-08 16:24:44,608 INFO [master/cd4730e3eae2:0.Chore.1]
> master.HMaster(1454): balance
> hri=testMergeRegions,,1518107079782.9e2773ba1efba79a2defa276e9a26ed4.,
> source=cd4730e3eae2,39077,1518106776411,
> destination=cd4730e3eae2,40578,1518106776318
> 2018-02-08 16:24:44,608 DEBUG
> [RpcServer.default.FPBQ.Fifo.handler=4,queue=0,port=37885]
> procedure2.ProcedureExecutor(868): Stored pid=138,
> state=RUNNABLE:MERGE_TABLE_REGIONS_PREPARE; MergeTableRegionsProcedure
> table=testMergeRegions, regions=[9e2773ba1efba79a2defa276e9a26ed4,
> 8f8fd5cd032313e1aadb83e31e1b7479], forcibly=false
> ......
> 2018-02-08 16:24:50,111 INFO [PEWorker-13]
> procedure2.ProcedureExecutor(1249): Finished pid=138, state=SUCCESS;
> MergeTableRegionsProcedure table=testMergeRegions,
> regions=[9e2773ba1efba79a2defa276e9a26ed4, 8f8fd5cd032313e1aadb83e31e1b7479],
> forcibly=false in 5.5710sec
> 2018-02-08 16:24:50,113 INFO [PEWorker-13]
> procedure.MasterProcedureScheduler(813): pid=139,
> state=RUNNABLE:MOVE_REGION_UNASSIGN; MoveRegionProcedure
> hri=testMergeRegions,,1518107079782.9e2773ba1efba79a2defa276e9a26ed4.,
> source=cd4730e3eae2,39077,1518106776411,
> destination=cd4730e3eae2,40578,1518106776318 testMergeRegions
> testMergeRegions,,1518107079782.9e2773ba1efba79a2defa276e9a26ed4.
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
