[ 
https://issues.apache.org/jira/browse/HBASE-19965?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16363464#comment-16363464
 ] 

stack commented on HBASE-19965:
-------------------------------

Here is for the test that timed out, build 314:

-------------------------------------------------------------------------------
Test set: org.apache.hadoop.hbase.client.TestAsyncTableAdminApi
-------------------------------------------------------------------------------
Tests run: 30, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 574.271 s <<< 
FAILURE! - in org.apache.hadoop.hbase.client.TestAsyncTableAdminApi
org.apache.hadoop.hbase.client.TestAsyncTableAdminApi  Time elapsed: 8.443 s  
<<< ERROR!
org.junit.runners.model.TestTimedOutException: test timed out after 600 seconds

org.apache.hadoop.hbase.client.TestAsyncTableAdminApi  Time elapsed: 8.473 s  
<<< ERROR!
java.lang.Exception: Appears to be stuck in thread DataXceiver for client 
DFSClient_NONMAPREDUCE_1381247601_23 at /127.0.0.1:40966 [Receiving block 
BP-1735548202-172.17.0.2-1518565636532:blk_1073741829_1005]

Parameterized there are about 29 tests. None takes a particularly long time:

{code}
 1 2018-02-13 23:47:40,557 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTableWithEmptyRowInTheSplitKeys[0] 
Thread=302, OpenFileDescriptor=1612, MaxFileDescriptor=1048576, 
SystemLoadAverage=2007, ProcessCount=17, AvailableMemoryM    B=21888
  2 2018-02-13 23:47:40,659 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testDeleteTable[0] Thread=305, 
OpenFileDescriptor=1614, MaxFileDescriptor=1048576, SystemLoadAverage=1982, 
ProcessCount=17, AvailableMemoryMB=21890
  3 2018-02-13 23:47:51,503 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testDisableAndEnableTables[0] Thread=320, 
OpenFileDescriptor=1616, MaxFileDescriptor=1048576, SystemLoadAverage=1827, 
ProcessCount=17, AvailableMemoryMB=21940
  4 2018-02-13 23:48:32,308 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTable[0] Thread=344, 
OpenFileDescriptor=1589, MaxFileDescriptor=1048576, SystemLoadAverage=1798, 
ProcessCount=17, AvailableMemoryMB=22132
  5 2018-02-13 23:48:41,898 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTableWithRegions[0] Thread=344, 
OpenFileDescriptor=1586, MaxFileDescriptor=1048576, SystemLoadAverage=1867, 
ProcessCount=17, AvailableMemoryMB=21816
  6 2018-02-13 23:49:23,348 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testIsTableEnabledAndDisabled[0] Thread=435, 
OpenFileDescriptor=1571, MaxFileDescriptor=1048576, SystemLoadAverage=1732, 
ProcessCount=17, AvailableMemoryMB=21124
  7 2018-02-13 23:49:36,012 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testListTables[0] Thread=441, 
OpenFileDescriptor=1577, MaxFileDescriptor=1048576, SystemLoadAverage=1809, 
ProcessCount=17, AvailableMemoryMB=20713
  8 2018-02-13 23:50:08,285 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testTruncateTablePreservingSplits[0] Thread=375, 
OpenFileDescriptor=1567, MaxFileDescriptor=1048576, SystemLoadAverage=1902, 
ProcessCount=17, AvailableMemoryMB=20604
  9 2018-02-13 23:50:26,969 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTableNumberOfRegions[0] Thread=373, 
OpenFileDescriptor=1590, MaxFileDescriptor=1048576, SystemLoadAverage=1889, 
ProcessCount=17, AvailableMemoryMB=20979
 10 2018-02-13 23:51:18,514 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testDisableAndEnableTable[0] Thread=439, 
OpenFileDescriptor=1569, MaxFileDescriptor=1048576, SystemLoadAverage=1876, 
ProcessCount=17, AvailableMemoryMB=20712
 11 2018-02-13 23:51:40,787 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testEnableTableRetainAssignment[0] Thread=430, 
OpenFileDescriptor=1575, MaxFileDescriptor=1048576, SystemLoadAverage=1754, 
ProcessCount=17, AvailableMemoryMB=20766
 12 2018-02-13 23:51:59,198 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testTruncateTable[0] Thread=473, 
OpenFileDescriptor=1578, MaxFileDescriptor=1048576, SystemLoadAverage=1826, 
ProcessCount=17, AvailableMemoryMB=21183
 13 2018-02-13 23:52:17,821 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testGetTableDescriptor[0] Thread=446, 
