hbase-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "stack (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HBASE-19965) Fix flaky TestAsyncRegionAdminApi
Date Tue, 13 Feb 2018 06:35:00 GMT

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

Mime
View raw message