[ 
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)

Reply via email to