OpenFileDescriptor=1576, MaxFileDescriptor=1048576, SystemLoadAverage=1827, 
ProcessCount=17, AvailableMemoryMB=21732
 14 2018-02-13 23:52:27,280 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testTableExist[0] Thread=446, 
OpenFileDescriptor=1576, MaxFileDescriptor=1048576, SystemLoadAverage=1855, 
ProcessCount=17, AvailableMemoryMB=21342
 15 2018-02-13 23:52:38,715 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTableWithOnlyEmptyStartRow[0] 
Thread=459, OpenFileDescriptor=1581, MaxFileDescriptor=1048576, 
SystemLoadAverage=1814, ProcessCount=17, AvailableMemoryMB=205    98
 16 2018-02-13 23:52:38,764 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTableWithEmptyRowInTheSplitKeys[1] 
Thread=459, OpenFileDescriptor=1581, MaxFileDescriptor=1048576, 
SystemLoadAverage=1814, ProcessCount=17, AvailableMemoryM    B=20595
 17 2018-02-13 23:52:38,813 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testDeleteTable[1] Thread=459, 
OpenFileDescriptor=1581, MaxFileDescriptor=1048576, SystemLoadAverage=1814, 
ProcessCount=17, AvailableMemoryMB=20594
 18 2018-02-13 23:52:50,184 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testDisableAndEnableTables[1] Thread=396, 
OpenFileDescriptor=1580, MaxFileDescriptor=1048576, SystemLoadAverage=1760, 
ProcessCount=19, AvailableMemoryMB=20454
 19 2018-02-13 23:53:25,670 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTable[1] Thread=370, 
OpenFileDescriptor=1574, MaxFileDescriptor=1048576, SystemLoadAverage=1660, 
ProcessCount=17, AvailableMemoryMB=20662
 20 2018-02-13 23:53:37,265 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTableWithRegions[1] Thread=366, 
OpenFileDescriptor=1576, MaxFileDescriptor=1048576, SystemLoadAverage=1664, 
ProcessCount=17, AvailableMemoryMB=22533
 21 2018-02-13 23:54:10,781 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testIsTableEnabledAndDisabled[1] Thread=456, 
OpenFileDescriptor=1573, MaxFileDescriptor=1048576, SystemLoadAverage=1792, 
ProcessCount=17, AvailableMemoryMB=19696
 22 2018-02-13 23:54:22,740 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testListTables[1] Thread=455, 
OpenFileDescriptor=1577, MaxFileDescriptor=1048576, SystemLoadAverage=1648, 
ProcessCount=17, AvailableMemoryMB=19641
 23 2018-02-13 23:54:56,100 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testTruncateTablePreservingSplits[1] Thread=387, 
OpenFileDescriptor=1567, MaxFileDescriptor=1048576, SystemLoadAverage=1639, 
ProcessCount=17, AvailableMemoryMB=20829
 24 2018-02-13 23:55:15,611 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testCreateTableNumberOfRegions[1] Thread=383, 
OpenFileDescriptor=1596, MaxFileDescriptor=1048576, SystemLoadAverage=1636, 
ProcessCount=20, AvailableMemoryMB=20761
 25 2018-02-13 23:55:54,008 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testDisableAndEnableTable[1] Thread=475, 
OpenFileDescriptor=1569, MaxFileDescriptor=1048576, SystemLoadAverage=1807, 
ProcessCount=18, AvailableMemoryMB=22096
 26 2018-02-13 23:56:12,884 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testEnableTableRetainAssignment[1] Thread=454, 
OpenFileDescriptor=1573, MaxFileDescriptor=1048576, SystemLoadAverage=1775, 
ProcessCount=17, AvailableMemoryMB=20974
 27 2018-02-13 23:56:35,923 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testTruncateTable[1] Thread=485, 
OpenFileDescriptor=1575, MaxFileDescriptor=1048576, SystemLoadAverage=1652, 
ProcessCount=17, AvailableMemoryMB=20504
 28 2018-02-13 23:56:52,508 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testGetTableDescriptor[1] Thread=462, 
OpenFileDescriptor=1586, MaxFileDescriptor=1048576, SystemLoadAverage=1705, 
ProcessCount=17, AvailableMemoryMB=20830
 29 2018-02-13 23:57:06,321 INFO  [Time-limited test] 
hbase.ResourceChecker(148): before: 
client.TestAsyncTableAdminApi#testTableExist[1] Thread=456, 
OpenFileDescriptor=1569, MaxFileDescriptor=1048576, SystemLoadAverage=1984, 
ProcessCount=17, AvailableMemoryMB=20508
~
{code}

Could work on startup times. Would help. Let me split out a third class.

> 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