tephra-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Andreas Neumann (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (TEPHRA-253) TransactionProcessorTest is sometimes flaky
Date Sat, 09 Sep 2017 19:46:02 GMT

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

Andreas Neumann commented on TEPHRA-253:
----------------------------------------

Suspicion confirmed. After changing travis to dump the standard output of the test case, I
see:
{noformat}
2017-09-09 19:18:16,851 - INFO  [main:o.a.h.h.r.RegionCoprocessorHost@196] - Load coprocessor
org.apache.tephra.hbase.coprocessor.TransactionProcessor from HTD of TestRegionScanner successfully.
2017-09-09 19:18:16,868 - INFO  [StoreOpener-fc704aec719b675f06e5d7bd12da85f0-1:o.a.h.h.r.c.CompactionConfiguration@85]
- size [134217728, 9223372036854775807); files [3, 10); ratio 1.200000; off-peak ratio 5.000000;
throttle point 2684354560; delete expired; major period 604800000, major jitter 0.500000
2017-09-09 19:18:16,883 - INFO  [main:o.a.h.h.r.HRegion@644] - Onlined fc704aec719b675f06e5d7bd12da85f0;
next sequenceid=1
2017-09-09 19:18:16,883 - INFO  [main:o.a.t.h.c.TransactionProcessorTest@178] - Coprocessor
is using transaction state: null
2017-09-09 19:18:16,926 - INFO  [main:o.a.t.h.c.TransactionProcessorTest@192] - Flushing region
TestRegionScanner,,1504984696824.fc704aec719b675f06e5d7bd12da85f0.
2017-09-09 19:18:16,960 - INFO  [HDFSTransactionStateStorage STARTING:o.a.t.p.HDFSTransactionStateStorage@109]
- Using snapshot dir /home/travis/build/apache/incubator-tephra/tephra-hbase-compat-0.96/target/junit6493752557205114158/junit8165179254738335598
2017-09-09 19:18:16,981 - INFO  [TransactionStateCache STARTING:o.a.t.p.HDFSTransactionStateStorage@185]
- Read encoded transaction snapshot of 84 bytes
2017-09-09 19:18:16,984 - INFO  [TransactionStateCache STARTING:o.a.t.c.TransactionStateCache@166]
- Transaction state reloaded with snapshot from 1504984695267
2017-09-09 19:18:17,393 - INFO  [main:o.a.h.h.r.DefaultStoreFlusher@88] - Flushed, sequenceid=37,
memsize=5.9 K, hasBloomFilter=true, into tmp file hdfs://localhost:53322/home/travis/build/apache/incubator-tephra/tephra-hbase-compat-0.96/target/junit6493752557205114158/junit7077794411994061305/hbase/data/default/TestRegionScanner/fc704aec719b675f06e5d7bd12da85f0/.tmp/6e813e3b7af94e13afc9dc1303dda3f8
2017-09-09 19:18:17,415 - INFO  [main:o.a.h.h.r.HStore@770] - Added hdfs://localhost:53322/home/travis/build/apache/incubator-tephra/tephra-hbase-compat-0.96/target/junit6493752557205114158/junit7077794411994061305/hbase/data/default/TestRegionScanner/fc704aec719b675f06e5d7bd12da85f0/f/6e813e3b7af94e13afc9dc1303dda3f8,
entries=36, sequenceid=37, filesize=2.2 K
2017-09-09 19:18:17,416 - INFO  [main:o.a.h.h.r.HRegion@1708] - Finished memstore flush of
~5.9 K/6048, currentsize=0/0 for region TestRegionScanner,,1504984696824.fc704aec719b675f06e5d7bd12da85f0.
in 489ms, sequenceid=37, compaction requested=false
{noformat}
Clearly, the flush begins before the transaction state is loaded. 

> TransactionProcessorTest is sometimes flaky
> -------------------------------------------
>
>                 Key: TEPHRA-253
>                 URL: https://issues.apache.org/jira/browse/TEPHRA-253
>             Project: Tephra
>          Issue Type: Bug
>    Affects Versions: 0.12.0-incubating
>            Reporter: Andreas Neumann
>            Assignee: Andreas Neumann
>             Fix For: 0.13.0-incubating
>
>
> The test sometimes fails as follows:
> {noformat}
> Running org.apache.tephra.hbase.coprocessor.TransactionProcessorTest
> Tests run: 6, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 7.741 sec <<<
FAILURE!
> testFamilyDeleteTimestamp(org.apache.tephra.hbase.coprocessor.TransactionProcessorTest)
 Time elapsed: 1.526 sec
> testTransactionStateCache(org.apache.tephra.hbase.coprocessor.TransactionProcessorTest)
 Time elapsed: 0.053 sec
> testDataJanitorRegionScanner(org.apache.tephra.hbase.coprocessor.TransactionProcessorTest)
 Time elapsed: 0.288 sec  <<< FAILURE!
> org.junit.internal.ArrayComparisonFailure: arrays first differed at element [3]; expected:<4>
but was:<1>
> 	at org.junit.internal.ComparisonCriteria.arrayEquals(ComparisonCriteria.java:50)
> 	at org.junit.Assert.internalArrayEquals(Assert.java:473)
> 	at org.junit.Assert.assertArrayEquals(Assert.java:294)
> 	at org.junit.Assert.assertArrayEquals(Assert.java:305)
> 	at org.apache.tephra.hbase.coprocessor.TransactionProcessorTest.assertKeyValueMatches(TransactionProcessorTest.java:593)
> 	at org.apache.tephra.hbase.coprocessor.TransactionProcessorTest.assertKeyValueMatches(TransactionProcessorTest.java:585)
> 	at org.apache.tephra.hbase.coprocessor.TransactionProcessorTest.testDataJanitorRegionScanner(TransactionProcessorTest.java:190)
> {noformat}
> It is not clear what is causing this, most likely the region server did not have an up-to-date
transaction state snapshot at the time of the lfush (that might be due to TEPHRA-239 orTEPHRA-249,
or it might be a condition where flush() has no effect because the region is already flushing,

> Let's observe this and gather more information when/if it happens again. 



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

Mime
View raw message